diff --git a/src/main/java/com/logtail/logback/LogtailAppender.java b/src/main/java/com/logtail/logback/LogtailAppender.java index 0e59543..09a844f 100644 --- a/src/main/java/com/logtail/logback/LogtailAppender.java +++ b/src/main/java/com/logtail/logback/LogtailAppender.java @@ -551,8 +551,10 @@ public boolean isDisabled() { @Override public void start() { - // The sender runs on a daemon thread, so a JVM exiting on its own would take the queued logs with it - shutdownHook = new Thread(this::stop, "logtail-appender-shutdown"); + // The sender runs on a daemon thread, so a JVM exiting on its own would take the queued logs with it. The hook + // only sends the queue and leaves the appender running: all shutdown hooks run at once, and frameworks such as + // Spring Boot and Quarkus keep logging while they shut down and stop logback themselves at the very end + shutdownHook = new Thread(this::flushQueue, "logtail-appender-shutdown"); Runtime.getRuntime().addShutdownHook(shutdownHook); super.start(); } @@ -565,7 +567,7 @@ public void stop() { try { Runtime.getRuntime().removeShutdownHook(shutdownHook); } catch (IllegalStateException e) { - // The JVM is already shutting down - stop() is running from the hook itself or from logback's + // The JVM is already shutting down - stop() is running from logback's or a framework's shutdown hook } scheduledExecutorService.shutdown(); @@ -578,4 +580,16 @@ public void stop() { flushLock.unlock(); } } + + /** + * Waits for a flush in progress on another thread, then sends everything still queued. + */ + protected void flushQueue() { + flushLock.lock(); + try { + flush(); + } finally { + flushLock.unlock(); + } + } } diff --git a/src/test/java/com/logtail/logback/LogtailAppenderJvmExitTest.java b/src/test/java/com/logtail/logback/LogtailAppenderJvmExitTest.java index ed68663..6606983 100644 --- a/src/test/java/com/logtail/logback/LogtailAppenderJvmExitTest.java +++ b/src/test/java/com/logtail/logback/LogtailAppenderJvmExitTest.java @@ -12,6 +12,7 @@ import java.io.File; import java.io.IOException; import java.net.InetSocketAddress; +import java.util.ArrayList; import java.util.Arrays; import java.util.Collections; import java.util.List; @@ -29,12 +30,27 @@ /** * Logs queued in the appender must reach Better Stack even when the application never stops logback and - * simply lets the JVM exit, and stop() must not return while a flush is still in progress on another thread. + * simply lets the JVM exit, logs written while a framework shuts down must still be sent when it stops logback, + * and stop() must not return while a flush is still in progress on another thread. */ public class LogtailAppenderJvmExitTest { @Test public void testQueuedLogsAreSentWhenTheJvmExitsWithoutStoppingLogback() throws Exception { + assertEquals(Collections.singletonList(Collections.singletonList("Logged right before the JVM exits")), + messagesSentByApp(ExitingApp.class)); + } + + @Test + public void testLogsWrittenWhileAFrameworkShutsDownAreSentWhenItStopsLogback() throws Exception { + assertEquals(Arrays.asList("Logged right before the JVM exits", "Logged while the framework shuts down"), + messagesSentByApp(FrameworkApp.class).stream().flatMap(List::stream).collect(Collectors.toList())); + } + + /** + * Runs the app in a JVM of its own against a local endpoint and returns the messages of each request it sent. + */ + private List> messagesSentByApp(Class appClass) throws Exception { List receivedBodies = new CopyOnWriteArrayList<>(); HttpServer server = HttpServer.create(new InetSocketAddress("127.0.0.1", 0), 0); server.createContext("/", exchange -> { @@ -47,7 +63,7 @@ public void testQueuedLogsAreSentWhenTheJvmExitsWithoutStoppingLogback() throws Process app = new ProcessBuilder( System.getProperty("java.home") + File.separator + "bin" + File.separator + "java", "-cp", System.getProperty("java.class.path"), - ExitingApp.class.getName(), + appClass.getName(), "http://127.0.0.1:" + server.getAddress().getPort()) .inheritIO() .start(); @@ -60,10 +76,12 @@ public void testQueuedLogsAreSentWhenTheJvmExitsWithoutStoppingLogback() throws server.stop(0); } - assertEquals(1, receivedBodies.size()); - List> lines = new ObjectMapper().readValue(receivedBodies.get(0), new TypeReference>>() {}); - assertEquals(Collections.singletonList("Logged right before the JVM exits"), - lines.stream().map(line -> line.get("message")).collect(Collectors.toList())); + List> messages = new ArrayList<>(); + for (String body : receivedBodies) { + List> lines = new ObjectMapper().readValue(body, new TypeReference>>() {}); + messages.add(lines.stream().map(line -> line.get("message")).collect(Collectors.toList())); + } + return messages; } /** @@ -85,6 +103,36 @@ public static void main(String[] args) { } } + /** + * Run in a JVM of its own: like Spring Boot or Quarkus, its shutdown hook keeps logging while it shuts down and + * stops logback at the very end. + */ + public static class FrameworkApp { + public static void main(String[] args) { + LoggerContext context = new LoggerContext(); + LogtailAppender appender = new LogtailAppender(); + appender.setContext(context); + appender.setAppName("FrameworkApp"); + appender.setSourceToken("source-token"); + appender.setIngestUrl(args[0]); + appender.start(); + + Logger logger = context.getLogger("FrameworkApp"); + logger.addAppender(appender); + Runtime.getRuntime().addShutdownHook(new Thread(() -> { + try { + // All shutdown hooks start together - by now the appender's own hook has done its part + Thread.sleep(300); + } catch (InterruptedException e) { + Thread.currentThread().interrupt(); + } + logger.info("Logged while the framework shuts down"); + context.stop(); + })); + logger.info("Logged right before the JVM exits"); + } + } + @Test public void testStopWaitsForTheFlushInProgressAndSendsWhatQueuedBehindIt() throws Exception { CountDownLatch requestStarted = new CountDownLatch(1);