Unwanted logging by StatusLogger

[morvael]

Description

I think after the changes in https://github.com/apache/logging-log4j2/commit/4e00ea4bb2849185323e0310bcac283aff120cab I can now observe logging from org.apache.logging.log4j.core.config.AbstractConfiguration ("Starting configuration...", "Start watching for changes to...", etc) which were previously hidden by default. I think that logger used to by WARN by default, now it's INFO by default.

Configuration

Version: 2.24.1

Operating system: Linux Mint 21.3

JDK: Adoptium 21.0.4+7

[morvael]

The following lines are logged at the start:

Starting configuration XmlConfiguration[location=… , lastModified=…]...
Start watching for changes to … every 0 seconds
Configuration XmlConfiguration[location=… , lastModified=…] started.
Stopping configuration org.apache.logging.log4j.core.config.DefaultConfiguration@…
Configuration org.apache.logging.log4j.core.config.DefaultConfiguration@… stopped.

And these at the end:

Stopping configuration XmlConfiguration[location=… , lastModified=…]...
Configuration XmlConfiguration[location=… , lastModified=…] stopped.

[ppkarwasz]

Hi @morvael,

The default status logger level in version 2.24.1 is still ERROR. Can you check:

1. If your configuration file does not use the deprecated status attribute.
2. If you don't define the deprecated Log4jDefaultStatusLevel, log4j2.defaultStatusLevel or LOG4J_DEFAULT_STATUS_LEVEL properties in a property source (Java System properties, environment variables, log4j2.component.properties file).
3. If you don't define the log4j2.statusLoggerLevel property as Java System property, environment variable or in a log4j2.StatusLogger.properties file.

[morvael]

I will re-verify but I actually tried to use any and all of them to change the log level to WARN and nothing changed, it still printed that INFO.

[morvael]

I have no guarantee though that some of the dependencies I use doesn't do one of those things :(

[vy]

@morvael, could you try putting a breakpoint to the StatusLogger.Config#Config() ctor and see where the incorrect level is sourced from, please?

[morvael]

Will try. For now this is the stack trace when I get first log line:

[morvael]

This is the config stack trace:

[morvael]

private static Map<String, Object> normalizeProperties(Properties... propertiesList) { returns empty map, so no relevant properties were detected I guess.

[morvael]

Ok, it seems I'm going through that code twice actually. And in the second one I'm doing code-based rebuild of configuration to configure some stuff in the code (this is for test programs) like in the old log4j. And I have the line there: builder.setStatusLevel(Level.INFO); ...so the funny thing is it must have not worked the same in old versions as it works now, because it didn't log those messages.

So I think we can close the issue, though I still don't know why now and not before.

[morvael]

Sorry for false report.

[morvael]

Perhaps in the old version StatusLogger wasn't rebuilt.

[ppkarwasz]

@morvael,

Ok, it seems I'm going through that code twice actually. And in the second one I'm doing code-based rebuild of configuration to configure some stuff in the code (this is for test programs) like in the old log4j. And I have the line there: builder.setStatusLevel(Level.INFO); ...so the funny thing is it must have not worked the same in old versions as it works now, because it didn't log those messages.

That is easy to explain: I increased the level of those lifecycle messages in #3043 to make them more useful. The start and stop events of a LoggerContext and Configuration are pretty rare, but are very important to debug problems such as continuous reconfiguration. This is part of a continuous effort to improve our own logging statements according to our log level semantic. The meaning of status logger levels should signify:

• ERROR: these are errors that users should immediately resolve.
• WARN: these are potential problems that the system detected (e.g. the presence of an unrecognized property in the configuration file) and users should be able to remove those warnings (currently it is not always possible, which is a blocker for #1592).
• INFO: these are noteworthy events (e.g. reconfiguration, file rollover) that the system does not consider problems, but might help diagnosing problems.

Sorry for false report.

No problem.

[ctubbsii]

@ppkarwasz wrote:

That is easy to explain: I increased the level of those lifecycle messages in #3043 to make them more useful. The start and stop events of a LoggerContext and Configuration are pretty rare, but are very important to debug problems such as continuous reconfiguration.

That change made the lifecycle events much more noisy, and undesirable for normal operations. I agree they can be useful for debugging. That seems to imply they should have stayed at the debug level. For me, the INFO level should be reserved for mandatory lifecycle information that the user should see under normal circumstances. The DEBUG level should be used for lifecycle information that the user should see while debugging. Now, in order to suppress these extra messages, users are likely to turn off status logging at the INFO level, preventing them from seeing more useful information. (See apache/accumulo#5457)

[ppkarwasz]

For me, the INFO level should be reserved for mandatory lifecycle information that the user should see under normal circumstances. The DEBUG level should be used for lifecycle information that the user should see while debugging.

I agree on the classification, although probably we differ in the definition on what constitutes mandatory lifecycle information. For me this information is important:

Configuration XmlConfiguration[location=… , lastModified=…] started.
Configuration org.apache.logging.log4j.core.config.DefaultConfiguration@… stopped.

This information is less important:

Starting configuration XmlConfiguration[location=… , lastModified=…]...
Start watching for changes to … every 0 seconds
Stopping configuration org.apache.logging.log4j.core.config.DefaultConfiguration@…

Do you suggest to switch the 3 statements above to DEBUG?

Now, in order to suppress these extra messages, users are likely to turn off status logging at the INFO level, preventing them from seeing more useful information. (See apache/accumulo#5457)

I honestly don't know what useful information you are referring to. IIRC the INFO level was mostly unused. Do you have any examples? Important information like log file rollovers are currently at DEBUG level.

[ctubbsii]

As purely a user of logging, and not a developer of it, I think I take for granted that logging will be started through the automatic configuration purely from the environment and classpath, and the fact that I'm sending logs through the framework.

The idea of having configuration "started" or "stopped" is meaningless to me. It makes sense to reveal internal details about how logging is set up and shut down, but this isn't a practical concern that I have as a user of log4j that I'd want to see at the INFO level. It's something I should be able to just take for granted.

Configuration XmlConfiguration[location=… , lastModified=…] started.
Configuration org.apache.logging.log4j.core.config.DefaultConfiguration@… stopped.

So, the above messages aren't helpful to me at all at the INFO level. I can see how they would be useful at DEBUG, though. Perhaps they might be useful if logging is set up in code, but using the automatic configuration like so many projects do... the best way to use it, in my opinion... these just don't tell me anything useful... not useful enough to be shown it every time when I'm not debugging, anyway.

This information is less important:

Starting configuration XmlConfiguration[location=… , lastModified=…]...
Start watching for changes to … every 0 seconds
Stopping configuration org.apache.logging.log4j.core.config.DefaultConfiguration@…

Of these messages, I probably only care about the middle one, because this something that is only present because I have specifically configured the monitor interval, and diverges from the default expected behavior. So, it's a very user-facing thing: I specifically configured that feature, so it's useful to see, because I don't see it when I haven't configured it. However, it is new, and wasn't there before, so DEBUG probably makes sense for that one as well.

Do you suggest to switch the 3 statements above to DEBUG?

Yes, I think that would be best. They were DEBUG before, in 2.24.0.

Now, in order to suppress these extra messages, users are likely to turn off status logging at the INFO level, preventing them from seeing more useful information. (See apache/accumulo#5457)

I honestly don't know what useful information you are referring to. IIRC the INFO level was mostly unused. Do you have any examples? Important information like log file rollovers are currently at DEBUG level.

When the reconfiguration occurred, there were messages about those changes which I found useful. I guess we got used to, and liked, the idea that we only saw something if we changed something, and that the status was completely silent otherwise. That was a good design, but it changed after 2.24.0, when it was working well in that version.

Essentially, I want a non-noisy way to observe changes. DEBUG is noisy, so I don't want to use that by default. But, WARN or ERROR doesn't show me changes. So, INFO seemed perfectly suited to the "non-noisy way to observe changes" desired outcome, but the recent changes making them more noisy kinda ruined that. I don't know if I have a good argument for keeping them at DEBUG, or if it's just a resistance to change, but I know that 2.24.3 is too noisy at INFO, and 2.24.0 was just right.

[ppkarwasz]

I don't know if I have a good argument for keeping them at DEBUG, or if it's just a resistance to change, but I know that 2.24.3 is too noisy at INFO, and 2.24.0 was just right.

Probably there is a little of both.

The idea of having configuration "started" or "stopped" is meaningless to me.

I see your point, probably two start/stop events might be omitted:

• When the DefaultConfiguration is replaced with a user configuration at the start of the application.
• When the user configuration is replaced with a NullConfiguration at shutdown.

I think that events, where a user configuration is replaced with another user configuration are interesting. For example Spring Boot applications use log4j2.xml initially and switch to log4j2-spring.xml shortly after.

Maybe we should only log the start and stop of a configuration, if the user (or some external library) provides the location of the configuration file on the command line, instead of relying on the defaults?

[ctubbsii]

I don't know if I have a good argument for keeping them at DEBUG, or if it's just a resistance to change, but I know that 2.24.3 is too noisy at INFO, and 2.24.0 was just right.

Probably there is a little of both.

I do like big lifecycle events at INFO, I think... as long as it's not too noisy. Really, I think I just want to know that

1. Which configuration actually got used after everything is loaded (I expect exactly 1 message at the start of any application)
2. Any changes (I expect 0 messages unless I explicitly make a change to my file and I have a monitorInterval configured)

The idea of having configuration "started" or "stopped" is meaningless to me.

I see your point, probably two start/stop events might be omitted:

• When the DefaultConfiguration is replaced with a user configuration at the start of the application.
• When the user configuration is replaced with a NullConfiguration at shutdown.

Or just move them to DEBUG or TRACE. They don't have to go away entirely. If they aren't something set from the environment/config, and just internal lifecycle stuff, then it's probably not something most users care about, but could still be useful for troubleshooting.

I think that events, where a user configuration is replaced with another user configuration are interesting. For example Spring Boot applications use log4j2.xml initially and switch to log4j2-spring.xml shortly after.

That's weird. If the application is changing logging at runtime inside the app, I think it deserves whatever extra logging that they triggered. If it's noisy, it's their own fault for being weird :smiley_cat:

Maybe we should only log the start and stop of a configuration, if the user (or some external library) provides the location of the configuration file on the command line, instead of relying on the defaults?

"starting" and "stopping" seem to me like internal lifecycle events. As a user, I want to see my effective configuration from the environment (even if I didn't configure it explicitly, but it was picked up from the CLASSPATH), and when the effective configuration changes.

For example, imagine an app starts at 10:00, the user adds an includeOptional directive to point to a file that already exists at 10:29:40, the change is observed at 10:30, then the user edits the second file at 10:31:05, and the change is noticed 25 seconds later. Then, the user makes two more edits to the main file at 11:28 and 12:45:30 before the app exits. The only things that would be logged at INFO from the status logger would be something like:

<START OF APP>
INFO 10:00:00 Using log4j configuration file found at /path/to/log4j2.properties (monitorInterval = 30s)
INFO 10:30:00 Log4j configuration reloaded from file change event for /path/to/log4j2.properties
INFO 10:31:30 Log4j configuration reloaded from file change event for /path/to/log4j2-includeOptional-file.properties
INFO 11:28:00 Log4j configuration reloaded from file change event for /path/to/log4j2.properties
INFO 12:45:30 Log4j configuration reloaded from file change event for /path/to/log4j2.properties
<APP EXITS>

If the user didn't edit the files at all, only the first line would have appeared, and nothing else.

[ppkarwasz]

I am reopening this issue, so we can find a consensus on what kind of messages should appear with level INFO.

[garydgregory]

This is a classic and recurring issue in logging. The POVs to consider are:

• The library developers (in this case, us, Log4j)
• The application developers using that library (I'll include libraries reusing Log4j here)
• The users of the applications

Each is a different audience with varying and at times different needs.

Since we are talking about the status logger and not logging in general, we are further constrained by the configuration of this type of logging being limited to choosing a level, and that's it, no markers, no logger hierarchies.

If I enable Log4j's status logging, I must be aware that this is different from any other kind of logging. This is logging about logging.

If status logging output is mixed in with normal library and application logging, then the output can be confusing. A log's audience must be aware of this difference.

For me, WARN and ERROR events should contain actionable information. If a file is locked, I probably need to close an app. Once I am here, all behavior may be broken or unpredictable.

INFO tells me events are proceeding normally and gives me confidence the system is alive and well.

I need DEBUG if I am trying to solve a problem or am curious to see why a task is time or resource consuming.

I need TRACE to see what is being read or written on the wire or to a file. TRACE can also be used to see low-level class/method API IO.

Coming back to Log4j status logging, I think we need to consider what is informative vs. what is only needed when trying to solve an issue. We might find that we can move more events from INFO to DEBUG using this POV.

[ppkarwasz]

@garydgregory,

It seems we're very much aligned on the purpose of log levels:

• ERROR and WARN should signal actionable issues. It's well known that not all WARN messages from the StatusLogger are truly actionable. While this is being addressed in #1592, I don’t currently have the bandwidth to review all WARN messages across the codebase. Any help on that front would be greatly appreciated.
• TRACE and DEBUG are meant to provide verbose output and are mainly useful for Log4j developers or users troubleshooting specific problems.
• INFO remains a perennial gray area. It should ideally communicate that the system is functioning correctly. But what qualifies as “reassuring” is subjective, and there will always be some disagreement here.

"Regarding status logging in Log4j, I think we need to distinguish between what is informative and what is only useful during troubleshooting. That might help us demote some INFO messages to DEBUG."

Here, I see things differently: we actually have very few events logged at the INFO level, and I believe we should consider promoting some important messages from DEBUG. For example:

• Rollover events currently don't emit anything above DEBUG, even though they’re important for understanding log rotation behavior.
• Network appenders should emit an INFO message when a connection is established. Unlike file-based appenders, network connectivity should never be assumed to “just work,” and an explicit log line can be very helpful.

[garydgregory]

Unlike file-based appenders, network connectivity should never be assumed to “just work,” and an explicit log line can be very helpful.

Hm, but what about files that are on network drives...

[garydgregory]

Rollover events currently don't emit anything above DEBUG, even though they’re important for understanding log rotation behavior.

This opens the door to when and whatyou log. Do you say:

INFO - Rotating file from A to B

or

INFO - Rotated file from A to B

or

INFO - Rotating file from A to B
INFO - Rotated file from A to B

or

DEBUG - Rotating file from A to B
INFO - Rotated file from A to B

?

[garydgregory]

None of this should hold up 2.25.0.

[ctubbsii]

• Rollover events currently don't emit anything above DEBUG, even though they’re important for understanding log rotation behavior.

By rollover, do you mean reconfiguration, or file-rollover for the File appender?

I came here because of the change in #3043, where the "Starting..." messages were changed from DEBUG to INFO in LoggerContext. I think these would still show up in a reconfiguration event, in addition to any also emitted by any appenders. I wouldn't want to see appenders log at INFO whenever they rollover to a new file because of a daily rollover or file size limit... that would be too noisy.

• Network appenders should emit an INFO message when a connection is established. Unlike file-based appenders, network connectivity should never be assumed to “just work,” and an explicit log line can be very helpful.

I'm not so sure. As a user, I wouldn't want to see those internals. I would want to see when the new config took effect from a particular network location, or a warning if there is a network timeout or other I/O error trying to reconcile a flaky connection. I would not want to see connection established messages, or downloaded file, or any of those intermediate steps to load the configuration at the designated network location.

DEBUG - Rotating file from A to B INFO - Rotated file from A to B

I think this is basically what I suggested. As a user who isn't currently troubleshooting anything, it's useful to know when the new config file took effect, but not the internals of what's happening before that point.

The key here is that what goes to INFO should be a minimum. When a configuration is loaded or changed, only one INFO event is necessary... not a bunch coming from appenders, the LoggerContext, the root logger initialization, etc. Just one for the overall initialization of the configuration source, and just one each time the configuration changes.

[garydgregory]

Here's another general logging pickle that somewhat applies to status logging. There are events that you may care about depending on how and when you view them.

The best example of this is Maven logging of "Downloading..." and "Downloaded..." messages which are "info" events. When I am at the command line, I ignore them and I don't really care, and I can always use '-ntp' to filter them out.

BUT, when I look at build log files (say in Bamboo or GitHub), I get really annoyed if the build was not configured with '-ntp' because now I see tons of logging that is 100% irrelevant.

So arguing about the log level in this case is a red herring I claim and even if the level is "right" you still need an escape hatch.

[ppkarwasz]

None of this should hold up 2.25.0.

No, it won't. There are two additional PRs (#3501 and #3681) that will probably make it into 2.25.0, but the remaining will be moved to 2.25.1 or 2.26.0.