From 9dd7f050ef2ef0403efa19d86571e0810d668f14 Mon Sep 17 00:00:00 2001 From: venkat1701 Date: Wed, 14 Oct 2026 11:35:55 +0530 Subject: [PATCH 1/2] fix(server): keep log handlers open until the shutdown hook finishes On the JVM, LogManager registers a shutdown hook that resets every java.util.logging logger and closes its handlers. It runs at the same time as the serve hook, so the root logger had no handlers left while the server was closing connections and checkpointing. The checkpoint completed, but "checkpoint complete" and "shut down cleanly" were lost, and in most runs "received shutdown request" too. The server now provides a System.LoggerFinder that sends records to handlers held by Logging instead of the root JUL logger, so the LogManager hook has nothing to close. The serve hook closes them as its last step, and serve joins the hook before main closes logging. The native image looks up the logger finder while it builds, so Finder and Sink are initialized at build time. Neither has static state. --- server/pom.xml | 1 + .../main/java/io/hstore/server/Logging.java | 98 ++++++++++++++++--- .../src/main/java/io/hstore/server/Main.java | 28 ++++-- server/src/main/java/module-info.java | 2 + .../services/java.lang.System$LoggerFinder | 1 + .../java/io/hstore/server/ServerTest.java | 30 ++++++ 6 files changed, 143 insertions(+), 17 deletions(-) create mode 100644 server/src/main/resources/META-INF/services/java.lang.System$LoggerFinder diff --git a/server/pom.xml b/server/pom.xml index 6634617..4b0a58e 100644 --- a/server/pom.xml +++ b/server/pom.xml @@ -94,6 +94,7 @@ -H:+SharedArenaSupport --enable-url-protocols=http,https -march=compatibility + --initialize-at-build-time=io.hstore.server.Logging$Finder,io.hstore.server.Logging$Sink diff --git a/server/src/main/java/io/hstore/server/Logging.java b/server/src/main/java/io/hstore/server/Logging.java index ae9a18e..b5e3a10 100644 --- a/server/src/main/java/io/hstore/server/Logging.java +++ b/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 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 previous = sinks.handlers(); + sinks = new Sinks(level, List.copyOf(handlers)); + previous.forEach(Handler::close); + } + + static synchronized void close() { + List 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 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) { diff --git a/server/src/main/java/io/hstore/server/Main.java b/server/src/main/java/io/hstore/server/Main.java index 260016e..dab40cf 100644 --- a/server/src/main/java/io/hstore/server/Main.java +++ b/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; } diff --git a/server/src/main/java/module-info.java b/server/src/main/java/module-info.java index 59e62c9..3c7b29f 100644 --- a/server/src/main/java/module-info.java +++ b/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; } diff --git a/server/src/main/resources/META-INF/services/java.lang.System$LoggerFinder b/server/src/main/resources/META-INF/services/java.lang.System$LoggerFinder new file mode 100644 index 0000000..15ab5a2 --- /dev/null +++ b/server/src/main/resources/META-INF/services/java.lang.System$LoggerFinder @@ -0,0 +1 @@ +io.hstore.server.Logging$Finder diff --git a/server/src/test/java/io/hstore/server/ServerTest.java b/server/src/test/java/io/hstore/server/ServerTest.java index 630128f..a2df948 100644 --- a/server/src/test/java/io/hstore/server/ServerTest.java +++ b/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 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()); } From d3e880f961e41367d2fca7cf5213ebabdb4af84f Mon Sep 17 00:00:00 2001 From: venkat1701 Date: Wed, 14 Oct 2026 11:35:56 +0530 Subject: [PATCH 2/2] docs(operations): describe log handler ownership and exit code 143 --- docs/operations/cli.md | 1 + docs/operations/logging.md | 15 ++++++++++----- 2 files changed, 11 insertions(+), 5 deletions(-) diff --git a/docs/operations/cli.md b/docs/operations/cli.md index df43fce..f83d01f 100644 --- a/docs/operations/cli.md +++ b/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: `: 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: : `, 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 diff --git a/docs/operations/logging.md b/docs/operations/logging.md index cbeaf4f..4de882b 100644 --- a/docs/operations/logging.md +++ b/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