Events close to the exit time of the program don't get written

[psiniemi]

The appender does not try to flush remaining messages to CloudWatch on stop, so final messages typically don't get written. These messages are specially important in the case of failures that cause an exit or short-lived workloads.

[j256]

Huh. It's supposed to @psiniemi. In the stop() method it interrupts and then joins with the sender thread. That code is supposed to drain the queue. Certainly there are race conditions so that the appended may stop before other components that are still logging but in looking at the code I can't see a path where messages queued before the thread is interrupted are lost.

Can you explain the execution path to me more? Thanks.

[j256]

I'm going to close this since no response. Feel free to reopen.

[jsyrjala]

You'll need to have some code that will call the logback's stop() method.

See

• https://logback.qos.ch/manual/configuration.html#stopContext
• https://jira.qos.ch/browse/LOGBACK-1090

For example for standalone Java applications to have something like this in logback.xml:

    <shutdownHook class="ch.qos.logback.core.hook.DelayingShutdownHook"/>

Maybe this should be mentioned in README.md?

[jsyrjala]

Having said that, it seems that I am also losing last few messages, even though I am using the shutdownHooks etc described above.

I have a standalone Java app, that basically just logs stuff from multiple threads and then exits (returns from main()). The last few messages do not end up into CloudWatch. If I add a 1 minute delay just before exist, everything works. Logback is also logging the same events to stdout, and all the events show up there.

[borisbsu]

Created PR for this issue:
#44

By using shutdown hook we can properly handle writing remaining events into CloudWatch.

[nichines]

ShutdownHook did not work for me for a short running Spring Boot Application running in a Docker container using AWS FarGate. I created this class and defined it for Spring Boot using the system property.

-Dorg.springframework.boot.logging.LoggingSystem=my.package.DelayedShutdownLogbackLoggingSystem

I also reduced the to 2.5 seconds in my logback-spring.xml file.

<maxBatchTimeMillis>2500</maxBatchTimeMillis>

import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.core.util.Duration;
import org.slf4j.ILoggerFactory;
import org.slf4j.impl.StaticLoggerBinder;
import org.springframework.boot.logging.logback.LogbackLoggingSystem;
import org.springframework.util.StringUtils;

@SuppressWarnings("unused")
public class DelayedShutdownLogbackLoggingSystem extends LogbackLoggingSystem {
    public static final Duration DEFAULT_DELAY = Duration.buildBySeconds(5);

    /**
     * Amount of time to delay before the stopping the logger context
     */
    private Duration delay = DEFAULT_DELAY;

    public DelayedShutdownLogbackLoggingSystem(ClassLoader classLoader) {
        super(classLoader);

        final var loggingSystemShutdownDelayDelay = System.getProperty(SYSTEM_PROPERTY + ".shutdownDelay");

        if (StringUtils.hasLength(loggingSystemShutdownDelayDelay)) {
            delay = Duration.valueOf(loggingSystemShutdownDelayDelay);
        }
    }

    private LoggerContext getLoggerContext() {
        ILoggerFactory factory = StaticLoggerBinder.getSingleton().getLoggerFactory();
        return (LoggerContext) factory;
    }

    @Override
    public Runnable getShutdownHandler() {
        return () -> {
            try {
                Thread.sleep(delay.getMilliseconds());
            }
            catch (InterruptedException ignored) {
            }
            getLoggerContext().stop();
        };
    }
}