Delay shutdown of logging facilities until the application has completed its shutdown process

[basil]

Fixes #219.

Steps to reproduce

1. Run java -jar war/target/jenkins.war.
2. Press Control-C.

Expected results

Note: These are the actual results with this PR.

The application shutdown process prints the following logs:

2022-04-12 16:55:59.703+0000 [id=26]    INFO    winstone.Logger#logInternal: JVM is terminating. Shutting down Jetty
2022-04-12 16:55:59.710+0000 [id=26]    INFO    o.e.j.server.AbstractConnector#doStop: Stopped ServerConnector@6cd24612{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2022-04-12 16:55:59.710+0000 [id=26]    INFO    o.e.j.server.session.HouseKeeper#stopScavenging: node0 Stopped scavenging
2022-04-12 16:55:59.711+0000 [id=26]    INFO    hudson.lifecycle.Lifecycle#onStatusUpdate: Stopping Jenkins
2022-04-12 16:55:59.714+0000 [id=26]    INFO    jenkins.model.Jenkins$16#onAttained: Started termination
2022-04-12 16:55:59.720+0000 [id=26]    INFO    jenkins.model.Jenkins$16#onAttained: Completed termination
2022-04-12 16:55:59.720+0000 [id=26]    INFO    jenkins.model.Jenkins#_cleanUpDisconnectComputers: Starting node disconnection
2022-04-12 16:55:59.723+0000 [id=26]    INFO    jenkins.model.Jenkins#_cleanUpShutdownPluginManager: Stopping plugin manager
2022-04-12 16:55:59.725+0000 [id=26]    INFO    jenkins.model.Jenkins#_cleanUpPersistQueue: Persisting build queue
2022-04-12 16:55:59.737+0000 [id=26]    INFO    jenkins.model.Jenkins#_cleanUpAwaitDisconnects: Waiting for node disconnection completion
2022-04-12 16:55:59.737+0000 [id=26]    INFO    hudson.lifecycle.Lifecycle#onStatusUpdate: Jenkins stopped
2022-04-12 16:55:59.738+0000 [id=26]    INFO    o.e.j.s.handler.ContextHandler#doStop: Stopped w.@652ab8d9{Jenkins v2.344-SNAPSHOT,/,null,STOPPED}{/home/basil/.jenkins/war}

Actual results

The application shutdown process does not print any logs:

2022-04-12 16:57:31.176+0000 [id=32]    INFO    hudson.lifecycle.Lifecycle#onStatusUpdate: Stopping Jenkins
2022-04-12 16:57:31.176+0000 [id=26]    INFO    winstone.Logger#logInternal: JVM is terminating. Shutting down Jetty

Evaluation

As described in JDK-8161253, there is no way to control the order of execution of shutdown hooks. When the LogManager#Cleaner shutdown hook runs before Winstone's shutdown hook, it shuts down logging facilities. Logging facilities are subsequently unavailable to the application shutdown process, which is invoked from Winstone's shutdown hook.

Solution

In the comments to JDK-8161253, Jason Mehrens suggests a workaround: create a custom log handler and install it on the root logger before all other log handlers. Since the first action of LogManager#Cleaner is to close all the installed log handlers on the root logger, it will invoke the custom log handler's close() method. At this point, the custom log handler has intercepted control and can delay shutdown of logging facilities until the application has completed its shutdown process.

Implementation

Added a 5-second sleep to ensure that we don't wait forever if the shutdown process is not making progress.

Testing disconnection

Ran the steps to reproduce before and after this change. Before this change, I could reproduce this problem. After this change, I could not.

Also ran this change against core with an artificial modification to add a 30-second sleep to the application shutdown process. Verified that we stopped getting logs after 5 seconds, ensuring that the timeout logic was working.

[jglick]

Seems to work even with jenkinsci/log-cli-plugin#119 active.