Add special handler to allow logger messages during shutdown #1387

drcrallen · 2015-05-22T23:08:19Z

This gets rid of those pesky FATAL Unable to register shutdown hook because JVM is shutting down. messages.

Previously the shutdown hooks fire essentially at random. This was causing logging messages to regularly be lost during the shutdown cycle if the log4j shutdown hook was fired before some of the ones that use logging in their shutdown messages.

This patch (with the appropriate server setting) causes the logger shutdown to fire as the last lifecycle.stop() item.

Omitting the server property simply reverts to the prior behavior of regularly discarding logger messages during shutdown.

drcrallen · 2015-05-22T23:15:24Z

Example without this patch:

2015-05-22T23:13:46,153 INFO [main] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void io.druid.server.coordination.AbstractDataSegmentAnnouncer.start()] on object[io.druid.server.coordination.BatchDataSegmentAnnouncer@7df01c0f].
2015-05-22T23:13:46,153 INFO [main] io.druid.server.coordination.AbstractDataSegmentAnnouncer - Announcing self[DruidServerMetadata{name='localhost:8081', host='localhost:8081', maxSize=10000000000, tier='_default_tier', type='historical', priority='0'}] at [/druid/announcements/localhost:8081]
2015-05-22T23:13:46,670 INFO [Thread-52] com.metamx.common.lifecycle.Lifecycle - Running shutdown hook
2015-05-22 23:13:46,703 FATAL Unable to register shutdown hook because JVM is shutting down.

Example WITH this patch:

2015-05-22T23:14:46,373 INFO [main] io.druid.server.coordination.AbstractDataSegmentAnnouncer - Announcing self[DruidServerMetadata{name='localhost:8081', host='localhost:8081', maxSize=10000000000, tier='_default_tier', type='historical', priority='0'}] at [/druid/announcements/localhost:8081]
2015-05-22T23:14:48,511 INFO [Thread-52] com.metamx.common.lifecycle.Lifecycle - Running shutdown hook
2015-05-22T23:14:48,514 INFO [Thread-52] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.server.coordination.AbstractDataSegmentAnnouncer.stop()] on object[io.druid.server.coordination.BatchDataSegmentAnnouncer@18a7811e].
2015-05-22T23:14:48,514 INFO [Thread-52] io.druid.server.coordination.AbstractDataSegmentAnnouncer - Stopping class io.druid.server.coordination.BatchDataSegmentAnnouncer with config[io.druid.server.initialization.ZkPathsConfig@58d3f4be]
2015-05-22T23:14:48,514 INFO [Thread-52] io.druid.curator.announcement.Announcer - unannouncing [/druid/announcements/localhost:8081]
2015-05-22T23:14:48,535 INFO [Thread-52] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.server.coordination.BaseZkCoordinator.stop()] on object[io.druid.server.coordination.ZkCoordinator@86e795a].
2015-05-22T23:14:48,535 INFO [Thread-52] io.druid.server.coordination.ZkCoordinator - Stopping ZkCoordinator for [DruidServerMetadata{name='localhost:8081', host='localhost:8081', maxSize=10000000000, tier='_default_tier', type='historical', priority='0'}]
2015-05-22T23:14:48,538 INFO [Thread-52] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.curator.announcement.Announcer.stop()] on object[io.druid.curator.announcement.Announcer@1eac5edf].
2015-05-22T23:14:48,539 INFO [Thread-52] io.druid.curator.announcement.Announcer - unannouncing [/druid/segments/localhost:8081/localhost:8081_historical__default_tier_2015-05-22T23:14:46.300Z_3f633ec82ac044cf87bfbd06f452026d0]
2015-05-22T23:14:48,540 INFO [Thread-52] io.druid.curator.CuratorModule - Stopping Curator
2015-05-22T23:14:48,545 INFO [Thread-52] org.apache.zookeeper.ZooKeeper - Session: 0x14d2f23309e0112 closed
2015-05-22T23:14:48,545 INFO [main-EventThread] org.apache.zookeeper.ClientCnxn - EventThread shut down
2015-05-22T23:14:48,558 INFO [Thread-52] org.eclipse.jetty.server.ServerConnector - Stopped ServerConnector@6a3cb917{HTTP/1.1}{0.0.0.0:8081}
2015-05-22T23:14:48,560 INFO [Thread-52] org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@3441ba3a{/,null,UNAVAILABLE}
2015-05-22T23:14:48,566 INFO [Thread-52] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.metrics.MonitorScheduler.stop()] on object[com.metamx.metrics.MonitorScheduler@44b641c4].
2015-05-22T23:14:48,567 INFO [Thread-52] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.emitter.service.ServiceEmitter.close() throws java.io.IOException] on object[com.metamx.emitter.service.ServiceEmitter@2fc64742].
2015-05-22T23:14:48,567 INFO [Thread-52] com.metamx.emitter.core.LoggingEmitter - Close: started [false]
2015-05-22T23:14:48,567 INFO [Thread-52] com.metamx.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void com.metamx.emitter.core.LoggingEmitter.close() throws java.io.IOException] on object[com.metamx.emitter.core.LoggingEmitter@3b53bb3b].

gianm · 2015-05-23T00:29:10Z

Bummer about the shutdown hooks.

Some questions:

Does the code actually get called? It doesn't look like anything is injecting the QuietLoggerShutdown and I dunno if it will actually get instantiated.
Is it possible to do something useful without needing a property? If not, how about emitting a warning on startup if the property isn't there, so people know they have a less than perfect setup?
Is the dependency worth it or is it doing something really simple that we could just do ourselves?

drcrallen · 2015-05-24T02:46:39Z

@gianm : The dependency is exactly one java class https://github.com/DjDCH/Log4j-StaticShutdown/blob/master/src/main/java/com/djdch/log4j/StaticShutdownCallbackRegistry.java that we would pretty much have to copy to get the functionality. It is MIT license so direct copy is probably a no-go.

The CLI classes pickup ManageLifecycle automagically.

This will revert to the prior behavior if the property is missing.

cheddar · 2015-05-27T23:34:23Z

Looking at what that class does, it basically just extends Log4j's ShutdownCallbackRegistry. It's pretty difficult to do programmatic stuff to adjust the configuration of the log4j subsystem when you use properties files to initialize it. We essentially need to set the system property before the log4j system is initialized.

I believe it is initialized by the first call to LoggerFactory.getLogger() in com.metamx.common.logging.Logger.

So, if we were to actually add a static initializer there to set the system property for us, we would likely be able to register our own shutdown handler instead of having it use the internal one.

I would then recommend that we create our own ShutdownCallbackRegistry that

Registers with the normal JVM shutdown hook
On start() removes the JVM shutdown hook
On close(), if start() was called, shuts things down, if start() was not called, is a noop.

drcrallen · 2015-06-01T17:27:50Z

@cheddar : Doing such a thing in the Logger would also be a multi-system intrusion of log4j instead of slf4j abstraction.

We cannot rely on the JVM shutdown hook because they are fired essentially randomly. We have to be able to specify that the logger shutdown hook runs after the Lifecycle shutdown, which is not the case if both are simply shutdown hooks (unless you know some magic you would like to share :) )

drcrallen · 2015-06-05T18:13:30Z

@cheddar : Modified

cheddar · 2015-06-12T18:10:02Z

common/src/main/java/io/druid/common/config/Log4jShutdown.java

+      }
+    };
+    shutdownCallbacks.add(cancellable);
+    if (!isStarted()) {


It's not clear to me why this means that we are shutting down in the middle of registering. Couldn't it just not have been started in the first place?

method has a !isStarted check at the top. If it is started at the top but not started here, it is because of a shutdown in progress.

cheddar · 2015-06-12T18:16:44Z

Is it at all possible to add a check somewhere that can notice if the static property setting stuff was too late and warn/error about it?

cheddar · 2015-06-12T18:18:14Z

server/src/main/java/io/druid/initialization/Log4jShutterDownerModule.java

+            "shutdownCallbackRegistry"
+        );
+        shutdownCallbackRegistryField.setAccessible(true);
+        final Log4jShutdown log4jShutdown = (Log4jShutdown) shutdownCallbackRegistryField.get(LogManager.getFactory());


Why do we need reflection to reach in and call the shutdowner? Can't we just get it injected?

Log4j does its own instantiation based on the system property and does not inject through guice. This was the only way at the time I could find of grabbing the log4j instance. Seems like a bug in log4j2 imho (unless I'm missing something)

drcrallen · 2015-09-02T18:11:27Z

@cheddar There is now a check in the configure step via class cast and a warning if the class cast fails.

gianm · 2015-10-27T17:57:30Z

👍

drcrallen · 2015-10-27T18:17:45Z

@gianm / @cheddar updated to 2.4.1 to eliminate the need for reflection

gianm · 2015-10-27T21:26:17Z

server/src/main/java/io/druid/initialization/Log4jShutterDownerModule.java

+            .to(Log4jShutterDowner.class)
+            .asEagerSingleton();
+    }
+    catch (ClassNotFoundException | ClassCastException e) {


Should this be catching NoClassDefFoundError too? I think that would pop up if the log4j stuff (like org.apache.logging.log4j.core.impl.Log4jContextFactory) isn't on the classpath.

Added LinkageError

* Adds a special PropertyChecker interface which is ONLY for setting string properties at the very start of psvm

gianm · 2015-10-27T21:37:39Z

still 👍

Add special handler to allow logger messages during shutdown

drcrallen mentioned this pull request May 22, 2015

stop java process results in unclean shutdown with EXIT 143 or 130 depending on signal #1378

Closed

drcrallen force-pushed the enableShutdownLogging branch 3 times, most recently from 4333af4 to 9d7ba77 Compare June 5, 2015 18:11

drcrallen added Ease of Use Ease of Use labels Jun 6, 2015

xvrl removed the Ease of Use label Jun 9, 2015

cheddar reviewed Jun 12, 2015
View reviewed changes

drcrallen added the Discuss label Jun 24, 2015

drcrallen added this to the 0.9 milestone Sep 2, 2015

drcrallen force-pushed the enableShutdownLogging branch from 9d7ba77 to d6dbdb7 Compare September 2, 2015 18:10

drcrallen removed the Discuss label Sep 2, 2015

drcrallen closed this Sep 3, 2015

drcrallen reopened this Sep 3, 2015

drcrallen closed this Sep 4, 2015

drcrallen reopened this Sep 4, 2015

drcrallen force-pushed the enableShutdownLogging branch from d6dbdb7 to 22a4703 Compare September 8, 2015 21:03

drcrallen force-pushed the enableShutdownLogging branch from 22a4703 to a3dedfc Compare October 27, 2015 18:17

gianm reviewed Oct 27, 2015
View reviewed changes

Add special handler to allow logger messages during shutdown

7a2ceef

* Adds a special PropertyChecker interface which is ONLY for setting string properties at the very start of psvm

drcrallen force-pushed the enableShutdownLogging branch from a3dedfc to 7a2ceef Compare October 27, 2015 21:33

xvrl added a commit that referenced this pull request Nov 10, 2015

Merge pull request #1387 from metamx/enableShutdownLogging

a57cbfd

Add special handler to allow logger messages during shutdown

xvrl merged commit a57cbfd into apache:master Nov 10, 2015

xvrl deleted the enableShutdownLogging branch November 10, 2015 01:20

gianm modified the milestones: 0.8.3, 0.9.0 Dec 1, 2015

This was referenced Dec 1, 2015

0.8.3 backports #2022

Merged

druid-0.8.3 release notes #2044

Closed

This was referenced Dec 17, 2015

Nodes won't die if zookeeper went away. #2016

Closed

Log4jShutdown.stop not idempotent #2124

Closed

ServerDiscoverySelector.stop() not idempotent #2123

Closed

ExecutorLifecycle stop not idempotent #2122

Closed

seoeun25 pushed a commit to seoeun25/incubator-druid that referenced this pull request Jan 10, 2020

apache#1387 No need to sort left alias for hash join

2c64a3e

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add special handler to allow logger messages during shutdown #1387

Add special handler to allow logger messages during shutdown #1387

drcrallen commented May 22, 2015

drcrallen commented May 22, 2015

gianm commented May 23, 2015

drcrallen commented May 24, 2015

cheddar commented May 27, 2015

drcrallen commented Jun 1, 2015

drcrallen commented Jun 5, 2015

cheddar Jun 12, 2015

drcrallen Jun 12, 2015

cheddar commented Jun 12, 2015

cheddar Jun 12, 2015

drcrallen Jun 12, 2015

drcrallen commented Sep 2, 2015

gianm commented Oct 27, 2015

drcrallen commented Oct 27, 2015

gianm Oct 27, 2015

drcrallen Oct 27, 2015

gianm commented Oct 27, 2015

Add special handler to allow logger messages during shutdown #1387

Add special handler to allow logger messages during shutdown #1387

Conversation

drcrallen commented May 22, 2015

drcrallen commented May 22, 2015

gianm commented May 23, 2015

drcrallen commented May 24, 2015

cheddar commented May 27, 2015

drcrallen commented Jun 1, 2015

drcrallen commented Jun 5, 2015

cheddar Jun 12, 2015

Choose a reason for hiding this comment

drcrallen Jun 12, 2015

Choose a reason for hiding this comment

cheddar commented Jun 12, 2015

cheddar Jun 12, 2015

Choose a reason for hiding this comment

drcrallen Jun 12, 2015

Choose a reason for hiding this comment

drcrallen commented Sep 2, 2015

gianm commented Oct 27, 2015

drcrallen commented Oct 27, 2015

gianm Oct 27, 2015

Choose a reason for hiding this comment

drcrallen Oct 27, 2015

Choose a reason for hiding this comment

gianm commented Oct 27, 2015