clintropolis opened a new pull request #6864: add 'init' lifecycle stage for finer control over startup and shutdown URL: https://github.com/apache/incubator-druid/pull/6864 This PR introduces an additional lifecycle stage, `Lifecycle.Stage.INIT` which runs first on startup and last on shutdown. The primary reason for this is to put `Log4jShutterDownerModule` in the `INIT` level to ensure it runs last on shutdown, fixing errors similar to those reported in #5568, which was caused by log4j shutdown running late, but not last, with `LoggingEmitter`, `DiscoveryModule`, `Announcer` `CuratorModule` commonly shutting down after log4j shutdown. Also adds a `name` field to `Lifecycle` which helps with additional logging around lifecycle stage startup and stops and which lifecycle they belong to. on startup: ``` 2019-01-15T10:20:20,157 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle - Starting lifecycle [module] stage [INIT] 2019-01-15T10:20:20,158 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking start method[public void org.apache.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.start()] on object[org.apache.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@5e7c141d]. 2019-01-15T10:20:20,158 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle - Starting lifecycle [module] stage [NORMAL] 2019-01-15T10:20:20,158 INFO [main] org.apache.druid.curator.CuratorModule - Starting Curator 2019-01-15T10:20:20,158 INFO [main] org.apache.curator.framework.imps.CuratorFrameworkImpl - Starting .... ``` and stopping: ``` 2019-01-15T10:23:35,297 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle - Lifecycle [module] running shutdown hook 2019-01-15T10:23:35,301 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [module] stage [LAST] 2019-01-15T10:23:35,303 INFO [Thread-49] org.apache.druid.curator.discovery.CuratorDruidNodeAnnouncer - Unannouncing [DiscoveryDruidNode{druidNode=DruidNode{serviceName='coordinator', host='localhost', bindOnHost=false, port=-1, plaintextPort=8081, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='COORDINATOR', services={}}]. 2019-01-15T10:23:35,303 INFO [Thread-49] org.apache.druid.curator.announcement.Announcer - unannouncing [/druid/internal-discovery/COORDINATOR/localhost:8081] 2019-01-15T10:23:35,330 INFO [Thread-49] org.apache.druid.curator.discovery.CuratorDruidNodeAnnouncer - Unannounced [DiscoveryDruidNode{druidNode=DruidNode{serviceName='coordinator', host='localhost', bindOnHost=false, port=-1, plaintextPort=8081, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='COORDINATOR', services={}}]. 2019-01-15T10:23:35,330 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [module] stage [NORMAL] 2019-01-15T10:23:35,334 INFO [Thread-49] org.apache.druid.server.initialization.jetty.JettyServerModule - Stopping Jetty Server... 2019-01-15T10:23:35,340 INFO [Thread-49] org.eclipse.jetty.server.AbstractConnector - Stopped ServerConnector@6f5d0190{HTTP/1.1,[http/1.1]}{0.0.0.0:8081} 2019-01-15T10:23:35,340 INFO [Thread-49] org.eclipse.jetty.server.session - node0 Stopped scavenging 2019-01-15T10:23:35,342 INFO [Thread-49] org.eclipse.jetty.server.handler.ContextHandler - Stopped o.e.j.s.ServletContextHandler@1980a3f{/,[jar:file:/Users/clint/.m2/repository/io/druid/druid-console/0.0.4/druid-console-0.0.4.jar!/io/druid/console, file:///Users/clint/workspace/clintropolis/druid/server/target/classes/static/],UNAVAILABLE} 2019-01-15T10:23:35,345 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.server.coordinator.DruidCoordinator.stop()] on object[org.apache.druid.server.coordinator.DruidCoordinator@7d70638]. 2019-01-15T10:23:35,348 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.discovery.DruidLeaderClient.stop()] on object[org.apache.druid.discovery.DruidLeaderClient@67f77f6e]. 2019-01-15T10:23:35,348 INFO [Thread-49] org.apache.druid.discovery.DruidLeaderClient - Stopped. 2019-01-15T10:23:35,349 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.curator.discovery.ServerDiscoverySelector.stop() throws java.io.IOException] on object[org.apache.druid.curator.discovery.ServerDiscoverySelector@44fff386]. 2019-01-15T10:23:35,350 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider.stop()] on object[org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider@11f9535b]. 2019-01-15T10:23:35,350 INFO [Thread-49] org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider - stopping 2019-01-15T10:23:35,351 INFO [Thread-49] org.apache.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider - stopped 2019-01-15T10:23:35,351 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [http-client] stage [LAST] 2019-01-15T10:23:35,351 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [http-client] stage [NORMAL] 2019-01-15T10:23:35,351 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.java.util.http.client.NettyHttpClient.stop()] on object[org.apache.druid.java.util.http.client.NettyHttpClient@41a374be]. 2019-01-15T10:23:35,358 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [http-client] stage [INIT] 2019-01-15T10:23:35,358 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.metadata.SQLMetadataRuleManager.stop()] on object[org.apache.druid.metadata.SQLMetadataRuleManager@41ad373]. 2019-01-15T10:23:35,358 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.client.AbstractCuratorServerInventoryView.stop() throws java.io.IOException] on object[org.apache.druid.client.BatchServerInventoryView@403c3a01]. 2019-01-15T10:23:35,359 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.metadata.SQLMetadataSegmentManager.stop()] on object[org.apache.druid.metadata.SQLMetadataSegmentManager@6f798482]. 2019-01-15T10:23:35,359 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.common.config.ConfigManager.stop()] on object[org.apache.druid.common.config.ConfigManager@44af588b]. 2019-01-15T10:23:35,359 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.java.util.metrics.MonitorScheduler.stop()] on object[org.apache.druid.java.util.metrics.MonitorScheduler@2938127d]. 2019-01-15T10:23:35,359 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.java.util.emitter.service.ServiceEmitter.close() throws java.io.IOException] on object[ServiceEmitter{serviceDimensions={service=coordinator, host=localhost:8081, version=}, emitter=LoggingEmitter{log=Logger{name=[org.apache.druid.java.util.emitter.core.LoggingEmitter], class[class org.apache.logging.slf4j.Log4jLogger]}, level=INFO}}]. 2019-01-15T10:23:35,359 INFO [Thread-49] org.apache.druid.java.util.emitter.core.LoggingEmitter - Close: started [false] 2019-01-15T10:23:35,359 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.java.util.emitter.core.LoggingEmitter.close()] on object[LoggingEmitter{log=Logger{name=[org.apache.druid.java.util.emitter.core.LoggingEmitter], class[class org.apache.logging.slf4j.Log4jLogger]}, level=INFO}]. 2019-01-15T10:23:35,365 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.curator.announcement.Announcer.stop()] on object[org.apache.druid.curator.announcement.Announcer@934b52f]. 2019-01-15T10:23:35,365 INFO [Thread-49] org.apache.druid.curator.announcement.Announcer - Stopping announcer 2019-01-15T10:23:35,365 INFO [Thread-49] org.apache.druid.curator.CuratorModule - Stopping Curator 2019-01-15T10:23:35,366 INFO [Curator-Framework-0] org.apache.curator.framework.imps.CuratorFrameworkImpl - backgroundOperationsLoop exiting 2019-01-15T10:23:35,373 INFO [Thread-49] org.apache.zookeeper.ZooKeeper - Session: 0x1000aa973a2005e closed 2019-01-15T10:23:35,373 INFO [main-EventThread] org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x1000aa973a2005e 2019-01-15T10:23:35,373 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle - Stopping lifecycle [module] stage [INIT] 2019-01-15T10:23:35,373 INFO [Thread-49] org.apache.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void org.apache.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner.stop()] on object[org.apache.druid.initialization.Log4jShutterDownerModule$Log4jShutterDowner@5e7c141d]. ``` Finally, I was starting and stopping things so often trying to isolate this issue that I added a fun but totally useless ascii banner after service announce so my Druid would shout from the rooftops that it had announced itself: ``` 2019-01-15T21:05:58,205 INFO [main] org.eclipse.jetty.server.Server - Started @6655ms 2019-01-15T21:05:58,205 INFO [main] org.apache.druid.java.util.common.lifecycle.Lifecycle - Starting lifecycle [module] stage [LAST] 2019-01-15T21:05:58,205 INFO [main] org.apache.druid.curator.discovery.CuratorDruidNodeAnnouncer - Announcing [DiscoveryDruidNode{druidNode=DruidNode{serviceName='coordinator', host='localhost', bindOnHost=false, port=-1, plaintextPort=8081, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='COORDINATOR', services={}}]. 2019-01-15T21:05:58,238 INFO [main] org.apache.druid.curator.discovery.CuratorDruidNodeAnnouncer - Announced [DiscoveryDruidNode{druidNode=DruidNode{serviceName='coordinator', host='localhost', bindOnHost=false, port=-1, plaintextPort=8081, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}, nodeType='COORDINATOR', services={}}]. 2019-01-15T21:05:58,239 INFO [main] org.apache.druid.cli.ServerRunnable - .''''''''''''''''''''. 'kkkkkkkkkkkkkkkkkkkkkkkdl;. ..,:dkxc. ;O, .xo oO. .;dko. dM; .l; .WW. ,:::::. .;:::::::::::::::::::;,'. ckk' xM' 'M0 :ccccc, .cccccccccccccccccccclldkxl' :kd .cdOXXKkd; KX .xk;oOXXO' 'O; oO. oO. 'lx0XXKko':MO .,dkc ok, 'OWk;.....:0NWO 'MMWl...,. xM, ,MX. KM' ;KNo'....'cKNMl .kk. ck; ;NN' xMd :MM: OM' lMO .NK cWK. .NMc xk' ok, KM; lMl lMx .XX oMx .Mo .WN. .WM' ,kx. .xk. .WM' kM, kMc .Mx 0M; :Ml .M0 'MW. ;kk, lkl kMk oMK OM' 'MK ,NM' lM' .NMd .OMk ..:dko' ckx. .xNKo,..';oKKMK .WW. oW0c''',ckXMX xM' .OW0:'..':xXXMl ,llllllllllllllllllllodxkxo:. .oko. .;okOOxoc..d: .dc .cxOOOdc,.oc cl .cdOOOxo;.,d' ',,,,,,,,,,,,,,,,,,,,.. 'okkc .,okxc. ...... ......'':coxkdc. 'kkkkkk; dkkkkkxdlc;'. ...... ..... 'coordinator' has joined the Apache Druid (incubating) cluster! 2019-01-15T21:05:59,280 INFO [LookupCoordinatorManager--0] org.apache.druid.server.lookup.cache.LookupCoordinatorManager - Not updating lookups because no data exists 2019-01-15T21:06:02,479 INFO [Coordinator-Exec--0] org.apache.druid.common.config.ConfigManager - Creating watch for key[coordinator.compaction.config] 2019-01-15T21:06:02,483 INFO [Coordinator-Exec--0] org.apache.druid.server.coordinator.helper.DruidCoordinatorSegmentInfoLoader - Starting coordination. Getting available segments. ``` ... which I can remove if anyone has any opposition.
---------------------------------------------------------------- This is an automated message from the Apache Git Service. To respond to the message, please log on GitHub and use the URL above to go to the specific comment. For queries about this service, please contact Infrastructure at: [email protected] With regards, Apache Git Services --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
