Skip to content

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

Merged
venkat1701 merged 2 commits into
mainfrom
fix/jvm-sigterm-shutdown
Oct 14, 2026
Merged

venkat1701 merged 2 commits into
mainfrom
fix/jvm-sigterm-shutdown

Conversation

@venkat1701

Copy link
Copy Markdown
Collaborator

Closes #70

What was going on

The checkpoint was never cut short. Only the log lines were lost.

Logging.configure attached the console and file handlers to the root java.util.logging logger. On the JVM, LogManager registers its own shutdown hook (LogManager.Cleaner, thread name Logging-Cleaner) that calls reset(), which removes and closes every handler on every JUL logger. The JVM starts all shutdown hooks at once, so Cleaner ran next to the server's hook. A debug print at the start of our hook showed Logger.getLogger("").getHandlers().length == 0 in every run: the handlers were already gone before received shutdown request was logged, or right after it. database.close() still finished, so the final checkpoint was written, but its log lines had nowhere to go.

I didn't track down why the native binary was not affected. After this change neither mode depends on the order of JUL's shutdown hook. Exit code 143 is not part of the bug: it is 128 + SIGTERM, and the native binary returns it as well.

Change

  • Logging now provides a System.LoggerFinder (declared in module-info.java and in META-INF/services for the class path and the native image). Every System.Logger record goes straight to handlers that Logging owns. The handlers are not attached to any JUL logger, so LogManager.reset() from the Cleaner hook has nothing to close. Level filtering, the PostgreSQL-style formatter and the rotating FileHandler are unchanged.
  • The native image looks up the LoggerFinder at build time, so server/pom.xml adds --initialize-at-build-time for Logging$Finder and Logging$Sink. Neither has static state. The handlers live in Logging, which is still initialized at run time.
  • The serve shutdown hook (now named hstore-shutdown) closes Studio, the server and the database, then calls Logging.close(). That flushes and closes the handlers and removes hstore-0.log.lck.
  • main closes logging after a command returns. serve joins the shutdown hook before it returns, so the main thread can't close the handlers while the hook is still checkpointing.
  • docs/operations/logging.md explains who owns the handlers. docs/operations/cli.md lists exit code 143 for serve stopped by SIGTERM.

Testing

ServerTest.sigtermCheckpointsAndLogsTheCleanShutdown starts serve in a child JVM with the test's module path, waits for listening on, sends SIGTERM with Process.destroy() and checks the output for received shutdown request, checkpoint complete and shut down cleanly. With the server/src/main changes reverted it failed 3 out of 3 runs, and the output stopped after configuration: port=0.

Manual repro, 20 runs on each side. Each run starts serve on the JVM (java -p engine.jar:db.jar:server.jar -m io.hstore.server/io.hstore.server.Main serve DIR --port P --studio off), creates a node type and inserts two nodes over connect, sends kill -TERM, then restarts on the same directory and reads the recovery line:

main (0c847f7) this branch
received shutdown request logged 5 / 20 20 / 20
checkpoint complete logged 0 / 20 20 / 20
shut down cleanly logged 0 / 20 20 / 20
restart replays 0 commits 20 / 20 20 / 20
exit code 143 every run 143 every run

The last row is why the checkpoint was never at risk. Both before and after, the restart found nothing to replay.

With --log_directory, hstore-0.log ends with shut down cleanly and no .lck file is left after the process exits.

Native image: I rebuilt it from this branch with ./mvnw -q -Pnative -DskipTests package -pl server. Without the two --initialize-at-build-time entries the build stops in analysis, because the image heap ends up holding a Logging$Finder and a Logging$Sink (the latter through jdk.internal.event.EventHelper.securityLogger). With them it builds. The same 20-run script against the native binary gave 20/20 for every shutdown line, 20/20 restarts with nothing to replay, and exit code 143 every run. The log lines use the PostgreSQL format as before, and --log_directory leaves no .lck file.

./mvnw -q install passes.

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.
@venkat1701
venkat1701 merged commit 20742a4 into main Oct 14, 2026
@venkat1701
venkat1701 deleted the fix/jvm-sigterm-shutdown branch October 14, 2026 13:08
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

SIGTERM in JVM mode exits before the clean shutdown finishes

1 participant