"Path must start with / character" leads to Singularity hanging forever

[stevenschlansker]

We had a minor production incident caused by Singularity's connection to ZK entering a zombie state.

INFO  [2015-07-14 07:59:13,127] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@54f4a7f0{/,null,AVAILABLE}
INFO  [2015-07-14 07:59:13,129] io.dropwizard.setup.AdminEnvironment: tasks = 

    POST    /tasks/gc (io.dropwizard.servlets.tasks.GarbageCollectionTask)

INFO  [2015-07-14 07:59:13,133] org.eclipse.jetty.server.handler.ContextHandler: Started i.d.j.MutableServletContextHandler@408e96d9{/admin,null,AVAILABLE}
INFO  [2015-07-14 07:59:13,152] org.eclipse.jetty.server.ServerConnector: Started SingularityService@12f8b1d8{HTTP/1.1}{0.0.0.0:7099}
INFO  [2015-07-14 07:59:32,309] org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x24e8b9313780002, likely server has closed socket, closing socket connection and attempting reconnect
INFO  [2015-07-14 07:59:32,413] org.apache.curator.framework.state.ConnectionStateManager: State change: SUSPENDED
INFO  [2015-07-14 07:59:32,481] org.apache.zookeeper.ClientCnxn: Opening socket connection to server mesos3-prod-sc.otsql.opentable.com/10.20.16.252:2181. Will not attempt to authenticate using SASL (unknown error)
INFO  [2015-07-14 07:59:32,482] org.apache.zookeeper.ClientCnxn: Socket connection established to mesos3-prod-sc.otsql.opentable.com/10.20.16.252:2181, initiating session
INFO  [2015-07-14 07:59:32,785] org.apache.zookeeper.ClientCnxn: Session establishment complete on server mesos3-prod-sc.otsql.opentable.com/10.20.16.252:2181, sessionid = 0x24e8b9313780002, negotiated timeout = 40000
INFO  [2015-07-14 07:59:32,786] org.apache.curator.framework.state.ConnectionStateManager: State change: RECONNECTED
ERROR [2015-07-14 07:59:33,428] org.apache.curator.framework.imps.CuratorFrameworkImpl: Background exception was not retry-able or retry gave up
! java.lang.IllegalArgumentException: Path must start with / character
! at org.apache.curator.utils.PathUtils.validatePath(PathUtils.java:53) ~[singularity-20150708-2.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.utils.ZKPaths.getNodeFromPath(ZKPaths.java:56) ~[singularity-20150708-2.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.recipes.leader.LeaderLatch.checkLeadership(LeaderLatch.java:478) ~[singularity-20150708-2.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.recipes.leader.LeaderLatch.access$500(LeaderLatch.java:60) ~[singularity-20150708-2.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.recipes.leader.LeaderLatch$6.processResult(LeaderLatch.java:535) ~[singularity-20150708-2.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.imps.CuratorFrameworkImpl.sendToBackgroundCallback(CuratorFrameworkImpl.java:686) [singularity-20150708-2.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:485) [singularity-20150708-2.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.imps.GetChildrenBuilderImpl$2.processResult(GetChildrenBuilderImpl.java:166) [singularity-20150708-2.jar:0.4.3-SNAPSHOT]
! at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:587) [singularity-20150708-2.jar:0.4.3-SNAPSHOT]
! at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495) [singularity-20150708-2.jar:0.4.3-SNAPSHOT]
INFO  [2015-07-14 10:30:17,357] org.eclipse.jetty.server.ServerConnector: Stopped SingularityService@12f8b1d8{HTTP/1.1}{0.0.0.0:7099}
INFO  [2015-07-14 10:30:17,358] org.eclipse.jetty.server.handler.ContextHandler: Stopped i.d.j.MutableServletContextHandler@408e96d9{/admin,null,UNAVAILABLE}
INFO  [2015-07-14 10:30:17,359] org.eclipse.jetty.server.handler.ContextHandler: Stopped i.d.j.MutableServletContextHandler@54f4a7f0{/,null,UNAVAILABLE}
INFO  [2015-07-14 10:30:17,378] org.apache.zookeeper.ClientCnxn: EventThread shut down
INFO  [2015-07-14 10:30:17,378] org.apache.zookeeper.ZooKeeper: Session: 0x24e8b9313780002 closed

The three hour gap is until an administrator was paged and came in to restart manually.

Two issues here:

• What is this IAE about the path being invalid?
• Why didn't a ZK exception cause Singularity to abort?

This is a slightly patched (in a way that shouldn't possibly be relevant, just the PRs I have that are not merged yet) 0.4.3-SNAPSHOT as of a week ago.

[wsorenson]

That sucks, I wonder if this is related to a curator upgrade (you'd think the leader latch would be getting more stable over time, not less..?)

Just clarifying: once restarted it worked? Also, did this happen on startup after an upgrade (or during an upgrade?)

Can you report the exact version of Apache Curator?

[stevenschlansker]

You'd think! Here's the branch in case it's interesting: https://github.com/stevenschlansker/Singularity/commits/jul-2015-fixes
Looks like we are running Curator 2.4.2

Restarting Singularity by hand fixed the problem. This happened on startup immediately after an abort:

INFO  [2015-07-14 07:58:49,405] com.hubspot.singularity.mesos.SingularityMesosScheduler: Finished handling 4 offer(s) (00:00.009), 0 accepted, 4 declined, 0 outstanding tasks
2015-07-14 07:58:59,462:17532(0x7fb4262be700):ZOO_ERROR@handle_socket_error_msg@1643: Socket [10.20.16.234:2181] zk retcode=-7, errno=110(Connection timed out): connection to 10.20.16.234:2181 timed out (exceeded timeout by 3ms)
2015-07-14 07:58:59,462:17532(0x7fb4262be700):ZOO_INFO@check_events@1703: initiated connection to server [10.20.16.235:2181]
I0714 07:58:59.462713 17563 group.cpp:418] Lost connection to ZooKeeper, attempting to reconnect ...
2015-07-14 07:58:59,464:17532(0x7fb4262be700):ZOO_INFO@check_events@1750: session establishment complete on server [10.20.16.235:2181], sessionId=0x14e4df27b0c000a, negotiated timeout=10000
I0714 07:58:59.464948 17565 group.cpp:313] Group process (group(1)@10.20.16.252:42157) reconnected to ZooKeeper
I0714 07:58:59.465001 17565 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
2015-07-14 07:58:59,773:17532(0x7fb4262be700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [10.20.16.235:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
2015-07-14 07:58:59,773:17532(0x7fb4262be700):ZOO_INFO@check_events@1703: initiated connection to server [10.20.16.252:2181]
I0714 07:58:59.773811 17567 group.cpp:418] Lost connection to ZooKeeper, attempting to reconnect ...
2015-07-14 07:58:59,774:17532(0x7fb4262be700):ZOO_INFO@check_events@1750: session establishment complete on server [10.20.16.252:2181], sessionId=0x14e4df27b0c000a, negotiated timeout=10000
I0714 07:58:59.774618 17562 group.cpp:313] Group process (group(1)@10.20.16.252:42157) reconnected to ZooKeeper
I0714 07:58:59.774649 17562 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
INFO  [2015-07-14 07:58:59,772] org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x24e4df27f9c0003, likely server has closed socket, closing socket connection and attempting reconnect
I0714 07:58:59.878298 17579 sched.cpp:1623] Asked to abort the driver
I0714 07:58:59.878437 17565 sched.cpp:856] Aborting framework 'Singularity'
INFO  [2015-07-14 07:58:59,876] org.apache.curator.framework.state.ConnectionStateManager: State change: SUSPENDED
INFO  [2015-07-14 07:58:59,877] com.hubspot.singularity.SingularityLeaderController: We are not the leader! Current status DRIVER_RUNNING
INFO  [2015-07-14 07:58:59,877] com.hubspot.singularity.mesos.SingularityDriver: Notifying scheduler about impending driver abort
INFO  [2015-07-14 07:58:59,877] com.hubspot.singularity.mesos.SingularityMesosSchedulerDelegator: Scheduler is moving to stopped, current state: RUNNING
INFO  [2015-07-14 07:58:59,877] com.hubspot.singularity.mesos.SingularityMesosSchedulerDelegator: Scheduler now in state: STOPPED
INFO  [2015-07-14 07:58:59,877] com.hubspot.singularity.mesos.SingularityDriver: Calling driver.abort() ...
INFO  [2015-07-14 07:58:59,878] com.hubspot.singularity.mesos.SingularityDriver: Aborted with status: DRIVER_ABORTED
ERROR [2015-07-14 07:58:59,878] com.hubspot.singularity.SingularityAbort: Singularity on mesos3-prod-sc is aborting due to LOST_LEADERSHIP
DEBUG [2015-07-14 07:58:59,884] com.hubspot.singularity.smtp.SingularitySmtpSender: Queuing an email to [platform-alert@opentable.com]/[] (subject: Singularity on mesos3-prod-sc is aborting due to LOST_LEADERSHIP)
INFO  [2015-07-14 07:58:59,884] com.hubspot.singularity.SingularityAbort: Attempting to flush logs and wait 00:00.100 ...
2015-07-14 07:59:00,772:17532(0x7fb4262be700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [10.20.16.252:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
I0714 07:59:00.772366 17566 group.cpp:418] Lost connection to ZooKeeper, attempting to reconnect ...
2015-07-14 07:59:04,108:17532(0x7fb4262be700):ZOO_WARN@zookeeper_interest@1557: Exceeded deadline by 1001ms
2015-07-14 07:59:04,109:17532(0x7fb4262be700):ZOO_INFO@check_events@1703: initiated connection to server [10.20.16.234:2181]
2015-07-14 07:59:08,069:17532(0x7fb4262be700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [10.20.16.234:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
2015-07-14 07:59:08,069:17532(0x7fb4262be700):ZOO_INFO@check_events@1703: initiated connection to server [10.20.16.235:2181]
2015-07-14 07:59:08,070:17532(0x7fb4262be700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [10.20.16.235:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
2015-07-14 07:59:08,070:17532(0x7fb4262be700):ZOO_INFO@check_events@1703: initiated connection to server [10.20.16.252:2181]
2015-07-14 07:59:08,070:17532(0x7fb4262be700):ZOO_ERROR@handle_socket_error_msg@1721: Socket [10.20.16.252:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
INFO  [2015-07-14 07:59:09,854] io.dropwizard.assets.AssetsBundle: Registering AssetBundle with name: assets for path /static/*
INFO  [2015-07-14 07:59:09,884] io.dropwizard.assets.AssetsBundle: Registering AssetBundle with name: api-docs for path /api-docs/*
...
INFO  [2015-07-14 07:59:11,423] io.dropwizard.server.ServerFactory: Starting SingularityService
INFO  [2015-07-14 07:59:11,485] org.eclipse.jetty.setuid.SetUIDListener: Opened SingularityService@12f8b1d8{HTTP/1.1}{0.0.0.0:7099}

[stevenschlansker]

Happened again, another minor production incident, this time woke up two of our on-calls at 4am 😞

We are now running master from about 1 week ago.

INFO  [2015-08-12 10:28:31,041] org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x34f0248b2340008, likely server has closed socket, closing socket connection and attempting reconnect
INFO  [2015-08-12 10:28:31,144] org.apache.curator.framework.state.ConnectionStateManager: State change: SUSPENDED
INFO  [2015-08-12 10:28:31,487] org.apache.zookeeper.ClientCnxn: Opening socket connection to server mesos2-prod-sc.otsql.opentable.com/10.20.16.235:2181. Will not attempt to authenticate using SASL (unknown error)
INFO  [2015-08-12 10:28:31,488] org.apache.zookeeper.ClientCnxn: Socket connection established to mesos2-prod-sc.otsql.opentable.com/10.20.16.235:2181, initiating session
INFO  [2015-08-12 10:28:31,675] org.apache.zookeeper.ClientCnxn: Session establishment complete on server mesos2-prod-sc.otsql.opentable.com/10.20.16.235:2181, sessionid = 0x34f0248b2340008, negotiated timeout = 40000
INFO  [2015-08-12 10:28:31,676] org.apache.curator.framework.state.ConnectionStateManager: State change: RECONNECTED
INFO  [2015-08-12 10:28:31,718] org.apache.zookeeper.ClientCnxn: Unable to read additional data from server sessionid 0x34f0248b2340008, likely server has closed socket, closing socket connection and attempting reconnect
INFO  [2015-08-12 10:28:31,818] org.apache.curator.framework.state.ConnectionStateManager: State change: SUSPENDED
INFO  [2015-08-12 10:28:32,794] org.apache.zookeeper.ClientCnxn: Opening socket connection to server mesos1-prod-sc.otsql.opentable.com/10.20.16.234:2181. Will not attempt to authenticate using SASL (unknown error)
INFO  [2015-08-12 10:28:32,795] org.apache.zookeeper.ClientCnxn: Socket connection established to mesos1-prod-sc.otsql.opentable.com/10.20.16.234:2181, initiating session
INFO  [2015-08-12 10:28:32,797] org.apache.zookeeper.ClientCnxn: Session establishment complete on server mesos1-prod-sc.otsql.opentable.com/10.20.16.234:2181, sessionid = 0x34f0248b2340008, negotiated timeout = 40000
INFO  [2015-08-12 10:28:32,797] org.apache.curator.framework.state.ConnectionStateManager: State change: RECONNECTED
ERROR [2015-08-12 10:28:33,828] org.apache.curator.framework.imps.CuratorFrameworkImpl: Background exception was not retry-able or retry gave up
! java.lang.IllegalArgumentException: Path must start with / character
! at org.apache.curator.utils.PathUtils.validatePath(PathUtils.java:54) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.utils.ZKPaths.getNodeFromPath(ZKPaths.java:80) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.recipes.leader.LeaderLatch.checkLeadership(LeaderLatch.java:526) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.recipes.leader.LeaderLatch.access$700(LeaderLatch.java:63) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.recipes.leader.LeaderLatch$7.processResult(LeaderLatch.java:584) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.imps.CuratorFrameworkImpl.sendToBackgroundCallback(CuratorFrameworkImpl.java:728) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:505) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.imps.GetChildrenBuilderImpl$2.processResult(GetChildrenBuilderImpl.java:166) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:590) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
ERROR [2015-08-12 10:29:14,006] org.apache.curator.framework.imps.CuratorFrameworkImpl: Background exception was not retry-able or retry gave up
! java.lang.IllegalArgumentException: Path must start with / character
! at org.apache.curator.utils.PathUtils.validatePath(PathUtils.java:54) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.utils.ZKPaths.getNodeFromPath(ZKPaths.java:80) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.recipes.leader.LeaderLatch.checkLeadership(LeaderLatch.java:526) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.recipes.leader.LeaderLatch.access$700(LeaderLatch.java:63) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.recipes.leader.LeaderLatch$7.processResult(LeaderLatch.java:584) ~[singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.imps.CuratorFrameworkImpl.sendToBackgroundCallback(CuratorFrameworkImpl.java:728) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.imps.CuratorFrameworkImpl.processBackgroundOperation(CuratorFrameworkImpl.java:505) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.curator.framework.imps.GetChildrenBuilderImpl$2.processResult(GetChildrenBuilderImpl.java:166) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:590) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
! at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498) [singularity-20150803-1.jar:0.4.3-SNAPSHOT]
INFO  [2015-08-12 12:09:21,829] io.dropwizard.assets.AssetsBundle: Registering AssetBundle with name: assets for path /static/*
INFO  [2015-08-12 12:09:21,872] io.dropwizard.assets.AssetsBundle: Registering AssetBundle with name: api-docs for path /api-docs/*

[stevenschlansker]

Looking at the traces, one clue may be that it seems to happen immediately after the ZK client does a disconnect / reconnect cycle.

[wsorenson]

We'll take a look. It would be nice to reproduce consistently to find the issue in curator, the suspend / reconnect cycle is a good hint - (I wonder why you get so many ZK connection issues?)

One easy solution would be to just abort on SUSPEND instead of attempting to the handle the reconnect case.

[ssalinas]

Looks like this could be related to this bug https://issues.apache.org/jira/browse/CURATOR-168

Going to try reproducing it locally, but best guess right now is that bumping curator versions will square it away. Looks to be solved in 2.8.0

[stevenschlansker]

I was just looking down that exact code path and thinking very similarly. I'd be +1 to upgrading Curator for the next release, any objection?

[ssalinas]

Agreed, I'll open a PR to bump the version, running fine locally with 2.8.0 so far.

[wsorenson]

We also plan to address the fact that if we receive this sort of error we shouldn't hang.

[ssalinas]

After digging some more on the curator code, looks like this exception will never bubble up. In here the whole thing is wrapped in a try catch that just logs the error for the event and keeps going.

We might have to go towards the option of aborting on a SUSPEND if the error never actually bubbles up where we can see/use it. thoughts?

[wsorenson]

I guess we could be abundantly cautious and add some sort of thread or state checker that looks for connectivity to ZK / Mesos and if it goes too long without it, aborts.

[ssalinas]

@stevenschlansker have you guys seen this again since the curator upgrade? We haven't on our side. Wondering if we can close this or if we need to go down the path of implementing an abort on SUSPEND status (or something else to manage that issue)

[stevenschlansker]

We haven't seen this in a very long time.