Repository navigation
fix(server): keep log handlers open through a SIGTERM shutdown - #93
Merged
Merged
Conversation
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.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #70
What was going on
The checkpoint was never cut short. Only the log lines were lost.
Logging.configureattached the console and file handlers to the rootjava.util.logginglogger. On the JVM,LogManagerregisters its own shutdown hook (LogManager.Cleaner, thread nameLogging-Cleaner) that callsreset(), which removes and closes every handler on every JUL logger. The JVM starts all shutdown hooks at once, soCleanerran next to the server's hook. A debug print at the start of our hook showedLogger.getLogger("").getHandlers().length == 0in every run: the handlers were already gone beforereceived shutdown requestwas 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
Loggingnow provides aSystem.LoggerFinder(declared inmodule-info.javaand inMETA-INF/servicesfor the class path and the native image). EverySystem.Loggerrecord goes straight to handlers thatLoggingowns. The handlers are not attached to any JUL logger, soLogManager.reset()from theCleanerhook has nothing to close. Level filtering, the PostgreSQL-style formatter and the rotatingFileHandlerare unchanged.LoggerFinderat build time, soserver/pom.xmladds--initialize-at-build-timeforLogging$FinderandLogging$Sink. Neither has static state. The handlers live inLogging, which is still initialized at run time.serveshutdown hook (now namedhstore-shutdown) closes Studio, the server and the database, then callsLogging.close(). That flushes and closes the handlers and removeshstore-0.log.lck.maincloses logging after a command returns.servejoins the shutdown hook before it returns, so the main thread can't close the handlers while the hook is still checkpointing.docs/operations/logging.mdexplains who owns the handlers.docs/operations/cli.mdlists exit code 143 forservestopped by SIGTERM.Testing
ServerTest.sigtermCheckpointsAndLogsTheCleanShutdownstartsservein a child JVM with the test's module path, waits forlistening on, sends SIGTERM withProcess.destroy()and checks the output forreceived shutdown request,checkpoint completeandshut down cleanly. With theserver/src/mainchanges reverted it failed 3 out of 3 runs, and the output stopped afterconfiguration: port=0.Manual repro, 20 runs on each side. Each run starts
serveon 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 overconnect, sendskill -TERM, then restarts on the same directory and reads the recovery line:received shutdown requestloggedcheckpoint completeloggedshut down cleanlyloggedThe 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.logends withshut down cleanlyand no.lckfile 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-timeentries the build stops in analysis, because the image heap ends up holding aLogging$Finderand aLogging$Sink(the latter throughjdk.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_directoryleaves no.lckfile../mvnw -q installpasses.