You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@druid.apache.org by GitBox <gi...@apache.org> on 2019/01/15 22:51:16 UTC
[GitHub] clintropolis opened a new pull request #6864: add 'init' lifecycle
stage for finer control over startup and shutdown
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:
users@infra.apache.org
With regards,
Apache Git Services
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@druid.apache.org
For additional commands, e-mail: commits-help@druid.apache.org