Marathon: Marathon "recovering deployments", killing all tasks of some apps

[EvanKrall]

At Yelp, we've had a number of incidents since we upgraded to 0.15.3 where Marathon has killed all instances of an app.

Something (it's not clear what; possibly the traceback in the log snippet below?) appears to be triggering the MarathonSchedulerActor to restart, which "recovers" deployments. During the recovery of those deployments, Marathon first Starts the app, which sets instances = 0; then later Scales the app to the desired number. Since the app already existed, the Start action actually _kills_ the running tasks.

This appears to hit both applications that were created recently and have been deployed for some time.

Here's some snippets of logs from a particular app that had this problem. The first timestamp on the line is when syslog received the line, and is in UTC; the second timestamp is from Marathon and is PDT.

First, the app gets deployed initially.

2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,167] INFO [/servicename.shard--4.git378c7549.configcbe6b7a5]: new app detected (mesosphere.marathon.upgrade.GroupVersioningUtil$:ForkJoinPool-2-worker-269)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,193] INFO Computed new deployment plan:
2016-04-13T17:06:31+00:00 DeploymentPlan 2016-04-13T17:06:31.160Z
2016-04-13T17:06:31+00:00 step 1:
2016-04-13T17:06:31+00:00   * Start(App(/servicename.shard--4.git378c7549.configcbe6b7a5, image="docker-paasta.yelpcorp.com:443/services-servicename:paasta-378c754959731a4c8799c58a9169d6d385151adc")), instances=0)
2016-04-13T17:06:31+00:00 step 2:
2016-04-13T17:06:31+00:00   * Scale(App(/servicename.shard--4.git378c7549.configcbe6b7a5, image="docker-paasta.yelpcorp.com:443/services-servicename:paasta-378c754959731a4c8799c58a9169d6d385151adc")), instances=5)
2016-04-13T17:06:31+00:00  (mesosphere.marathon.state.GroupManager:ForkJoinPool-2-worker-269)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,193] INFO Deploy plan with force=false:
2016-04-13T17:06:31+00:00 DeploymentPlan 2016-04-13T17:06:31.160Z
2016-04-13T17:06:31+00:00 step 1:
2016-04-13T17:06:31+00:00   * Start(App(/servicename.shard--4.git378c7549.configcbe6b7a5, image="docker-paasta.yelpcorp.com:443/services-servicename:paasta-378c754959731a4c8799c58a9169d6d385151adc")), instances=0)
2016-04-13T17:06:31+00:00 step 2:
2016-04-13T17:06:31+00:00   * Scale(App(/servicename.shard--4.git378c7549.configcbe6b7a5, image="docker-paasta.yelpcorp.com:443/services-servicename:paasta-378c754959731a4c8799c58a9169d6d385151adc")), instances=5)
2016-04-13T17:06:31+00:00   (mesosphere.marathon.MarathonSchedulerService$$EnhancerByGuice$$6617eef1:ForkJoinPool-2-worker-269)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,193] INFO [/servicename.shard--4.git378c7549.configcbe6b7a5] storing new app version 2016-04-13T17:06:31.160Z (mesosphere.marathon.state.GroupManager:ForkJoinPool-2-worker-269)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,281] WARN Using deprecated embed=sapps.failures. Use apps.tasks, apps.lastTaskFailure, apps.deployments instead. (mesosphere.marathon.api.v2.AppInfoEmbedResolver$:qtp452817647-80935)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,291] INFO Updated groups/apps according to deployment plan f57ff185-0498-433f-a60a-0014ef8588c3 (mesosphere.marathon.state.GroupManager:ForkJoinPool-2-worker-265)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,291] INFO Deployment acknowledged. Waiting to get processed:
2016-04-13T17:06:31+00:00 DeploymentPlan 2016-04-13T17:06:31.160Z
2016-04-13T17:06:31+00:00 step 1:
2016-04-13T17:06:31+00:00   * Start(App(/servicename.shard--4.git378c7549.configcbe6b7a5, image="docker-paasta.yelpcorp.com:443/services-servicename:paasta-378c754959731a4c8799c58a9169d6d385151adc")), instances=0)
2016-04-13T17:06:31+00:00 step 2:
2016-04-13T17:06:31+00:00   * Scale(App(/servicename.shard--4.git378c7549.configcbe6b7a5, image="docker-paasta.yelpcorp.com:443/services-servicename:paasta-378c754959731a4c8799c58a9169d6d385151adc")), instances=5)
2016-04-13T17:06:31+00:00  (mesosphere.marathon.state.GroupManager:ForkJoinPool-2-worker-265)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,349] INFO Starting health check actor for app [/servicename.shard--4.git378c7549.configcbe6b7a5] version [2016-04-13T17:06:31.160Z] and healthCheck [HealthCheck(Some(/status/version),HTTP,Some(0),None,21600 seconds,10 seconds,10 seconds,30,false,None)] (mesosphere.marathon.health.Heal
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,350] INFO Starting app /servicename.shard--4.git378c7549.configcbe6b7a5 (mesosphere.marathon.SchedulerActions:marathon-akka.actor.default-dispatcher-266)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,350] INFO Already running 0 instances of /servicename.shard--4.git378c7549.configcbe6b7a5. Not scaling. (mesosphere.marathon.SchedulerActions:marathon-akka.actor.default-dispatcher-266)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,350] INFO Successfully started 0 instances of /servicename.shard--4.git378c7549.configcbe6b7a5 (mesosphere.marathon.upgrade.AppStartActor:marathon-akka.actor.default-dispatcher-233)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,351] INFO Started appTaskLaunchActor for /servicename.shard--4.git378c7549.configcbe6b7a5 version 2016-04-13T17:06:31.160Z with initial count 5 (mesosphere.marathon.core.launchqueue.impl.AppTaskLauncherActor:marathon-akka.actor.default-dispatcher-235)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,352] INFO activating matcher ActorOfferMatcher(Actor[akka://marathon/user/launchQueue/1/120-servicename.shard--4.git378c7549.configcbe6b7a5#2045163658]). (mesosphere.marathon.core.matcher.manager.impl.OfferMatcherManagerActor:marathon-akka.actor.default-dispatcher-266)
2016-04-13T17:06:31+00:00 [2016-04-13 10:06:31,349] INFO Adding health check for app [/servicename.shard--4.git378c7549.configcbe6b7a5] and version [2016-04-13T17:06:31.160Z]: [HealthCheck(Some(/status/version),HTTP,Some(0),None,21600 seconds,10 seconds,10 seconds,30,false,None)] (mesosphere.marathon.health.MarathonHealthCheckMana

About 90 minutes later, the trouble starts.

Marathon issues a reconcile for this app (and many others at the same time).

2016-04-13T18:25:20+00:00 [2016-04-13 11:25:20,506] INFO reconcile [/servicename.shard--4.git378c7549.configcbe6b7a5] with latest version [2016-04-13T17:06:31.160Z] (mesosphere.marathon.health.MarathonHealthCheckManager$$EnhancerByGuice$$cfe9b5cd:ForkJoinPool-2-worker-305)

This traceback shows up in the logs:

2016-04-13T18:25:20+00:00 java.util.concurrent.TimeoutException: Futures timed out after [1000 milliseconds]
2016-04-13T18:25:20+00:00   at scala.concurrent.impl.Promise$DefaultPromise.result(Promise.scala:223) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at scala.concurrent.Await$$anonfun$result$1.apply(package.scala:190) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread$$anon$3.block(ThreadPoolBuilder.scala:169) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at scala.concurrent.forkjoin.ForkJoinPool.managedBlock(ForkJoinPool.java:3640) [marathon:0.15.3]
2016-04-13T18:25:20+00:00   at akka.dispatch.MonitorableThreadFactory$AkkaForkJoinWorkerThread.blockOn(ThreadPoolBuilder.scala:167) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at scala.concurrent.Await$.result(package.scala:190) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at mesosphere.marathon.core.launchqueue.impl.LaunchQueueDelegate.askQueueActor(LaunchQueueDelegate.scala:41) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at mesosphere.marathon.core.launchqueue.impl.LaunchQueueDelegate.purge(LaunchQueueDelegate.scala:36) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at mesosphere.marathon.MarathonSchedulerActor$$anonfun$deploymentFailed$1.apply(MarathonSchedulerActor.scala:317) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at mesosphere.marathon.MarathonSchedulerActor$$anonfun$deploymentFailed$1.apply(MarathonSchedulerActor.scala:317) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at scala.collection.immutable.Set$Set1.foreach(Set.scala:79) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at mesosphere.marathon.MarathonSchedulerActor.deploymentFailed(MarathonSchedulerActor.scala:317) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at mesosphere.marathon.MarathonSchedulerActor$$anonfun$sharedHandlers$1.applyOrElse(MarathonSchedulerActor.scala:183) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:170) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at akka.actor.Actor$class.aroundReceive(Actor.scala:465) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at mesosphere.marathon.MarathonSchedulerActor.aroundReceive(MarathonSchedulerActor.scala:35) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at akka.actor.ActorCell.receiveMessage(ActorCell.scala:516) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at akka.actor.ActorCell.invoke(ActorCell.scala:487) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:254) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at akka.dispatch.Mailbox.run(Mailbox.scala:221) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at akka.dispatch.Mailbox.exec(Mailbox.scala:231) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339) ~[marathon:0.15.3]
2016-04-13T18:25:20+00:00   at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107) [marathon:0.15.3]
2016-04-13T18:25:20+00:00   at scala.concurrent.impl.Promise$DefaultPromise.ready(Promise.scala:219) ~[marathon:0.15.3]

Then the MarathonSchedulerActor restarts:

2016-04-13T18:25:20+00:00 [2016-04-13 11:25:20,522] INFO Starting scheduler actor (mesosphere.marathon.MarathonSchedulerActor:marathon-akka.actor.default-dispatcher-344)

This triggers a recovery of all deployments:

2016-04-13T18:25:20+00:00 [2016-04-13 11:25:20,522] INFO Recovering deployment:
2016-04-13T18:25:20+00:00 DeploymentPlan 2016-04-13T17:06:31.160Z
2016-04-13T18:25:20+00:00 step 1:
2016-04-13T18:25:20+00:00   * Start(App(/servicename.shard--4.git378c7549.configcbe6b7a5, image="docker-paasta.yelpcorp.com:443/services-servicename:paasta-378c754959731a4c8799c58a9169d6d385151adc")), instances=0)
2016-04-13T18:25:20+00:00 step 2:
2016-04-13T18:25:20+00:00   * Scale(App(/servicename.shard--4.git378c7549.configcbe6b7a5, image="docker-paasta.yelpcorp.com:443/services-servicename:paasta-378c754959731a4c8799c58a9169d6d385151adc")), instances=5)
2016-04-13T18:25:20+00:00  (mesosphere.marathon.MarathonSchedulerActor:marathon-akka.actor.default-dispatcher-344)

According to the plan, Marathon then "starts" the app (even though it was already running!), which sets the desired number of instances to 0.

2016-04-13T18:25:22+00:00 [2016-04-13 11:25:22,519] INFO Starting app /servicename.shard--4.git378c7549.configcbe6b7a5 (mesosphere.marathon.SchedulerActions:marathon-akka.actor.default-dispatcher-186)
2016-04-13T18:25:22+00:00 [2016-04-13 11:25:22,519] INFO Scaling /servicename.shard--4.git378c7549.configcbe6b7a5 from 5 down to 0 instances (mesosphere.marathon.SchedulerActions:marathon-akka.actor.default-dispatcher-186)

2016-04-13T18:25:22+00:00 [2016-04-13 11:25:22,532] INFO Stopped appTaskLaunchActor for /servicename.shard--4.git378c7549.configcbe6b7a5 version 2016-04-13T17:06:31.160Z (mesosphere.marathon.core.launchqueue.impl.AppTaskLauncherActor:marathon-akka.actor.default-dispatcher-293)

It then kills all 5 of the instances:

2016-04-13T18:25:22+00:00 [2016-04-13 11:25:22,533] INFO Killing tasks: List(servicename.shard--4.git378c7549.configcbe6b7a5.28966741-019c-11e6-a897-02424de92a7e, servicename.shard--4.git378c7549.configcbe6b7a5.8cc6dc44-019b-11e6-a897-02424de92a7e, servicename.shard--4.git378c7549.configcbe6b7a5.b94341f8-019b-11e6-a897-02424de92a7e, servicename.shard--4.git378c7549.configcbe6b7a5.8cc6dc43-019b-11e6-a897-02424de92a7e, servicename.shard--4.git378c7549.configcbe6b7a5.b94341f7-019b-11e6-a897-02424de92a7e) (mesosphere.marathon.SchedulerActions:marathon-akka.actor.default-dispatcher-186)

And then, just to taunt us, brags about starting all 0 of the instances it wanted.

2016-04-13T18:25:22+00:00 [2016-04-13 11:25:22,534] INFO Successfully started 0 instances of /servicename.shard--4.git378c7549.configcbe6b7a5 (mesosphere.marathon.upgrade.AppStartActor:marathon-akka.actor.default-dispatcher-329)

(Later, it scales back up to 5 instances, but this particular application takes 10+ minutes to start, since it has to download a lot of data at startup).

cc @solarkennedy

[kolloch]

Hi @EvanKrall, thanks for reporting this.

As far as we can see, there are two parts that are misbehaving:

1. We get a timeout for a purge as a result of a canceled/failed deployment. We do not know the root cause of this yet and we would appreciate the full logs of the failing Marathon to analyze this further. This triggers a restart of the deployment actor which restarts all deployments.
2. The deployment restart does not behave correctly. When a deployment with a new app is restarted, the new app is first scaled down to zero again. That does not make sense it should be avoided.

[kolloch]

Oh, and if you can, please check if part 1 is still a problem with Marathon 1.1 since we have changed the related code quite a bit. Part 2 should unfortunately still be mostly the same.

[solarkennedy]

I'll work on upgrading our infrastructure to Marathon 1.1

[EvanKrall]

Our logs have a lot of mildly sensitive information (app names, etc) in them that I'd rather not post in bulk here. I'll get in touch with you over email.

[EvanKrall]

I've written an executable reproduction case: https://github.com/EvanKrall/reproduce_marathon_issue_3783

Seems like to get a failure, you need:

• An application that's deploying for a while (I've emulated this by having unmeetable constraints in the test case)
• Two(?) leadership abdications. (In this test, triggered by a DELETE /v2/leader. This seems to trigger the bug even though I'm only running one copy of Marathon.)

[EvanKrall]

My test case fails against marathon 1.1.2, 0.15.6, and 1.2.0.

[aquamatthias]

Hey @EvanKrall Thanks for the steps to reproduce this problem - we will look into that.

[solarkennedy]

This happened yesterday again. Any recommendations on a workaround until the root cause is fixed? Run in non-HA mode everywhere?

[aquamatthias]

Almost all DeploymentActions are written under the assumption they can be executed completely in one session (executed by the same leader). The state of those actions are held only in memory and does not reconcile correctly, if a deployment is resumed.

Example:
RestartApplication: will replace all old instances with the new version, where all currently running instances are considered old. If this action is resumed (e.g. a leader election took place) all already started new versions are considered old and will be replaced.

We need to add logic, so we can resume already started actions.

The original ticket states, that deployments get restarted even without a leader election.
Do you still see this behavior in recent versions?
We are aware of the fact, that this happens after a leader election.

[EvanKrall]

I haven't confirmed from logs, but as far as I can remember, all our incidences of this bug have been associated with a leader election.

[solarkennedy]

This happened again after a marathon 1.3 upgrade today with @nhandler.

We are going to add a safeguard to try to never restart Marathon if there are in-progress deployments. (except there always are in prod!)

Honestly I would rather Marathon "forget" about in-progress deployments and make the operator re-initiate them after a leader re-election than the current behavior of disruptive deployment-recovery. It literally brings down yelp.com (search) sometimes. Luckily the MTTR is small.

[aquamatthias]

@solarkennedy Just a heads up: this is on the list of things we are working on next. We are also rethinking the (rather rigid) deployments approach.

[solarkennedy]

This took down the our search subsystem (2016-10-13) again today (2016-10-17). I'm going to change gears and devote my time to working around this bug in any way I can.

[solarkennedy]

It looks like, from @EvanKrall's repro case, that this might be fixed in Marathon >= 1.4.0:
https://travis-ci.org/EvanKrall/reproduce_marathon_issue_3783

Hard to be 100% certain. It could be a false positive if the leader election changed in such a way to make this endpoint no longer force a leader election:
https://github.com/thefactory/marathon-python/blob/24cb891444ddafa3f73e9170a4fa699f71877472/marathon/client.py#L709

But it is kinda promising?

[mattmb]

In addition to @solarkennedy's comment: I'm pretty sure this is the commit that changed the behaviour: https://github.com/mesosphere/marathon/commit/8667787454059ac83b108b19ff17623465ff25f4

i.e. when built locally the parent of this commit fails @EvanKrall's test case but this commit doesn't. It's obviously a pretty big commit but I'd be interested if anyone can spot where this behaviour changed in the codebase.

[solarkennedy]

For the latest update, this itest is still a mixed bag:

• -snap17 still passes!
• -snap24 fails with HTTP 500: {"message":"while assembling rich tasks for app [/app-id]"} after a failover?
• @mattmb asked me to add 1.3.6, but it fails with Error while calling http://marathon:8080/v2/apps/app-id: ('Connection aborted.', BadStatusLine("''",)

https://travis-ci.org/EvanKrall/reproduce_marathon_issue_3783/builds/175891799

At Yelp we are have rolled back to using 1.1 in production and this 1.4-snap18 in stage. (no more 1.3 at all)

[aquamatthias]

@solarkennedy

• All fixes regarding recovering deployments from previous runs are available on master. See commit: https://github.com/mesosphere/marathon/commit/ccf689d06a03da7f783d14cd426fd6110ab3eb8b
  This means all deployment actions will reconcile the state before the action get started.
  Especially the RestartAction will filter already started tasks (so new tasks started by the old leader will not get killed)
  This fix is currently not available for Marathon 1.3.
• The 500 - while assembling rich tasks for app is a regression. Fix is here: https://phabricator.mesosphere.com/D185. Once this is merged, I will create another snap.
• Not 100% sure about BadStatusLine. Looked into your test result - the error says the returned status code is unknown?

[solarkennedy]

@aquamatthias Thank you for the confirmation. Please feel free to close this issue.

I'm looking forward to the next stable release! I'm also looking forward to @jparkie's test in #4623. (imo that PR or a different test could officially resolve this issue github-style)

[aquamatthias]

@solarkennedy I have created https://github.com/mesosphere/marathon/releases/tag/v1.4.0-snap26 This should fix the HTTP 500.

[unterstein]

Hi @solarkennedy,

like @aquamatthias said, this should be fixed from snap26 following. We cut v1.4.0-RC3 yesterday. Would it be possible to add this particular build to your travis jobs?

Currently I am trying to find out why latest-dev fails on travis, see https://travis-ci.org/EvanKrall/reproduce_marathon_issue_3783/jobs/175891809

Is The command "sed -i "s/MARATHON_VERSION/${MARATHON_VERSION}/g" docker-compose.yml && tox" exited with 1. expected in case of the described bug?

[unterstein]

@EvanKrall ^^^

[solarkennedy]

Tox fails (exit 1) because the other things fail. It needs to be re-run to pick up what the latest dev is now though.

I've added RC3 and bumped travis, let's see!
https://travis-ci.org/EvanKrall/reproduce_marathon_issue_3783/builds/183962209

[aquamatthias]

Still looks wrong:

The command "sed -i "s/MARATHON_VERSION/${MARATHON_VERSION}/g" docker-compose.yml && tox" exited with 1.

why is it working for snap 17?

[solarkennedy]

This is the smoking gun in docker-compose logs:
marathon_1 | [2016-12-14 19:55:10,709] ERROR Mesos Master version 0.28.2 does not meet minimum required version 1.1.0 (mesosphere.marathon.MarathonScheduler$$EnhancerByGuice$$d2c802be:Thread-16)

This check probably wasn't in snap17. I'll update the itest with a newer version of mesos.

[solarkennedy]

Alright well now the itests are revealing a change in the api from snap17 to rc3 that I'll have to update the python lib to account for:

 TypeError: __init__() got an unexpected keyword argument 'kill_selection'

[solarkennedy]

Well, now it fails with
https://travis-ci.org/EvanKrall/reproduce_marathon_issue_3783/jobs/184122800#L2531

Error while calling http://marathon:8080/v2/apps/app-id: ('Connection aborted.', BadStatusLine("''",))

I'm going to stick with snap17 in dev/stage and 1.1.1 in prod for now. The fact that rc3 requires an upgrade to the latest version of mesos means we are going to have to upgrade mesos throughout our infrastructure anyway, so it will be a while.

But you don't have to wait on me and my repro case if you are confident that there hasn't been a regression since snap17. I still have faith that a built-in test case from #4623 is a more direct way to verify that this bug is fixed and will continue to stay fixed.

[solarkennedy]

Woot!