fix(server): keep log handlers open through a SIGTERM shutdown

docs/operations/cli.md

@@ -54,6 +54,7 @@ Use `connect` to talk to a running server.
 | `0` | Success. |
 | `1` | `exec`: at least one statement failed (an output line starts with `error`). |
 | `2` | Error printed as `hstore: <message>`: unknown command, missing argument, invalid setting value, a directory that is already initialised, failed authentication, a database locked by another process, an incompatible `FORMAT`. I/O failures print `hstore: <message>: <cause>`, for example `hstore: cannot connect to /127.0.0.1:1: Connection refused`. `ping` also returns `2` when no server answers. |
+| `143` | `serve` stopped by SIGTERM (128 + 15). The JVM and the native binary both report it after the clean shutdown has finished. |
 
 ## Commands
 

docs/operations/logging.md

@@ -1,10 +1,15 @@
 # Logging
 
-HStore logs through `System.Logger`. The server binds it to `java.util.logging` and installs a
-PostgreSQL-style formatter
-([`Logging.java`](../../server/src/main/java/io/hstore/server/Logging.java)). Logs always go to **stderr**, so
-`docker logs` and `journalctl` capture them with no further configuration. Optionally they are also written to
-size-rotated files.
+HStore logs through `System.Logger`. The server module provides its own `System.LoggerFinder`
+([`Logging.java`](../../server/src/main/java/io/hstore/server/Logging.java)) that hands every record to a
+console handler and, optionally, a rotating file handler, both using a PostgreSQL-style formatter. Logs always
+go to **stderr**, so `docker logs` and `journalctl` capture them with no further configuration.
+
+The handlers are owned by the server, not attached to `java.util.logging` loggers. On the JVM, `LogManager`
+registers a shutdown hook that closes every handler attached to a JUL logger, and it runs at the same time as
+the server's own shutdown hook. Keeping the handlers outside JUL means the shutdown lines (`received shutdown
+request`, the final checkpoint, `shut down cleanly`) are always written. The server closes its handlers as the
+last step of shutdown, which also removes the `hstore-0.log.lck` lock file.
 
 ## Line format
 

server/pom.xml

@@ -94,6 +94,7 @@
                                 <buildArg>-H:+SharedArenaSupport</buildArg>
                                 <buildArg>--enable-url-protocols=http,https</buildArg>
                                 <buildArg>-march=compatibility</buildArg>
+                                <buildArg>--initialize-at-build-time=io.hstore.server.Logging$Finder,io.hstore.server.Logging$Sink</buildArg>
                             </buildArgs>
                         </configuration>
                     </plugin>

server/src/main/java/io/hstore/server/Logging.java

@@ -10,20 +10,23 @@
 import java.time.Instant;
 import java.time.ZoneId;
 import java.time.format.DateTimeFormatter;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.ResourceBundle;
 import java.util.logging.ConsoleHandler;
 import java.util.logging.FileHandler;
 import java.util.logging.Formatter;
 import java.util.logging.Handler;
 import java.util.logging.Level;
-import java.util.logging.LogManager;
 import java.util.logging.LogRecord;
-import java.util.logging.Logger;
 
 final class Logging {
 
     private static final DateTimeFormatter TIMESTAMP = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS zzz").withZone(ZoneId.systemDefault());
     private static final long PID = ProcessHandle.current().pid();
 
+    private static volatile Sinks sinks = new Sinks(Level.INFO, List.of(console(Level.INFO, new PostgresStyle())));
+
     private Logging() {
     }
 
@@ -32,26 +35,31 @@ static void configure(ServerConfig config) {
                 config.integer(Setting.LOG_ROTATION_MB), config.integer(Setting.LOG_FILE_COUNT));
     }
 
-    static void configure(Level level, String directory, int rotationMegabytes, int files) {
-        LogManager.getLogManager().reset();
-        Logger root = Logger.getLogger("");
-        root.setLevel(level);
+    static synchronized void configure(Level level, String directory, int rotationMegabytes, int files) {
         Formatter formatter = new PostgresStyle();
-        Handler console = new ConsoleHandler();
-        console.setFormatter(formatter);
-        console.setLevel(level);
-        root.addHandler(console);
+        List<Handler> handlers = new ArrayList<>();
+        handlers.add(console(level, formatter));
         if (!directory.isBlank()) {
             try {
                 Files.createDirectories(Path.of(directory));
                 FileHandler file = new FileHandler(Path.of(directory, "hstore-%g.log").toString(), rotationMegabytes << 20, files, true);
                 file.setFormatter(formatter);
                 file.setLevel(level);
-                root.addHandler(file);
+                handlers.add(file);
             } catch (IOException e) {
+                handlers.forEach(Handler::close);
                 throw new UncheckedIOException("cannot open log directory " + directory, e);
             }
         }
+        List<Handler> previous = sinks.handlers();
+        sinks = new Sinks(level, List.copyOf(handlers));
+        previous.forEach(Handler::close);
+    }
+
+    static synchronized void close() {
+        List<Handler> previous = sinks.handlers();
+        sinks = new Sinks(sinks.level(), List.of());
+        previous.forEach(Handler::close);
     }
 
     static Level level(String name) {
@@ -64,6 +72,74 @@ static Level level(String name) {
         };
     }
 
+    private static Handler console(Level level, Formatter formatter) {
+        Handler console = new ConsoleHandler();
+        console.setFormatter(formatter);
+        console.setLevel(level);
+        return console;
+    }
+
+    private static Level level(System.Logger.Level level) {
+        return switch (level) {
+            case ALL -> Level.ALL;
+            case TRACE -> Level.FINER;
+            case DEBUG -> Level.FINE;
+            case INFO -> Level.INFO;
+            case WARNING -> Level.WARNING;
+            case ERROR -> Level.SEVERE;
+            case OFF -> Level.OFF;
+        };
+    }
+
+    private record Sinks(Level level, List<Handler> handlers) {
+        boolean accepts(Level candidate) {
+            return candidate != Level.OFF && level != Level.OFF && candidate.intValue() >= level.intValue();
+        }
+    }
+
+    public static final class Finder extends System.LoggerFinder {
+        @Override
+        public System.Logger getLogger(String name, Module module) {
+            return new Sink(name);
+        }
+    }
+
+    private record Sink(String name) implements System.Logger {
+        @Override
+        public String getName() {
+            return name;
+        }
+
+        @Override
+        public boolean isLoggable(Level level) {
+            return sinks.accepts(level(level));
+        }
+
+        @Override
+        public void log(Level level, ResourceBundle bundle, String message, Throwable thrown) {
+            publish(level, bundle, message, thrown, null);
+        }
+
+        @Override
+        public void log(Level level, ResourceBundle bundle, String format, Object... parameters) {
+            publish(level, bundle, format, null, parameters);
+        }
+
+        private void publish(Level level, ResourceBundle bundle, String message, Throwable thrown, Object[] parameters) {
+            Sinks current = sinks;
+            var converted = level(level);
+            if (!current.accepts(converted)) {
+                return;
+            }
+            LogRecord record = new LogRecord(converted, message);
+            record.setLoggerName(name);
+            record.setResourceBundle(bundle);
+            record.setThrown(thrown);
+            record.setParameters(parameters);
+            current.handlers().forEach(handler -> handler.publish(record));
+        }
+    }
+
     private static final class PostgresStyle extends Formatter {
         @Override
         public String format(LogRecord record) {

server/src/main/java/io/hstore/server/Main.java

@@ -121,7 +121,13 @@ private Main() {
     public static void main(String[] args) {
         try {
             Arguments arguments = Arguments.parse(args);
-            System.exit(run(command(arguments), arguments));
+            int status;
+            try {
+                status = run(command(arguments), arguments);
+            } finally {
+                Logging.close();
+            }
+            System.exit(status);
         } catch (IllegalArgumentException | HStoreException failure) {
             IO.println("hstore: " + failure.getMessage());
             System.exit(2);
@@ -302,13 +308,23 @@ private static int serve(Path directory, Arguments arguments) {
                 Duration.ofMinutes(config.integer(Setting.STUDIO_SESSION_MINUTES)),
                 Optional.of(config.string(Setting.STUDIO_ASSETS)).filter(value -> !value.isBlank()).map(Path::of), tls))) : Optional.empty();
         studio.ifPresent(Studio::start);
-        Runtime.getRuntime().addShutdownHook(Thread.ofPlatform().unstarted(() -> {
+        Thread shutdown = Thread.ofPlatform().name("hstore-shutdown").unstarted(() -> {
             log.log(System.Logger.Level.INFO, "received shutdown request; closing connections and checkpointing");
-            studio.ifPresent(Studio::close);
-            server.close();
-            database.close();
-        }));
+            try {
+                studio.ifPresent(Studio::close);
+                server.close();
+                database.close();
+            } finally {
+                Logging.close();
+            }
+        });
+        Runtime.getRuntime().addShutdownHook(shutdown);
         server.serve();
+        try {
+            shutdown.join();
+        } catch (InterruptedException e) {
+            Thread.currentThread().interrupt();
+        }
         return 0;
     }
 

server/src/main/java/module-info.java

@@ -5,4 +5,6 @@
     requires io.hstore.db;
     requires java.logging;
     requires jdk.httpserver;
+
+    provides System.LoggerFinder with io.hstore.server.Logging.Finder;
 }

server/src/main/resources/META-INF/services/java.lang.System$LoggerFinder

@@ -0,0 +1 @@
+io.hstore.server.Logging$Finder

server/src/test/java/io/hstore/server/ServerTest.java

@@ -9,6 +9,8 @@
 import io.hstore.engine.EngineOptions;
 
 import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.condition.DisabledOnOs;
+import org.junit.jupiter.api.condition.OS;
 import org.junit.jupiter.api.io.TempDir;
 
 import java.io.BufferedReader;
@@ -27,6 +29,7 @@
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Executors;
 import java.util.concurrent.Future;
+import java.util.concurrent.TimeUnit;
 import java.util.stream.IntStream;
 import javax.net.ssl.SSLContext;
 
@@ -87,6 +90,33 @@ void concurrentClientsShareOneDatabase() throws Exception {
         }
     }
 
+    @Test
+    @DisabledOnOs(OS.WINDOWS)
+    void sigtermCheckpointsAndLogsTheCleanShutdown() throws Exception {
+        String modules = System.getProperty("jdk.module.path");
+        List<String> command = new ArrayList<>(List.of(ProcessHandle.current().info().command().orElseThrow()));
+        command.addAll(modules == null ? List.of("-cp", System.getProperty("java.class.path"), Main.class.getName())
+                : List.of("-p", modules, "-m", "io.hstore.server/" + Main.class.getName()));
+        command.addAll(List.of("serve", directory.resolve("data").toString(), "--port", "0", "--studio", "off"));
+        Path log = directory.resolve("serve.log");
+        Process server = new ProcessBuilder(command).redirectErrorStream(true).redirectOutput(log.toFile()).start();
+        try {
+            long deadline = System.nanoTime() + TimeUnit.SECONDS.toNanos(60);
+            while (!Files.readString(log).contains("listening on") && System.nanoTime() < deadline && server.isAlive()) {
+                Thread.sleep(50);
+            }
+            assertTrue(Files.readString(log).contains("listening on"), Files.readString(log));
+            server.destroy();
+            assertTrue(server.waitFor(60, TimeUnit.SECONDS));
+            String output = Files.readString(log);
+            assertTrue(output.contains("received shutdown request"), output);
+            assertTrue(output.contains("checkpoint complete"), output);
+            assertTrue(output.contains("shut down cleanly"), output);
+        } finally {
+            server.destroyForcibly();
+        }
+    }
+
     static Path fixture(String name) throws Exception {
         return Path.of(ServerTest.class.getResource("/tls/" + name).toURI());
     }