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 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()); }