Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Register Logback OnErrorConsoleStatusListener when using custom Logback file #43931

Closed
wants to merge 1 commit into from

Conversation

nosan
Copy link
Contributor

@nosan nosan commented Jan 22, 2025

Prior to this commit, OnErrorConsoleStatusListener was not registered for a custom Logback configuration file.

This commit registers OnErrorConsoleStatusListener when the Logback configuration is loaded from a custom Logback file that does not include any StatusListener.

See gh-43822

It has also been tested with a native image.

A different approach is to register OnErrorConsoleStatusListener right after reportConfigurationErrorsIfNecessary.
main...nosan:spring-boot:43822-1

…ck file

Prior to this commit, OnErrorConsoleStatusListener was not registered
for a custom Logback configuration file.

This commit registers OnErrorConsoleStatusListener when the Logback
configuration is loaded from a custom Logback file that does
not include any StatusListener.

See spring-projectsgh-43822

Signed-off-by: Dmytro Nosan <dimanosan@gmail.com>
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Jan 22, 2025
@nosan
Copy link
Contributor Author

nosan commented Jan 24, 2025

Maybe Spring Boot should consistently register OnErrorConsoleStatusListener, regardless of whether the custom Logback configuration defines any StatusListener(s).

main...nosan:spring-boot:43822-2

@philwebb philwebb added type: enhancement A general enhancement and removed status: waiting-for-triage An issue we've not yet triaged labels Jan 28, 2025
@philwebb philwebb self-assigned this Jan 28, 2025
@philwebb philwebb added this to the 3.5.x milestone Jan 28, 2025
philwebb pushed a commit that referenced this pull request Jan 28, 2025
Update `LogbackLoggingSystem` so that the `OnErrorConsoleStatusListener`
is also registered when loading a custom Logback configuration file.

See gh-43931

Signed-off-by: Dmytro Nosan <dimanosan@gmail.com>
philwebb added a commit that referenced this pull request Jan 28, 2025
Introduce a `SystemStatusListener` class to simplify Logback
status listener registration for both debug and regular output.

See gh-43931
@philwebb philwebb closed this in 08e9c16 Jan 28, 2025
@philwebb philwebb modified the milestones: 3.5.x, 3.5.0-M2 Jan 28, 2025
@philwebb
Copy link
Member

Thanks very much @nosan, I've got with your 43822-2 branch.

After merging, I realized that the logback.debug support was pretty similar, so I consolidated things and created a single SystemStatusListener class. This also provided a nice home for the code that was previously in FilteringStatusListener.

Please let me know if you foresee any issues with commit 8536950.

@nosan
Copy link
Contributor Author

nosan commented Jan 28, 2025

Thank you, @philwebb.

I reviewed your changes regarding SystemStatusListener, and unfortunately, it introduces some issues.

If you try to run an application right now, you will see the following output:

13:01:49,451 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version 1.5.16
13:01:49,452 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - Here is a list of configurators discovered as a service, by rank: 
13:01:49,452 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 -   org.springframework.boot.logging.logback.RootLogLevelConfigurator
13:01:49,452 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - They will be invoked in order until ExecutionStatus.DO_NOT_INVOKE_NEXT_IF_ANY is returned.
13:01:49,452 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - Constructed configurator of type class org.springframework.boot.logging.logback.RootLogLevelConfigurator
13:01:49,455 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - org.springframework.boot.logging.logback.RootLogLevelConfigurator.configure() call lasted 0 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
13:01:49,455 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - Trying to configure with ch.qos.logback.classic.joran.SerializedModelConfigurator
13:01:49,456 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - Constructed configurator of type class ch.qos.logback.classic.joran.SerializedModelConfigurator
13:01:49,456 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.scmo]
13:01:49,456 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.scmo]
13:01:49,456 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - ch.qos.logback.classic.joran.SerializedModelConfigurator.configure() call lasted 0 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
13:01:49,456 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - Trying to configure with ch.qos.logback.classic.util.DefaultJoranConfigurator
13:01:49,456 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - Constructed configurator of type class ch.qos.logback.classic.util.DefaultJoranConfigurator
13:01:49,456 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
13:01:49,456 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.xml]
13:01:49,456 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - ch.qos.logback.classic.util.DefaultJoranConfigurator.configure() call lasted 0 milliseconds. ExecutionStatus=INVOKE_NEXT_IF_ANY
13:01:49,456 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - Trying to configure with ch.qos.logback.classic.BasicConfigurator
13:01:49,457 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - Constructed configurator of type class ch.qos.logback.classic.BasicConfigurator
13:01:49,457 |-INFO in ch.qos.logback.classic.BasicConfigurator@4ff8d125 - Setting up default configuration.
13:01:49,464 |-INFO in ch.qos.logback.core.ConsoleAppender[console] - BEWARE: Writing to the console can be very slow. Avoid logging to the 
13:01:49,464 |-INFO in ch.qos.logback.core.ConsoleAppender[console] - console in production environments, especially in high volume systems.
13:01:49,464 |-INFO in ch.qos.logback.core.ConsoleAppender[console] - See also https://logback.qos.ch/codes.html#slowConsole
13:01:49,464 |-INFO in ch.qos.logback.classic.util.ContextInitializer@c7ba306 - ch.qos.logback.classic.BasicConfigurator.configure() call lasted 7 milliseconds. ExecutionStatus=NEUTRAL
{"@timestamp":"2025-01-28T11:01:49.645418Z","log.level":"INFO","process.pid":44203,"process.thread.name":"main","service.name":"simple","service.environment":"test","log.logger":"com.test.SimpleApplication","message":"Starting SimpleApplication using Java 23.0.1 with PID 44203 (\/Users\/dmytronosan\/IdeaProjects\/gh-43861\/target\/classes started by dmytronosan in \/Users\/dmytronosan\/IdeaProjects\/gh-43861)","ecs.version":"8.11"}

This occurs because SystemStatusListener extends OnPrintStreamStatusListenerBase, which contains the following logic:

   public void start() {
        isStarted = true;
        if (retrospectiveThresold > 0) {
            retrospectivePrint();  //print all statuses
        }
    }

private void retrospectivePrint() {
        if (context == null)
            return;
        long now = System.currentTimeMillis();
        StatusManager sm = context.getStatusManager();
        List<Status> statusList = sm.getCopyOfStatusList();
        for (Status status : statusList) {
            long timestampOfStatusMesage = status.getTimestamp();
            if (isElapsedTimeLongerThanThreshold(now, timestampOfStatusMesage)) {
                print(status);
            }
        }
    }
    

Also, I noticed that SystemStatusListener could be registered twice for AoT if SpringBootJoranConfigurator.configureUsingAotGeneratedArtifacts returns false.

I fixed both issues in the following branch: main...nosan:spring-boot:43822-3

@philwebb philwebb reopened this Jan 28, 2025
philwebb pushed a commit that referenced this pull request Jan 28, 2025
Fix `SystemStatusListener` so that superfluous output is not
printed when starting an application. This change ensures that
the `SystemStatusListener` is not added twice, and that
retrospective logging only occurs when `debug` is true.

See gh-43931

Signed-off-by: Dmytro Nosan <dimanosan@gmail.com>
philwebb added a commit that referenced this pull request Jan 28, 2025
Change `SystemStatusListener` to a `OnConsoleStatusListener` to
ensure that it cannot be added twice from different threads.

Also add a local `retrospectivePrint()` that is used for non-debug
output that will print ERROR and WARN status, but not INFO.

See gh-43931
@philwebb philwebb closed this in 8e15317 Jan 28, 2025
@philwebb
Copy link
Member

Thanks @nosan. There's some pretty interesting stuff going on here. I didn't appreciate that BasicStatusManager only prevents duplicate insertion of OnConsoleStatusListener. I think our best bet might be to make SystemStatusManager a subclass of OnConsoleStatusListener so that the duplicate check happens inside the BasicStatusManager synchronized block.

I also went back a debugged the old version and discovered that the retrospectiveThresold didn't come into play because the FilteringStatusListener didn't pass down the setContext(...) call. I think it might be best if we still print retrospective status messages, but filter out INFO messages if we're not doing debug.

Hopefully c884529 takes care of those changes, but let me know if you find any more issues.

Thanks again for all your work on this!

@nosan
Copy link
Contributor Author

nosan commented Jan 28, 2025

Thank you, @philwebb

I tested your changes again, and everything works perfectly!

I’ve prepared a polished commit for your changes if you don't mind. main...nosan:spring-boot:43822-4

@nosan
Copy link
Contributor Author

nosan commented Jan 28, 2025

BTW, I think this issue #43822 should be closed as well.

philwebb pushed a commit that referenced this pull request Jan 28, 2025
See gh-43931

Signed-off-by: Dmytro Nosan <dimanosan@gmail.com>
philwebb added a commit that referenced this pull request Jan 28, 2025
* pr/43931:
  Polish SystemStatusListener

Closes gh-43931
@philwebb
Copy link
Member

Nice! I've merged that one as well.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: enhancement A general enhancement
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants