Skip to content

Conversation

@rjernst
Copy link
Member

@rjernst rjernst commented Jun 8, 2023

This commit adds the Log4j JUL bridge so that messages using JUL are more nicely converted to log4j messages. Currently these messages are captured via the stdout logging stream. This commit also adds a log4j filter to replace the logging stream filtering mechanism used to quiet some Lucene log messages that may be confusing to users.

closes #94613

This commit adds the Log4j JUL bridge so that messages using JUL are more nicely converted to log4j messages. Currently these messages are captured via the stdout logging stream. This commit also adds a log4j filter to replace the logging stream filtering mechanism used to quiet some Lucene log messages that may be confusing to users.
@rjernst
Copy link
Member Author

rjernst commented Jun 8, 2023

@pgomulka This is what I have so far for adding the bridge. I haven't yet finished the replacement for filtering. I'm interesting to hear your thoughts. Something I don't like about log4j filtering is that I seem to be unable to add a filter to a specific logger, so it then requires checking every message to see if it should be filtered. Is there a better way?

@ChrisHegarty I tried commenting out the jvm.options vector incubator line, but I am unable to reproduce the log message you mentioned in https://github.com/elastic/elasticsearch/pull/96453/files#r1213535128. Can you clarify what is necessary to trigger those log messages?

@rjernst rjernst added :Core/Infra/Logging Log management and logging utilities >refactoring labels Jun 8, 2023
@ChrisHegarty
Copy link
Contributor

Log4j JUL bridge so that messages using JUL are more nicely converted to log4j messages.

++

@ChrisHegarty I tried commenting out the jvm.options vector incubator line, but I am unable to reproduce the log message you mentioned in https://github.com/elastic/elasticsearch/pull/96453/files#r1213535128. Can you clarify what is necessary to trigger those log messages?

(Without any real investigation) I think we might be running into security manager issues from the jul bridge frames on the stack? This may be similar to what was discussed in #96715, which includes a recursive issue and stack overflow resulting from a bad interaction between loging and a security exception.

@pgomulka
Copy link
Contributor

@pgomulka This is what I have so far for adding the bridge. I haven't yet finished the replacement for filtering. I'm interesting to hear your thoughts. Something I don't like about log4j filtering is that I seem to be unable to add a filter to a specific logger, so it then requires checking every message to see if it should be filtered. Is there a better way?

Can we not simply add this to a log4j2.properties?
logger.MemorySegmentIndexInputProvider.name = org.apache.lucene.store.MemorySegmentIndexInputProvider
logger.MemorySegmentIndexInputProvider.level = OFF

@ChrisHegarty I tried commenting out the jvm.options vector incubator line, but I am unable to reproduce the log message you mentioned in https://github.com/elastic/elasticsearch/pull/96453/files#r1213535128. Can you clarify what is necessary to trigger those log messages?

as per my comment #96519 (comment). I suspect those messages could be reproduced before #96453 was merged.

Previously I could reproduced them as per commands in that #96519 (comment)

@rjernst
Copy link
Member Author

rjernst commented Jun 12, 2023

Can we not simply add this to a log4j2.properties?

I want to avoid putting there, since it would not be picked up by anyone with modifications or their own properties file (eg cloud). I think we should try to do things programmatically whenever possible.

@rjernst
Copy link
Member Author

rjernst commented Jun 12, 2023

logger.MemorySegmentIndexInputProvider.level = OFF

Also, we don't want to turn off these loggers altogether. Rather, we want to filter out these particular messages that can add confusion for users.

@pgomulka
Copy link
Contributor

pgomulka commented Jun 13, 2023

Can we not simply add this to a log4j2.properties?

I want to avoid putting there, since it would not be picked up by anyone with modifications or their own properties file (eg cloud). I think we should try to do things programmatically whenever possible.

logger.MemorySegmentIndexInputProvider.level = OFF

Also, we don't want to turn off these loggers altogether. Rather, we want to filter out these particular messages that can add confusion for users.

agree

I recon we add code along these lines in log configurate after we load configuration
rjernst#3

final LoggerContext ctx = (LoggerContext) LogManager.getContext(false); Configuration configuration = ctx.getConfiguration(); LuceneLogFilter luceneLogFilter = new LuceneLogFilter(); for (String loggerName : LuceneLogFilter.getLoggerNames()) { org.apache.logging.log4j.core.Logger logger = ctx.getLogger(loggerName); configuration.addLoggerFilter(logger, luceneLogFilter); } ctx.updateLoggers(); 

Perhaps similar programatic configuration we could apply for deprecation's rateLimitingFilter. Far too often I see problems where a config was not updated and that filter was not applied (it is configured in log4j2.properties).

@rjernst rjernst marked this pull request as ready for review June 13, 2023 13:48
@elasticsearchmachine elasticsearchmachine added the Team:Core/Infra Meta label for core/infra team label Jun 13, 2023
@elasticsearchmachine
Copy link
Collaborator

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

@rjernst
Copy link
Member Author

rjernst commented Jun 13, 2023

Thanks @pgomulka , I was able to build a configuration in code, and I added it to the compound configuration we already setup. I was also able to just use a regex filter instead of needing a custom filter. Also note that I did not add a filter for MMapDirectory because that warning message is no longer emitted by Lucene.

@rjernst
Copy link
Member Author

rjernst commented Jun 13, 2023

Also, I was able to reproduce the warning message when omitting the incubator module, so I am confident both these warning messages are being captured.

Copy link
Contributor

@pgomulka pgomulka left a comment

Choose a reason for hiding this comment

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

LGTM,
great use of RegexFilter

Copy link
Contributor

@ChrisHegarty ChrisHegarty left a comment

Choose a reason for hiding this comment

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

LGTM

@pgomulka
Copy link
Contributor

pgomulka commented Jun 13, 2023

I suspect that thanks to a fix in #96715 we are no longer prone to security manager exceptions?

@rjernst
Copy link
Member Author

rjernst commented Jun 13, 2023

I haven't seen any security manager exceptions. The ones being muted here are direct Lucene messages. #96715 allowed me to reproduce the vector warning message when omitting the incubator module.

@rjernst rjernst added the auto-merge-without-approval Automatically merge pull request when CI checks pass (NB doesn't wait for reviews!) label Jun 13, 2023
@elasticsearchmachine elasticsearchmachine merged commit 2bdf1bc into elastic:main Jun 13, 2023
@rjernst rjernst deleted the logging/jul branch June 13, 2023 23:31
pgomulka added a commit to pgomulka/elasticsearch that referenced this pull request Jun 14, 2023
pgomulka added a commit that referenced this pull request Jun 14, 2023
thecoop added a commit to thecoop/elasticsearch that referenced this pull request Jun 14, 2023
thecoop added a commit to thecoop/elasticsearch that referenced this pull request Jun 14, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

auto-merge-without-approval Automatically merge pull request when CI checks pass (NB doesn't wait for reviews!) :Core/Infra/Logging Log management and logging utilities >refactoring Team:Core/Infra Meta label for core/infra team v8.9.0

4 participants