Marathon: Marathon leaders suicide loop

[jonasekl]

We are having issues with our setup - our marathon cluster of 3 leaders keeps suiciding: [2016-08-25 20:39:48,829] ERROR Committing suicide! (mesosphere.marathon.MarathonScheduler$$EnhancerByGuice$$9ccfcc15:Thread-1072)

This seems to happen during reconciliation. The leader suicides, then another takes over.. . then after one "reconciliation_initial_delay" period, THAT master suicides as well. Sometimes the next leader does the exact same thing.

This is on 1.1.2 running on mesos 1.0.0. on CentOS Linux release 7.2.1511 (Core) and happens on both our old cluster which had been upgraded from earlier versions, and on a completely freshly installed cluster and unfortunately that is the only ERROR level message in the logs within a few minutes of the suicides.

When this happens ZK as well as mesos do not perform an election, thus seems to be a pure marathon issue.

Not sure what more information is appropriate, please let me know if I should include any other logs or other information about or setup. Any help is very much appreciated.

[jeschkies]

Could you give the logs before the error?

[jonasekl]

@jeschkies

Here is a subset of marathon.log. Please let me know if I should include any other logs.

Really appreciate your help.

marathon.log.tar.gz

[dmcwhorter]

seeing a similar issue, here's a snip from the logs (very similar every time this happens):

Aug 31 03:58:37 master2 marathon[3547]: I0831 03:58:37.990578 10865 sched.cpp:1171] Got error 'Framework disconnected'
Aug 31 03:58:37 master2 marathon[3547]: I0831 03:58:37.990700 10865 sched.cpp:2021] Asked to abort the driver
Aug 31 03:58:37 master2 marathon[3547]: [2016-08-31 03:58:37,993] WARN Error: Framework disconnected
Aug 31 03:58:37 master2 marathon[3547]: In case Mesos does not allow registration with the current frameworkId, delete the ZooKeeper Node: /marathon/state/framework:id
Aug 31 03:58:37 master2 marathon[3547]: CAUTION: if you remove this node, all tasks started with the current frameworkId will be orphaned! (mesosphere.marathon.MarathonSchedul
er$$EnhancerByGuice$$1db3a4f:Thread-1403)
Aug 31 03:58:37 master2 marathon[3547]: [2016-08-31 03:58:37,994] ERROR Committing suicide! (mesosphere.marathon.MarathonScheduler$$EnhancerByGuice$$1db3a4f:Thread-1403)
Aug 31 03:58:37 master2 marathon[3547]: I0831 03:58:37.999199 10865 sched.cpp:1217] Aborting framework '2b72e452-d86a-4fa0-9f4f-c6c87e4d4493-0000'
Aug 31 03:58:38 master2 marathon[3547]: [2016-08-31 03:58:38,001] INFO Shutting down actor system akka://marathon (mesosphere.marathon.core.base.ActorsModule:Thread-3)
Aug 31 03:58:38 master2 marathon[3547]: [2016-08-31 03:58:38,006] INFO Driver future completed with result=Success(()). (mesosphere.marathon.MarathonSchedulerService$$Enhancer
ByGuice$$afc91711:ForkJoinPool-2-worker-11)
Aug 31 03:58:38 master2 marathon[3547]: [2016-08-31 03:58:38,007] INFO Shutting down services (mesosphere.marathon.Main$:shutdownHook1)
Aug 31 03:58:38 master2 marathon[3547]: [2016-08-31 03:58:38,007] INFO Abdicating leadership while leading (reoffer=true) (mesosphere.marathon.core.election.impl.CuratorElecti
onService:ForkJoinPool-2-worker-11)
Aug 31 03:58:38 master2 marathon[3547]: [2016-08-31 03:58:38,010] INFO Defeated (LeaderLatchListener Interface). New leader: - (mesosphere.marathon.core.election.impl.CuratorE
lectionService:ForkJoinPool-2-worker-11)
Aug 31 03:58:38 master2 marathon[3547]: I0831 03:58:38.067185  3684 sched.cpp:1987] Asked to stop the driver
Aug 31 03:58:38 master2 marathon[3547]: I0831 03:58:38.067291 10866 sched.cpp:1187] Stopping framework '2b72e452-d86a-4fa0-9f4f-c6c87e4d4493-0000'

[dmcwhorter]

Also FYI we've seen this issue with 1.2.0-RC8 and 1.3.0-RC5

[jeschkies]

@dmcwhorter Did you try to remove the ZooKeeper node like the logs say?

[dmcwhorter]

@jeschkies I have not tried that. Since this has happened on multiple times on multiple clusters, my assumption has been that there is some kind of issue in marathon causing this to happen rather than an isolated issue. I will try it however to see if it makes any difference, that would at least be a useful data point I'm sure.

[dmcwhorter]

Actually, reading again, I was scared off by this warning:

CAUTION: if you remove this node, all tasks started with the current frameworkId will be orphaned!

I believe something has gone wrong already if I'm having to do this? Wouldn't this cause marathon to restart under a new framework ID? We have a bunch of processes running which I did not want marathon to lose control over...

[jonasekl]

Same goes for me, have not removed the zookeeper node.

[nsg]

_Note, I work with the same Marathon installation as @jonasekl_

By the look of it, it looks like something in @dmcwhorter ZK cluster has been corrupt. I wished that our problem that @jonasekl described had any information like that.

Same goes for me, have not removed the zookeeper node.

Considered that we built a completely new cluster from 0, new VM:s, new ZK installation, new Mesos installation and new Marathon. I think we can consider our ZK nodes quite removed :) We did not export/import any data, everything was recreated from scratch because we did consider the possibility of corrupt data.

We have suicides several times each hour, any recommendation on how to debug this properly? Note that this seems to happen when we removes or add a new application to Marathon (we do that a lot). Everything worked fine before 1.x

[dmcwhorter]

We also have run clean installs on 2 different clusters using 1.x+ and seen the same behavior. No other process using ZK has had issues. So it seems that if the issue is the data in ZK, something has corrupted ZK on both clusters in the same way that only affects marathon. Which leads me to think it could be a problem with marathon itself...

[dmcwhorter]

Another important note: our crashes are much less frequent, ~ once a day, and only the secondary nodes crash, not the primary.

[taotetek]

Hello! This looks like the issue we are running into as well. As our mesos cluster is not in production yet if there's anything we can do to help test please feel free to let me know. We can also provide logs around these occurrences is that would be helpful.

[jasongilanfarr]

We are currently _extremely_ aggressive in committing suicide - if marathon _ever_ looses the connection to ZK, it will commit suicide. We definitely need to make this a lot more robust. You may want to consider increasing "zk_session_timeout" beyond 10 seconds, but this won't help if marathon does lose the connection,.

[nsg]

@jasongilanfarr Thank you for the information, "extremely aggressive" do indeed sounds, aggressive :)

Would it be considered bad practice to configure marathon to only use the local zk node at localhost? At the moment we are specifying all the zk masters. Some type of network anomaly is not completely unrealistic.

Is the 1.x release more aggressive compared the old 0.x releases? Considering that our problems started when upgrading to the stable 1.x release.

I will give it a try in our staging environment on Monday, at least that would rule out the network (from the point of view of marathon). zk_session_timeout also sounds like something to try but 10s is already a long time and I think the connection is dropped, so it will probably not work.

[bydga]

We are expriencing the same behavior.. mesos 1.0.0, marathon 1.1.1, during (after) reconciliation - theres milion lines in the log like:

2016-09-19T10:38:33.056837+00:00 mesos-master2 marathon[20105]: [2016-09-19 10:38:33,056] INFO Received status update for task xxx.d60dc5aa-6dba-11e6-a48b-024277d21a81: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler$$EnhancerByGuice$$b1753258:Thread-2095)
2016-09-19T10:38:33.056979+00:00 mesos-master2 marathon[20105]: [2016-09-19 10:38:33,056] INFO Received status update for task yyy.625e36c5-78c9-11e6-90cb-069201a06507: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler$$EnhancerByGuice$$b1753258:Thread-2096)

and then marathon dies:

2016-09-19T09:47:27.492089+00:00 mesos-master2 marathon[14634]: [2016-09-19 09:47:27,491] WARN Error: Framework disconnected
2016-09-19T09:47:27.492092+00:00 mesos-master2 marathon[14634]: In case Mesos does not allow registration with the current frameworkId, delete the ZooKeeper Node: /marathon/state/framework:id
2016-09-19T09:47:27.492095+00:00 mesos-master2 marathon[14634]: CAUTION: if you remove this node, all tasks started with the current frameworkId will be orphaned! (mesosphere.marathon.MarathonScheduler$$EnhancerByGuice$$b1753258:Thread-1566)
2016-09-19T09:47:27.492099+00:00 mesos-master2 marathon[14634]: [2016-09-19 09:47:27,491] ERROR Committing suicide! (mesosphere.marathon.MarathonScheduler$$EnhancerByGuice$$b1753258:Thread-1566)
2016-09-19T09:47:27.492243+00:00 mesos-master2 marathon[14634]: I0919 09:47:27.492220 14738 sched.cpp:1217] Aborting framework '20160106-083626-1258962954-5050-9311-0000'
2016-09-19T09:47:27.492508+00:00 mesos-master2 marathon[14634]: [2016-09-19 09:47:27,492] INFO Driver future completed. Executing optional abdication command. (mesosphere.marathon.MarathonSchedulerService$$EnhancerByGuice$$ef2ab073:ForkJoinPool-2-worker-7)
2016-09-19T09:47:27.532470+00:00 mesos-master2 marathon[14634]: [2016-09-19 09:47:27,532] INFO Will offer leadership after 500 milliseconds backoff (mesosphere.marathon.MarathonSchedulerService$$EnhancerByGuice$$ef2ab073:ForkJoinPool-2-worker-7)
2016-09-19T09:47:27.532778+00:00 mesos-master2 marathon[14634]: [2016-09-19 09:47:27,532] INFO Defeated (Leader Interface) (mesosphere.marathon.MarathonSchedulerService$$EnhancerByGuice$$ef2ab073:main-EventThread)
2016-09-19T09:47:27.532806+00:00 mesos-master2 marathon[14634]: [2016-09-19 09:47:27,532] INFO Call onDefeated leadership callbacks on EntityStoreCache(MarathonStore(app:)), EntityStoreCache(MarathonStore(group:)), EntityStoreCache(MarathonStore(deployment:)), EntityStoreCache(MarathonStore(framework:)), EntityStoreCache(MarathonStore(taskFailure:)), EntityStoreCache(MarathonStore(events:)) (mesosphere.marathon.MarathonSchedulerService$$EnhancerByGuice$$ef2ab073:main-EventThread)

[nsg]

We have been running with only the localhost zk configured for a few days, still several suicides each hour.
I'm happy to debug and track this problem down, if anyone has any pointers of where to start looking.

Will try with 1.3.0 when https://github.com/mesosphere/marathon/issues/4391 is fixed.

[alahiff]

I also recently started seeing this problem with Marathon 1.3.0-RC7 and Mesos 1.0.0. After upgrading Marathon to 1.3.0 the problem didn't go away. I've just tried restarting Marathon using a new ZooKeeper node and redeployed all my apps in order to see if this helps.

[taotetek]

Just a follow up - since we moved to our production HA marathon setup with marathon 1.3, we have stopped experiencing this issue. Will report back if it happens again.

[alahiff]

After deleting the Marathon zk node things were fine until yesterday where there were 2 instances of the issue (framework disconnected during reconciliation) and 1 so far today.

[christianparpart]

@alahiff did you lose any running apps by removing that zk node? I fear losing all of our 100+ apps we spawned in there.

[christianparpart]

Actualy, I keep getting this message (and thus suicides and reelections), and I found this in the mesos-master.INFO log file:

W1007 15:44:54.081941 12830 master.hpp:2113] Master attempted to send message to disconnected framework 965aaa4a-cc50-4a75-af4b-ea02e3ea824b-0000 (marathon) at [email protected]:38447

The odd thing is, while the IP address is right, it's definitely the wrong port. Seems like Mesos frameworks (such as Marathon) also listen on a special talk-back IP:port for the mesos master to communicate to it. Why could the port be wrong, and how can I correct that?

[alahiff]

@christianparpart All running apps were lost - in my case this was ok and I was able to use a script to recreate all the running apps fairly quickly.

BTW I've had the same Marathon leader for 4 days now.

[jindraj]

@christianparpart the IP:port that you see in the log message is the other side of the connection. It is from where it was initiated.
Marathon initiated connection to mesos-master from that IP:port mentioned in the log message. Then mesos-master attemted to send send some message to Marathon, but the socket hasn't existed anymore. Because Marathon probably died.

[nsg]

We have spent a lot of time improving the network latency and variance over the last weeks, but unfortunately this has not reduced the suicides. Marathon only talk with the localhost ZK, and 1.3.0 made no difference.

The graph shows suicides/hour, so still quite bad :) We have tweaked the settings to that it's impossible for marathon to suicide all 3 masters before the first one has had time to start again.

[aquamatthias]

@jmlvanre I see "WARN Error: Framework disconnected"
Can you please look into this?

[alangibson]

Exact same problem here on a clean installation of Marathon 1.3.2 + Mesos 1.0.0 + Zookeeper 3.4.8. The hosts are connected via private 10 gig switch, so I don't think the network can be blamed.

marathon-log.txt

All Zookeeper logs have the following lines repeated endlessly:

2016-10-11 09:12:27,896 [myid:1] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@192] - Accepted socket connection from /10.10.10.124:31355
2016-10-11 09:12:27,897 [myid:1] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@873] - Refusing session request for client /10.10.10.124:31355 as it has seen zxid 0x10000006e our last zxid is 0x100000038 client must try another server
2016-10-11 09:12:27,897 [myid:1] - INFO  [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1008] - Closed socket connection for client /10.10.10.124:31355 (no session established for client)

So it looks like the Marathon logs are right; Zookeeper is indeed closing the connection. So I guess the real question is: why has Marathon 'seen zxid 0x10000006e' when all the Zookeeper nodes agree that ' last zxid is 0x100000038'.

This ancient, unresolved bug is possibly related:

https://issues.apache.org/jira/browse/ZOOKEEPER-832

EDIT: more logs
EDIT: Zookeeper logs
EDIT: JIRA ticket

[aquamatthias]

@alangibson Thanks for providing the logs. The problem you are running into is related to ZK. Marathon as well as the Mesos Driver have a connection to ZK. They report:

ZOO_ERROR@handle_socket_error_msg@1746: Socket [10.10.10.126:2181] zk retcode=-4, errno=112(Host is down): failed while receiving a server response
Lost connection to ZooKeeper, attempting to reconnect ...

So it looks like a ZK connection problem.

The original problem of this ticket (which still could have the same root cause): the mesos driver signals an error to Marathon. Marathon will react with abdication in this case.
So @dmcwhorter and @jonasekl I would like to see the Mesos logs at the time we see this error.
Can you provide those?

Also: If you could start Marathon with export GLOG_v=1 then we get more details for the Mesos scheduler driver.

[alangibson]

I just spent a couple of hours verifying our Zookeeper configuration. We are running Zookeeper in Docker, and so we were not keeping the Zookeeper log on its own device like the docs recommend. I created a new storage device and used Docker's volume feature to store the log there. Since that change, I've successfully redeployed our entire stack 3 times.

[jmlvanre]

If you are seeing this issue on Mesos 1.0.0 please upgrade to Mesos 1.0.1.
The Framework Disconnected issue was being generated due to this Mesos bug:
https://issues.apache.org/jira/browse/MESOS-5943

The connection was corrupted due to the bug which led mesos to think the connection was experiencing a 1 way partition.

Your Mesos cluster needs to be 1.0.1+, and the libmesos that your marathon links against also needs to be 1.0.1. This means that if you are running a docker image with marathon it needs to get updated.

Please do report any further issues if you are running 1.0.1 or above so we can triage accordingly.