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 2018/10/17 01:33:18 UTC
[GitHub] KenjiTakahashi edited a comment on issue #6468: Unexpected
"Triggering JVM shutdown"
KenjiTakahashi edited a comment on issue #6468: Unexpected "Triggering JVM shutdown"
URL: https://github.com/apache/incubator-druid/issues/6468#issuecomment-430457651
I have, but I did it wrongly. Seems our logging pipeline started timestamping with local time, for some reason... Anyway, found the affecting lines now:
```
2018-10-13T10:50:02,395 WARN [main-SendThread(demopm1-lin:2181)] org.apache.zookeeper.ClientCnxn - Client session timed out, have not heard from server in 72673ms for sessionid 0x164f1464cf900e0
2018-10-13T10:50:02,430 INFO [Coordinator-Exec--0] io.druid.server.coordinator.helper.DruidCoordinatorSegmentInfoLoader - Starting coordination. Getting available segments.
2018-10-13T10:50:02,452 INFO [main-SendThread(demopm1-lin:2181)] org.apache.zookeeper.ClientCnxn - Client session timed out, have not heard from server in 72673ms for sessionid 0x164f1464cf900e0, closing socket connection and attempting reconnect
2018-10-13T10:50:02,452 INFO [Coordinator-Exec--0] io.druid.server.coordinator.helper.DruidCoordinatorSegmentInfoLoader - Found [3,981] available segments.
2018-10-13T10:50:02,467 INFO [Coordinator-Exec--0] io.druid.server.coordinator.ReplicationThrottler - [_default_tier]: Replicant create queue is empty.
2018-10-13T10:50:02,471 INFO [DatabaseRuleManager-Exec--0] io.druid.metadata.SQLMetadataRuleManager - Polled and found rules for 2 datasource(s)
2018-10-13T10:50:02,503 INFO [Coordinator-Exec--0] io.druid.server.coordinator.helper.DruidCoordinatorBalancer - [_default_tier]: One or fewer servers found. Cannot balance.
2018-10-13T10:50:02,503 INFO [Coordinator-Exec--0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Assigned 0 segments among 1 servers
2018-10-13T10:50:02,503 INFO [Coordinator-Exec--0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - [_default_tier] : Dropped 0 segments among 1 servers
2018-10-13T10:50:02,503 INFO [Coordinator-Exec--0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - Load Queues:
2018-10-13T10:50:02,503 INFO [Coordinator-Exec--0] io.druid.server.coordinator.helper.DruidCoordinatorLogger - Server[demopm1-lin:10020, historical, _default_tier] has 0 left to load, 0 left to drop, 0 bytes queued, 154,353,403,052 bytes served.
2018-10-13T10:50:02,601 INFO [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: SUSPENDED
2018-10-13T10:50:02,845 INFO [DatabaseSegmentManager-Exec--0] io.druid.metadata.SQLMetadataSegmentManager - Polled and found 3,981 segments in the database
2018-10-13T10:50:03,236 INFO [NodeTypeWatcher[peon]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_SUSPENDED] for nodeType watcher.
2018-10-13T10:50:03,464 INFO [NodeTypeWatcher[overlord]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_SUSPENDED] for nodeType watcher.
2018-10-13T10:50:03,464 INFO [NodeTypeWatcher[broker]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_SUSPENDED] for nodeType watcher.
2018-10-13T10:50:03,465 INFO [NodeTypeWatcher[historical]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_SUSPENDED] for nodeType watcher.
2018-10-13T10:50:03,510 INFO [LeaderSelector[/druid/coordinator/_COORDINATOR]] io.druid.server.coordinator.DruidCoordinator - I am no longer the leader...
2018-10-13T10:50:03,528 INFO [LeaderSelector[/druid/coordinator/_COORDINATOR]] io.druid.curator.discovery.CuratorServiceAnnouncer - Unannouncing service[DruidNode{serviceName='druid/coordinator', host='demopm1-lin', port=-1, plaintextPort=10040, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}]
2018-10-13T10:50:03,600 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.curator.discovery.CuratorServiceAnnouncer - Unannouncing service[DruidNode{serviceName='druid/overlord', host='demopm1-lin', port=-1, plaintextPort=10040, enablePlaintextPort=true, tlsPort=-1, enableTlsPort=false}]
2018-10-13T10:50:04,392 INFO [main-SendThread(demopm1-lin:2181)] org.apache.zookeeper.ClientCnxn - Opening socket connection to server demopm1-lin/127.0.0.1:2181. Will not attempt to authenticate using SASL (unknown error)
2018-10-13T10:50:04,425 INFO [main-SendThread(demopm1-lin:2181)] org.apache.zookeeper.ClientCnxn - Socket connection established to demopm1-lin/127.0.0.1:2181, initiating session
2018-10-13T10:50:04,611 WARN [main-SendThread(demopm1-lin:2181)] org.apache.zookeeper.ClientCnxn - Unable to reconnect to ZooKeeper service, session 0x164f1464cf900e0 has expired
2018-10-13T10:50:04,611 INFO [main-SendThread(demopm1-lin:2181)] org.apache.zookeeper.ClientCnxn - Unable to reconnect to ZooKeeper service, session 0x164f1464cf900e0 has expired, closing socket connection
2018-10-13T10:50:04,625 WARN [main-EventThread] org.apache.curator.ConnectionState - Session expired event received
2018-10-13T10:50:04,674 INFO [main-EventThread] org.apache.zookeeper.ZooKeeper - Initiating client connection, connectString=sv-zookeeper sessionTimeout=30000 watcher=org.apache.curator.ConnectionState@40247d48
2018-10-13T10:50:04,703 INFO [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: LOST
2018-10-13T10:50:04,704 INFO [main-EventThread] org.apache.zookeeper.ClientCnxn - EventThread shut down for session: 0x164f1464cf900e0
2018-10-13T10:50:04,704 INFO [NodeTypeWatcher[overlord]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_LOST] for nodeType watcher.
2018-10-13T10:50:04,705 INFO [Announcer-0] io.druid.curator.announcement.Announcer - Node[/druid/internal-discovery/coordinator/demopm1-lin:10040] is added to reinstate.
2018-10-13T10:50:04,705 INFO [NodeTypeWatcher[historical]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_LOST] for nodeType watcher.
2018-10-13T10:50:04,705 INFO [Announcer-0] io.druid.curator.announcement.Announcer - Node[/druid/internal-discovery/overlord/demopm1-lin:10040] is added to reinstate.
2018-10-13T10:50:04,705 INFO [NodeTypeWatcher[peon]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_LOST] for nodeType watcher.
2018-10-13T10:50:04,705 INFO [NodeTypeWatcher[broker]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_LOST] for nodeType watcher.
2018-10-13T10:50:04,741 INFO [main-SendThread(demopm1-lin:2181)] org.apache.zookeeper.ClientCnxn - Opening socket connection to server demopm1-lin/127.0.0.1:2181. Will not attempt to authenticate using SASL (unknown error)
2018-10-13T10:50:04,741 INFO [main-SendThread(demopm1-lin:2181)] org.apache.zookeeper.ClientCnxn - Socket connection established to demopm1-lin/127.0.0.1:2181, initiating session
2018-10-13T10:50:05,079 INFO [main-SendThread(demopm1-lin:2181)] org.apache.zookeeper.ClientCnxn - Session establishment complete on server demopm1-lin/127.0.0.1:2181, sessionid = 0x164f1464cf900e6, negotiated timeout = 30000
2018-10-13T10:50:05,080 INFO [main-EventThread] org.apache.curator.framework.state.ConnectionStateManager - State change: RECONNECTED
2018-10-13T10:50:05,201 INFO [NodeTypeWatcher[overlord]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_RECONNECTED] for nodeType watcher.
2018-10-13T10:50:05,201 INFO [NodeTypeWatcher[peon]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_RECONNECTED] for nodeType watcher.
2018-10-13T10:50:05,201 INFO [Announcer-0] io.druid.curator.announcement.Announcer - Reinstating [/druid/internal-discovery/coordinator/demopm1-lin:10040]
2018-10-13T10:50:05,201 INFO [NodeTypeWatcher[broker]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_RECONNECTED] for nodeType watcher.
2018-10-13T10:50:05,201 INFO [NodeTypeWatcher[historical]] io.druid.curator.discovery.CuratorDruidNodeDiscoveryProvider$NodeTypeWatcher - Ignored event type [CONNECTION_RECONNECTED] for nodeType watcher.
2018-10-13T10:50:05,465 INFO [Announcer-0] io.druid.curator.announcement.Announcer - Reinstating [/druid/internal-discovery/overlord/demopm1-lin:10040]
2018-10-13T10:50:05,857 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.overlord.helpers.OverlordHelperManager.stop()] on object[io.druid.indexing.overlord.helpers.OverlordHelperManager@4f87c64f].
2018-10-13T10:50:05,857 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.indexing.overlord.helpers.OverlordHelperManager - OverlordHelperManager is stopping.
2018-10-13T10:50:05,857 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.indexing.overlord.helpers.OverlordHelperManager - OverlordHelperManager is stopped.
2018-10-13T10:50:05,857 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.overlord.supervisor.SupervisorManager.stop()] on object[io.druid.indexing.overlord.supervisor.SupervisorManager@35a47246].
2018-10-13T10:50:05,858 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.indexing.overlord.supervisor.SupervisorManager - SupervisorManager stopped.
2018-10-13T10:50:05,858 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.overlord.TaskQueue.stop()] on object[io.druid.indexing.overlord.TaskQueue@1d0e7a7a].
2018-10-13T10:50:05,947 INFO [TaskQueue-Manager] io.druid.indexing.overlord.TaskQueue - Interrupted, exiting!
2018-10-13T10:50:05,948 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.java.util.common.lifecycle.Lifecycle$AnnotationBasedHandler - Invoking stop method[public void io.druid.indexing.overlord.ForkingTaskRunner.stop()] on object[io.druid.indexing.overlord.ForkingTaskRunner@36bf526].
2018-10-13T10:50:05,948 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.indexing.overlord.ForkingTaskRunner - Closing output stream to task[index_realtime_pm_data_0_2018-10-11T22:24:13.446Z_mhccmjeb].
2018-10-13T10:50:06,039 INFO [LeaderSelector[/druid/overlord/_OVERLORD]] io.druid.indexing.overlord.ForkingTaskRunner - Closing output stream to task[index_realtime_pm_data_0_2018-10-11T22:24:13.446Z_cdneigbb].
```
So, the new question is, why *this* happens?
[Possibly important note: We're using Overlord inside Coordinator.]
It seems that dropped ZK connection causes Coordinator to loose leadership and in turn perform a pretty thorough restart of everything?
EDIT: We have only one Coordinator running there.
Does not sound very sensible, tbh. I will investigate it more tomorrow, but any thoughts are still welcome.
----------------------------------------------------------------
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