Skip to content

Conversation

@prdoyle
Copy link
Contributor

@prdoyle prdoyle commented Mar 10, 2025

The stack trace tends to attract attention even when entitlements are not the cause of a problem, so let's avoid the stack trace, but still include stack frame info from the frame of interest. We're in something of a unique position here, where we know the exact frame that matters (except in cases where the problem stems from landing on the wrong frame, I suppose).

Let's use child loggers so we can filter these independently.

prdoyle added 2 commits March 10, 2025 15:33
Some of these are expected, so an INFO seems more appropriate.

The stack trace tends to attract attention even when entitlements are not the
cause of a problem, so let's avoid the stack trace, but still include stack
frame info from the frame of interest.
@prdoyle prdoyle added >non-issue auto-backport Automatically create backport pull requests when merged test-entitlements v8.18.1 v8.19.0 v9.0.1 v9.1.0 :Core/Infra/Entitlements Entitlements infrastructure labels Mar 10, 2025
@prdoyle prdoyle self-assigned this Mar 10, 2025
@prdoyle prdoyle requested a review from a team as a code owner March 10, 2025 19:48
@elasticsearchmachine
Copy link
Collaborator

Pinging @elastic/es-core-infra (Team:Core/Infra)

@elasticsearchmachine elasticsearchmachine added the Team:Core/Infra Meta label for core/infra team label Mar 10, 2025
@rjernst
Copy link
Member

rjernst commented Mar 10, 2025

Some of these are expected

Instead of making the unexpected ones look "ok" with info level, can we hide the expected ones? eg can we create a child logger based on the module name + entitlement (or some other identifier) that we can mute with normal logging filtering? Then GCS/AWS libs can ignore those known warnings without flooding the ES log, but expected entitlement failures can be properly warned.

@rjernst
Copy link
Member

rjernst commented Mar 10, 2025

The stack trace tends to attract attention even when entitlements are not the cause of a problem

If we filter out the "known" entitlements failures we want to ignore, is that still the case? We wanted to ensure the log contains everything we need to fix the issue, even if the exception is caught and swallowed.

@prdoyle
Copy link
Contributor Author

prdoyle commented Mar 10, 2025

Instead of making the unexpected ones look "ok" with info level, can we hide the expected ones?

That's not what's happening here. We can't know a priori which ones are expected, so we've decided to log them all at info and rely on another mechanism to report a more serious failure for unexpected ones.

Also, teaching the server which plugins have expected entitlement failures seems backward; the server doesn't know about the plugins. I could imagine adding a way to put this into the policy files though.

Sorry @rjernst my mistake, I totally misread what you said as "instead of making the expected ones look ok".

@rjernst
Copy link
Member

rjernst commented Mar 10, 2025

teaching the server which plugins have expected entitlement failures seems backward

That's not what I was suggesting. Rather, I think we should use a unique logger for each module, so that we can control changing the log level per plugin/module. See for example modules/repository-s3/src/main/config/log4j2.properties where we tweak the log levels for certain things from aws sdk for very similar reason (confusing/irrelevant messages). Right now we use a single logger for the policy manager. Instead, we could use a unique logger in notEntitled, eg something like:

LogManager.getLogger(PolicyManager.class + "." + moduleName).warn(...)

We could conceivably do something more complicated (eg include the entitlement type in the logger name as well), but module name is probably sufficient for now.

@prdoyle
Copy link
Contributor Author

prdoyle commented Mar 11, 2025

Ok I'm not sure I see the advantage of that approach. Emitting warnings when everything is operating as intended seems bad. Perhaps I'll understand better after our sync meeting today.

@prdoyle
Copy link
Contributor Author

prdoyle commented Mar 11, 2025

Thinking about it some more, I like the "child logger" idea irrespective of info vs warn. The only wrinkle is that our alert currently matches on the exact logger name, so I'll need to figure out how to generalize that, but it should be doable.

@prdoyle
Copy link
Contributor Author

prdoyle commented Mar 11, 2025

Note to self: if the module has no name, we could use the same ALL_UNNAMED tag we use elsewhere.

// Don't emit a log for muted classes, e.g. classes containing self tests
if (mutedClasses.contains(callerClass) == false) {
var moduleName = callerClass.getModule().getName();
var notEntitledLogger = LogManager.getLogger(PolicyManager.class + "." + ((moduleName == null) ? "ALL_UNNAMED" : moduleName));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: we use ALL-UNNAMED (with a dash) in the policy files

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why the module name and not the component name? (plugin name, "server" or "apm-agent"?)
Wouldn't we have clash for ALL-UNNAMED from different plugins if we need to adjust log level for one non-modular plugin?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The component name is also reasonable, but the finer grained we can make this the less changing this logging could affect other log messages.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

whoops

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Having both as agreed is the best 👍 Thanks!

@prdoyle prdoyle changed the title Use INFO logs for NotEntitledException Reduce noise from NotEntitledException logging Mar 11, 2025
prdoyle and others added 2 commits March 11, 2025 13:41
We're alerting on this, so let's not rely on every caller of notEntitled to remember it.
Copy link
Member

@rjernst rjernst left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@prdoyle prdoyle merged commit 5112dbb into elastic:main Mar 11, 2025
22 checks passed
@prdoyle prdoyle deleted the chill-bro branch March 11, 2025 19:50
@elasticsearchmachine
Copy link
Collaborator

💚 Backport successful

Status Branch Result
8.18
8.x
9.0

prdoyle added a commit to prdoyle/elasticsearch that referenced this pull request Mar 11, 2025
* Refactor: findRequestingFrame

* INFO instead of WARN for NotEntitledException.

Some of these are expected, so an INFO seems more appropriate.

The stack trace tends to attract attention even when entitlements are not the
cause of a problem, so let's avoid the stack trace, but still include stack
frame info from the frame of interest.

* Use child loggers for Not Entitled logs

* Use warn, and include compoenent name

* Fix ALL_UNNAMED

* Mute entitlement warnings from repositories

* PR feedback

* Common out the Not Entitled prefix.

We're alerting on this, so let's not rely on every caller of notEntitled to remember it.
prdoyle added a commit to prdoyle/elasticsearch that referenced this pull request Mar 11, 2025
* Refactor: findRequestingFrame

* INFO instead of WARN for NotEntitledException.

Some of these are expected, so an INFO seems more appropriate.

The stack trace tends to attract attention even when entitlements are not the
cause of a problem, so let's avoid the stack trace, but still include stack
frame info from the frame of interest.

* Use child loggers for Not Entitled logs

* Use warn, and include compoenent name

* Fix ALL_UNNAMED

* Mute entitlement warnings from repositories

* PR feedback

* Common out the Not Entitled prefix.

We're alerting on this, so let's not rely on every caller of notEntitled to remember it.
elasticsearchmachine pushed a commit that referenced this pull request Mar 11, 2025
* Refactor: findRequestingFrame

* INFO instead of WARN for NotEntitledException.

Some of these are expected, so an INFO seems more appropriate.

The stack trace tends to attract attention even when entitlements are not the
cause of a problem, so let's avoid the stack trace, but still include stack
frame info from the frame of interest.

* Use child loggers for Not Entitled logs

* Use warn, and include compoenent name

* Fix ALL_UNNAMED

* Mute entitlement warnings from repositories

* PR feedback

* Common out the Not Entitled prefix.

We're alerting on this, so let's not rely on every caller of notEntitled to remember it.
elasticsearchmachine pushed a commit that referenced this pull request Mar 11, 2025
* Refactor: findRequestingFrame

* INFO instead of WARN for NotEntitledException.

Some of these are expected, so an INFO seems more appropriate.

The stack trace tends to attract attention even when entitlements are not the
cause of a problem, so let's avoid the stack trace, but still include stack
frame info from the frame of interest.

* Use child loggers for Not Entitled logs

* Use warn, and include compoenent name

* Fix ALL_UNNAMED

* Mute entitlement warnings from repositories

* PR feedback

* Common out the Not Entitled prefix.

We're alerting on this, so let's not rely on every caller of notEntitled to remember it.
elasticsearchmachine pushed a commit that referenced this pull request Mar 11, 2025
* Refactor: findRequestingFrame

* INFO instead of WARN for NotEntitledException.

Some of these are expected, so an INFO seems more appropriate.

The stack trace tends to attract attention even when entitlements are not the
cause of a problem, so let's avoid the stack trace, but still include stack
frame info from the frame of interest.

* Use child loggers for Not Entitled logs

* Use warn, and include compoenent name

* Fix ALL_UNNAMED

* Mute entitlement warnings from repositories

* PR feedback

* Common out the Not Entitled prefix.

We're alerting on this, so let's not rely on every caller of notEntitled to remember it.
albertzaharovits pushed a commit to albertzaharovits/elasticsearch that referenced this pull request Mar 13, 2025
* Refactor: findRequestingFrame

* INFO instead of WARN for NotEntitledException.

Some of these are expected, so an INFO seems more appropriate.

The stack trace tends to attract attention even when entitlements are not the
cause of a problem, so let's avoid the stack trace, but still include stack
frame info from the frame of interest.

* Use child loggers for Not Entitled logs

* Use warn, and include compoenent name

* Fix ALL_UNNAMED

* Mute entitlement warnings from repositories

* PR feedback

* Common out the Not Entitled prefix.

We're alerting on this, so let's not rely on every caller of notEntitled to remember it.
jfreden pushed a commit to jfreden/elasticsearch that referenced this pull request Mar 13, 2025
* Refactor: findRequestingFrame

* INFO instead of WARN for NotEntitledException.

Some of these are expected, so an INFO seems more appropriate.

The stack trace tends to attract attention even when entitlements are not the
cause of a problem, so let's avoid the stack trace, but still include stack
frame info from the frame of interest.

* Use child loggers for Not Entitled logs

* Use warn, and include compoenent name

* Fix ALL_UNNAMED

* Mute entitlement warnings from repositories

* PR feedback

* Common out the Not Entitled prefix.

We're alerting on this, so let's not rely on every caller of notEntitled to remember it.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

auto-backport Automatically create backport pull requests when merged :Core/Infra/Entitlements Entitlements infrastructure >non-issue Team:Core/Infra Meta label for core/infra team v8.18.1 v8.19.0 v9.0.1 v9.1.0

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants