{"action":"created","issue":{"url":"https://api.github.com/repos/mesosphere/marathon/issues/1652","labels_url":"https://api.github.com/repos/mesosphere/marathon/issues/1652/labels{/name}","comments_url":"https://api.github.com/repos/mesosphere/marathon/issues/1652/comments","events_url":"https://api.github.com/repos/mesosphere/marathon/issues/1652/events","html_url":"https://github.com/mesosphere/marathon/issues/1652","id":87719823,"number":1652,"title":"Task reconciliation does not work after leader reelection","user":{"login":"felixb","id":192135,"avatar_url":"https://avatars.githubusercontent.com/u/192135?v=3","gravatar_id":"","url":"https://api.github.com/users/felixb","html_url":"https://github.com/felixb","followers_url":"https://api.github.com/users/felixb/followers","following_url":"https://api.github.com/users/felixb/following{/other_user}","gists_url":"https://api.github.com/users/felixb/gists{/gist_id}","starred_url":"https://api.github.com/users/felixb/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/felixb/subscriptions","organizations_url":"https://api.github.com/users/felixb/orgs","repos_url":"https://api.github.com/users/felixb/repos","events_url":"https://api.github.com/users/felixb/events{/privacy}","received_events_url":"https://api.github.com/users/felixb/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/mesosphere/marathon/labels/analyze","name":"analyze","color":"fbca04"},{"url":"https://api.github.com/repos/mesosphere/marathon/labels/bug","name":"bug","color":"fc2929"}],"state":"open","locked":false,"assignee":null,"milestone":{"url":"https://api.github.com/repos/mesosphere/marathon/milestones/17","html_url":"https://github.com/mesosphere/marathon/milestones/0.10.0","labels_url":"https://api.github.com/repos/mesosphere/marathon/milestones/17/labels","id":1115259,"number":17,"title":"0.10.0","description":"","creator":{"login":"kolloch","id":339354,"avatar_url":"https://avatars.githubusercontent.com/u/339354?v=3","gravatar_id":"","url":"https://api.github.com/users/kolloch","html_url":"https://github.com/kolloch","followers_url":"https://api.github.com/users/kolloch/followers","following_url":"https://api.github.com/users/kolloch/following{/other_user}","gists_url":"https://api.github.com/users/kolloch/gists{/gist_id}","starred_url":"https://api.github.com/users/kolloch/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/kolloch/subscriptions","organizations_url":"https://api.github.com/users/kolloch/orgs","repos_url":"https://api.github.com/users/kolloch/repos","events_url":"https://api.github.com/users/kolloch/events{/privacy}","received_events_url":"https://api.github.com/users/kolloch/received_events","type":"User","site_admin":false},"open_issues":29,"closed_issues":1,"state":"open","created_at":"2015-05-18T10:01:48Z","updated_at":"2015-06-15T17:24:41Z","due_on":"2015-07-12T22:00:00Z","closed_at":null},"comments":1,"created_at":"2015-06-12T12:54:39Z","updated_at":"2015-06-16T10:33:29Z","closed_at":null,"body":"I'm running a cluster of 5 mesos-masters/zookeeper/marathon. There is a bunch of slaves.\r\nI'm running most of my apps as docker containers.\r\n\r\n* Marathon 0.8.2 (I experienced this bug in any version of 0.8.x)\r\n* Mesos 0.22.1\r\n* docker 1.6.2\r\n* RHEL 6.5\r\n\r\nEvery time the marathon leader gets reelected, it's failing the task reconciliation for _most_ of the tasks. You can see it killing nearly every task and spawning new instances shortly after.\r\nIt does not matter, how/why the leader gets reelected.\r\n\r\nI was able to reproduce this behavior in vagrant boxes:\r\n\r\n * 1x mesos-master/zookeeper/marathon\r\n * 1x marathon\r\n * 1x mesos-slave\r\n * 1x task running \"while true ; do sleep 10 ; date ; done\"\r\n * 1x task running yhttp in a docker container \"felixb/yocto-httpd\"\r\n\r\nI forced marathon to reelect the leader via REST-API.\r\nThe interesting part is, that task reconciliation works fine, when no docker task is running.\r\nBut as soon as there are multiple containerizers, only the oldest task stays alive.\r\n\r\nI'm running the mesos-master with the following options:\r\n\r\n    /usr/sbin/mesos-master --zk=zk://localhost:2181/mesos --port=17100 \\\r\n        --cluster=mesos develop --quorum=3 --roles=marathon,chronos,spark \\\r\n        --webui_dir=/usr/share/mesos/webui --work_dir=/var/opt/data/mesos\r\n\r\nThe slaves starts with multiple containerizers:\r\n\r\n    /usr/sbin/mesos-slave --master=zk://.../mesos --hadoop_home=/var/opt/hadoop \\\r\n        --cgroups_enable_cfs --cgroups_hierarchy=/cgroup --cgroups_limit_swap \\\r\n        --containerizers=docker,mesos --docker_stop_timeout=30secs \\\r\n        --executor_registration_timeout=2mins --isolation=cgroups/cpu,cgroups/mem \\\r\n        --port=17100 --recovery_timeout=2mins --strict=false --work_dir=/var/opt/data/mesos \\\r\n        --attributes=cluster:KGHAM1;datacenter:Hamburg;environment:shop;resourcepool:develop\r\n\r\nMarathon is running with the following options:\r\n\r\n    java -jar /var/opt/marathon/bin/../target/scala-2.11/marathon-assembly-0.8.2.jar \\\r\n        --master zk://localhost:2181/mesos --zk zk://localhost:2181/marathon --mesos_role marathon \\\r\n        --mesos_user marathon --http_port 8080 --checkpoint --event_subscriber http_callback --ha \\\r\n        --failover_timeout 75 --reconciliation_interval 75000\r\n\r\n\r\nmesos-master log file\r\n\r\n    I0612 14:26:02.232628  5511 http.cpp:516] HTTP request for '/master/state.json'\r\n    I0612 14:26:04.351080  5504 master.cpp:3760] Sending 1 offers to framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:04.358263  5508 master.cpp:2273] Processing ACCEPT call for offers: [ 20150612-105616-1160423616-17100-5468-O2347 ] on slave 20150612-105616-1160423616-17100-5468-S44 at slave(1)@192.168.42.1:17105 (192.168.42.1) for framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:04.358814  5508 hierarchical.hpp:648] Recovered cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000] (total allocatable: cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000]) on slave 20150612-105616-1160423616-17100-5468-S44 from framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:10.355249  5507 master.cpp:3760] Sending 1 offers to framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:10.366829  5511 master.cpp:2273] Processing ACCEPT call for offers: [ 20150612-105616-1160423616-17100-5468-O2348 ] on slave 20150612-105616-1160423616-17100-5468-S44 at slave(1)@192.168.42.1:17105 (192.168.42.1) for framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:10.367063  5511 hierarchical.hpp:648] Recovered cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000] (total allocatable: cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000]) on slave 20150612-105616-1160423616-17100-5468-S44 from framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:12.272161  5508 http.cpp:516] HTTP request for '/master/state.json'\r\n    I0612 14:26:14.755897  5504 master.cpp:3522] Performing explicit task state reconciliation for 2 tasks of framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:14.758635  5504 master.cpp:3461] Performing implicit task state reconciliation for framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:16.361681  5506 master.cpp:3760] Sending 1 offers to framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:16.368597  5507 master.cpp:2273] Processing ACCEPT call for offers: [ 20150612-105616-1160423616-17100-5468-O2349 ] on slave 20150612-105616-1160423616-17100-5468-S44 at slave(1)@192.168.42.1:17105 (192.168.42.1) for framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:16.368785  5505 hierarchical.hpp:648] Recovered cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000] (total allocatable: cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000]) on slave 20150612-105616-1160423616-17100-5468-S44 from framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:22.328002  5510 http.cpp:516] HTTP request for '/master/state.json'\r\n    I0612 14:26:22.366937  5509 master.cpp:3760] Sending 1 offers to framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:22.384783  5509 master.cpp:2273] Processing ACCEPT call for offers: [ 20150612-105616-1160423616-17100-5468-O2350 ] on slave 20150612-105616-1160423616-17100-5468-S44 at slave(1)@192.168.42.1:17105 (192.168.42.1) for framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185\r\n    I0612 14:26:22.385000  5509 hierarchical.hpp:648] Recovered cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000] (total allocatable: cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000]) on slave 20150612-105616-1160423616-17100-5468-S44 from framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:26.933971  5509 master.cpp:1711] Received re-registration request from framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-001537a2-628d-4a4c-8f96-9c69c9eedde4@192.168.42.80:37340\r\n    I0612 14:26:26.934072  5509 master.cpp:1764] Re-registering framework 20150611-103128-1160423616-17100-12472-0001 (marathon)  at scheduler-001537a2-628d-4a4c-8f96-9c69c9eedde4@192.168.42.80:37340\r\n    I0612 14:26:26.934095  5509 master.cpp:1783] Updating info for framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:26.934114  5509 master.cpp:1798] Framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-c38256f0-c3a0-4946-b883-25400d5b8f7a@192.168.42.69:35185 failed over\r\n    I0612 14:26:28.372448  5510 master.cpp:3760] Sending 1 offers to framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-001537a2-628d-4a4c-8f96-9c69c9eedde4@192.168.42.80:37340\r\n    I0612 14:26:28.381594  5506 master.cpp:2273] Processing ACCEPT call for offers: [ 20150612-105616-1160423616-17100-5468-O2351 ] on slave 20150612-105616-1160423616-17100-5468-S44 at slave(1)@192.168.42.1:17105 (192.168.42.1) for framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-001537a2-628d-4a4c-8f96-9c69c9eedde4@192.168.42.80:37340\r\n    I0612 14:26:28.381857  5509 hierarchical.hpp:648] Recovered cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000] (total allocatable: cpus(*):3.7; mem(*):6587; disk(*):227114; ports(*):[31000-31794, 31796-32000]) on slave 20150612-105616-1160423616-17100-5468-S44 from framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:32.369503  5511 http.cpp:516] HTTP request for '/master/state.json'\r\n    I0612 14:26:34.377359  5504 master.cpp:3760] Sending 1 offers to framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-001537a2-628d-4a4c-8f96-9c69c9eedde4@192.168.42.80:37340\r\n    I0612 14:26:34.386256  5505 master.cpp:2273] Processing ACCEPT call for offers: [ 20150612-105616-1160423616-17100-5468-O2352 ] on slave 20150612-105616-1160423616-17100-5468-S44 at slave(1)@192.168.42.1:17105 (192.168.42.1) for framework 20150611-103128-1160423616-17100-12472-0001 (marathon) at scheduler-001537a2-628d-4a4c-8f96-9c69c9eedde4@192.168.42.80:37340\r\n\r\nmesos-slave logfile\r\n\r\n    I0612 14:26:26.926584 11071 slave.cpp:1945] Updating framework 20150611-103128-1160423616-17100-12472-0001 pid to scheduler-001537a2-628d-4a4c-8f96-9c69c9eedde4@192.168.42.80:37340\r\n    I0612 14:26:26.926962 11071 status_update_manager.cpp:178] Resuming sending status updates\r\n    I0612 14:26:33.999011 11072 slave.cpp:3648] Current disk usage 23.96%. Max allowed age: 4.623004749876655days\r\n    I0612 14:26:41.958184 11070 slave.cpp:1581] Asked to kill task sleep.0b5119ae-10fe-11e5-b846-0800276a3382 of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.080211 11065 slave.cpp:2531] Handling status update TASK_KILLED (UUID: a55df415-acde-4c2c-95b5-8b9fc5522ae5) for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382 of framework 20150611-103128-1160423616-17100-12472-0001 from executor(1)@192.168.42.1:38521\r\n    I0612 14:26:42.080806 11068 mem.cpp:319] Updated 'memory.soft_limit_in_bytes' to 32MB for container 4911e40a-8785-44b6-8101-425cc9cbd9e2\r\n    I0612 14:26:42.080827 11072 cpushare.cpp:377] Updated 'cpu.shares' to 102 (cpus 0.1) for container 4911e40a-8785-44b6-8101-425cc9cbd9e2\r\n    I0612 14:26:42.081543 11072 cpushare.cpp:399] Updated 'cpu.cfs_period_us' to 100ms and 'cpu.cfs_quota_us' to 10ms (cpus 0.1) for container 4911e40a-8785-44b6-8101-425cc9cbd9e2\r\n    I0612 14:26:42.081663 11069 status_update_manager.cpp:317] Received status update TASK_KILLED (UUID: a55df415-acde-4c2c-95b5-8b9fc5522ae5) for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382 of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.081696 11069 status_update_manager.hpp:346] Checkpointing UPDATE for status update TASK_KILLED (UUID: a55df415-acde-4c2c-95b5-8b9fc5522ae5) for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382 of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.086590 11066 slave.cpp:2776] Forwarding the update TASK_KILLED (UUID: a55df415-acde-4c2c-95b5-8b9fc5522ae5) for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382 of framework 20150611-103128-1160423616-17100-12472-0001 to master@192.168.42.69:17100\r\n    I0612 14:26:42.086659 11066 slave.cpp:2709] Sending acknowledgement for status update TASK_KILLED (UUID: a55df415-acde-4c2c-95b5-8b9fc5522ae5) for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382 of framework 20150611-103128-1160423616-17100-12472-0001 to executor(1)@192.168.42.1:38521\r\n    I0612 14:26:42.093179 11069 status_update_manager.cpp:389] Received status update acknowledgement (UUID: a55df415-acde-4c2c-95b5-8b9fc5522ae5) for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382 of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.093250 11069 status_update_manager.hpp:346] Checkpointing ACK for status update TASK_KILLED (UUID: a55df415-acde-4c2c-95b5-8b9fc5522ae5) for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382 of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.387437 11065 slave.cpp:1144] Got assigned task sleep.483a0e86-10fe-11e5-898b-080027a4f769 for framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.387725 11065 slave.cpp:1254] Launching task sleep.483a0e86-10fe-11e5-898b-080027a4f769 for framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.390823 11065 slave.cpp:4208] Launching executor sleep.483a0e86-10fe-11e5-898b-080027a4f769 of framework 20150611-103128-1160423616-17100-12472-0001 in work directory '/home/flx/tmp/mesos/slaves/20150612-105616-1160423616-17100-5468-S44/frameworks/20150611-103128-1160423616-17100-12472-0001/executors/sleep.483a0e86-10fe-11e5-898b-080027a4f769/runs/18441293-386e-4c40-b810-820fbb208087'\r\n    I0612 14:26:42.391315 11071 docker.cpp:598] No container info found, skipping launch\r\n    I0612 14:26:42.391487 11069 containerizer.cpp:484] Starting container '18441293-386e-4c40-b810-820fbb208087' for executor 'sleep.483a0e86-10fe-11e5-898b-080027a4f769' of framework '20150611-103128-1160423616-17100-12472-0001'\r\n    I0612 14:26:42.393004 11067 cpushare.cpp:377] Updated 'cpu.shares' to 204 (cpus 0.2) for container 18441293-386e-4c40-b810-820fbb208087\r\n    I0612 14:26:42.393188 11065 slave.cpp:1401] Queuing task 'sleep.483a0e86-10fe-11e5-898b-080027a4f769' for executor sleep.483a0e86-10fe-11e5-898b-080027a4f769 of framework '20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.393698 11067 cpushare.cpp:399] Updated 'cpu.cfs_period_us' to 100ms and 'cpu.cfs_quota_us' to 20ms (cpus 0.2) for container 18441293-386e-4c40-b810-820fbb208087\r\n    I0612 14:26:42.394875 11069 mem.cpp:487] Started listening for OOM events for container 18441293-386e-4c40-b810-820fbb208087\r\n    I0612 14:26:42.395299 11069 mem.cpp:319] Updated 'memory.soft_limit_in_bytes' to 64MB for container 18441293-386e-4c40-b810-820fbb208087\r\n    I0612 14:26:42.395860 11069 mem.cpp:354] Updated 'memory.limit_in_bytes' to 64MB for container 18441293-386e-4c40-b810-820fbb208087\r\n    I0612 14:26:42.396847 11069 linux_launcher.cpp:213] Cloning child process with flags = 0\r\n    I0612 14:26:42.398118 11069 containerizer.cpp:694] Checkpointing executor's forked pid 13248 to '/home/flx/tmp/mesos/meta/slaves/20150612-105616-1160423616-17100-5468-S44/frameworks/20150611-103128-1160423616-17100-12472-0001/executors/sleep.483a0e86-10fe-11e5-898b-080027a4f769/runs/18441293-386e-4c40-b810-820fbb208087/pids/forked.pid'\r\n    I0612 14:26:42.400061 11069 slave.cpp:3165] Monitoring executor 'sleep.483a0e86-10fe-11e5-898b-080027a4f769' of framework '20150611-103128-1160423616-17100-12472-0001' in container '18441293-386e-4c40-b810-820fbb208087'\r\n    I0612 14:26:42.522264 11072 slave.cpp:2164] Got registration for executor 'sleep.483a0e86-10fe-11e5-898b-080027a4f769' of framework 20150611-103128-1160423616-17100-12472-0001 from executor(1)@192.168.42.1:47995\r\n    I0612 14:26:42.523583 11072 cpushare.cpp:377] Updated 'cpu.shares' to 204 (cpus 0.2) for container 18441293-386e-4c40-b810-820fbb208087\r\n    I0612 14:26:42.525938 11072 cpushare.cpp:399] Updated 'cpu.cfs_period_us' to 100ms and 'cpu.cfs_quota_us' to 20ms (cpus 0.2) for container 18441293-386e-4c40-b810-820fbb208087\r\n    I0612 14:26:42.525087 11066 mem.cpp:319] Updated 'memory.soft_limit_in_bytes' to 64MB for container 18441293-386e-4c40-b810-820fbb208087\r\n    I0612 14:26:42.526494 11066 slave.cpp:1555] Sending queued task 'sleep.483a0e86-10fe-11e5-898b-080027a4f769' to executor 'sleep.483a0e86-10fe-11e5-898b-080027a4f769' of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.531574 11072 slave.cpp:2531] Handling status update TASK_RUNNING (UUID: ad73f97e-d43e-4216-b8d5-8ea1ec30471d) for task sleep.483a0e86-10fe-11e5-898b-080027a4f769 of framework 20150611-103128-1160423616-17100-12472-0001 from executor(1)@192.168.42.1:47995\r\n    I0612 14:26:42.531791 11071 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: ad73f97e-d43e-4216-b8d5-8ea1ec30471d) for task sleep.483a0e86-10fe-11e5-898b-080027a4f769 of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.531944 11071 status_update_manager.hpp:346] Checkpointing UPDATE for status update TASK_RUNNING (UUID: ad73f97e-d43e-4216-b8d5-8ea1ec30471d) for task sleep.483a0e86-10fe-11e5-898b-080027a4f769 of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.541491 11071 slave.cpp:2776] Forwarding the update TASK_RUNNING (UUID: ad73f97e-d43e-4216-b8d5-8ea1ec30471d) for task sleep.483a0e86-10fe-11e5-898b-080027a4f769 of framework 20150611-103128-1160423616-17100-12472-0001 to master@192.168.42.69:17100\r\n    I0612 14:26:42.541638 11071 slave.cpp:2709] Sending acknowledgement for status update TASK_RUNNING (UUID: ad73f97e-d43e-4216-b8d5-8ea1ec30471d) for task sleep.483a0e86-10fe-11e5-898b-080027a4f769 of framework 20150611-103128-1160423616-17100-12472-0001 to executor(1)@192.168.42.1:47995\r\n    I0612 14:26:42.564708 11071 status_update_manager.cpp:389] Received status update acknowledgement (UUID: ad73f97e-d43e-4216-b8d5-8ea1ec30471d) for task sleep.483a0e86-10fe-11e5-898b-080027a4f769 of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:42.564769 11071 status_update_manager.hpp:346] Checkpointing ACK for status update TASK_RUNNING (UUID: ad73f97e-d43e-4216-b8d5-8ea1ec30471d) for task sleep.483a0e86-10fe-11e5-898b-080027a4f769 of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:43.117852 11069 containerizer.cpp:1123] Executor for container '4911e40a-8785-44b6-8101-425cc9cbd9e2' has exited\r\n    I0612 14:26:43.117887 11069 containerizer.cpp:918] Destroying container '4911e40a-8785-44b6-8101-425cc9cbd9e2'\r\n    I0612 14:26:43.118870 11066 cgroups.cpp:2251] Freezing cgroup /sys/fs/cgroup/freezer/mesos/4911e40a-8785-44b6-8101-425cc9cbd9e2\r\n    I0612 14:26:43.119798 11069 cgroups.cpp:1418] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/4911e40a-8785-44b6-8101-425cc9cbd9e2 after 897024ns\r\n    I0612 14:26:43.120686 11067 cgroups.cpp:2268] Thawing cgroup /sys/fs/cgroup/freezer/mesos/4911e40a-8785-44b6-8101-425cc9cbd9e2\r\n    I0612 14:26:43.121527 11067 cgroups.cpp:1447] Successfullly thawed cgroup /sys/fs/cgroup/freezer/mesos/4911e40a-8785-44b6-8101-425cc9cbd9e2 after 804864ns\r\n    I0612 14:26:43.124860 11071 slave.cpp:3223] Executor 'sleep.0b5119ae-10fe-11e5-b846-0800276a3382' of framework 20150611-103128-1160423616-17100-12472-0001 exited with status 0\r\n    I0612 14:26:43.124912 11071 slave.cpp:3332] Cleaning up executor 'sleep.0b5119ae-10fe-11e5-b846-0800276a3382' of framework 20150611-103128-1160423616-17100-12472-0001\r\n    I0612 14:26:43.125069 11072 gc.cpp:56] Scheduling '/home/flx/tmp/mesos/slaves/20150612-105616-1160423616-17100-5468-S44/frameworks/20150611-103128-1160423616-17100-12472-0001/executors/sleep.0b5119ae-10fe-11e5-b846-0800276a3382/runs/4911e40a-8785-44b6-8101-425cc9cbd9e2' for gc 6.9999985528237days in the future\r\n    I0612 14:26:43.125115 11072 gc.cpp:56] Scheduling '/home/flx/tmp/mesos/slaves/20150612-105616-1160423616-17100-5468-S44/frameworks/20150611-103128-1160423616-17100-12472-0001/executors/sleep.0b5119ae-10fe-11e5-b846-0800276a3382' for gc 6.99999855237037days in the future\r\n    I0612 14:26:43.125141 11072 gc.cpp:56] Scheduling '/home/flx/tmp/mesos/meta/slaves/20150612-105616-1160423616-17100-5468-S44/frameworks/20150611-103128-1160423616-17100-12472-0001/executors/sleep.0b5119ae-10fe-11e5-b846-0800276a3382/runs/4911e40a-8785-44b6-8101-425cc9cbd9e2' for gc 6.99999855211852days in the future\r\n    I0612 14:26:43.125157 11072 gc.cpp:56] Scheduling '/home/flx/tmp/mesos/meta/slaves/20150612-105616-1160423616-17100-5468-S44/frameworks/20150611-103128-1160423616-17100-12472-0001/executors/sleep.0b5119ae-10fe-11e5-b846-0800276a3382' for gc 6.9999985518963days in the future\r\n    I0612 14:27:34.000224 11070 slave.cpp:3648] Current disk usage 23.96%. Max allowed age: 4.622995095040417days\r\n\r\nmarathon old leader log file:\r\n\r\n    [2015-06-12 14:26:14,743] INFO Expunging orphaned tasks from store (mesosphere.marathon.tasks.TaskTracker:170)\r\n    [2015-06-12 14:26:14,745] INFO Expunging orphaned task with key task:sleep:sleep.dfbc7be5-10fd-11e5-898b-080027a4f769 (mesosphere.marathon.tasks.TaskTracker:178)\r\n    [2015-06-12 14:26:14,753] INFO Syncing tasks for all apps (mesosphere.marathon.SchedulerActions:457)\r\n    [2015-06-12 14:26:14,754] INFO Requesting task reconciliation with the Mesos master (mesosphere.marathon.SchedulerActions:482)\r\n    [2015-06-12 14:26:14,757] INFO Received status update for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:26:14,761] INFO Received status update for task yhttpd.885a4b8c-10fc-11e5-b846-0800276a3382: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:26:14,764] INFO Received status update for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:26:14,767] INFO Received status update for task yhttpd.885a4b8c-10fc-11e5-b846-0800276a3382: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:26:16,367] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:26:16,367] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:26:22,382] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:26:22,383] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:26:26,828] INFO Abdicating (mesosphere.marathon.MarathonSchedulerService:312)\r\n    [2015-06-12 14:26:26,828] INFO Defeat leadership (mesosphere.marathon.MarathonSchedulerService:285)\r\n    [2015-06-12 14:26:26,847] INFO Stopping driver (mesosphere.marathon.MarathonSchedulerService:224)\r\n    I0612 14:26:26.847770 10494 sched.cpp:1589] Asked to stop the driver\r\n    I0612 14:26:26.848037 10477 sched.cpp:831] Stopping framework '20150611-103128-1160423616-17100-12472-0001'\r\n    [2015-06-12 14:26:26,848] INFO Driver future completed. Executing optional abdication command. (mesosphere.marathon.MarathonSchedulerService:195)\r\n    [INFO] [06/12/2015 14:26:26.829] [marathon-akka.actor.default-dispatcher-50] [akka://marathon/user/MarathonScheduler/$a] Suspending scheduler actor\r\n    [2015-06-12 14:26:26,848] INFO 192.168.42.80 -  -  [12/Jun/2015:12:26:26 +0000] \"DELETE /v2/leader HTTP/1.1\" 200 33 \"-\" \"curl/7.38.0\" (mesosphere.chaos.http.ChaosRequestLog:15)\r\n    [2015-06-12 14:26:26,854] INFO Defeated (Leader Interface) (mesosphere.marathon.MarathonSchedulerService:245)\r\n    [2015-06-12 14:26:26,855] INFO Defeat leadership (mesosphere.marathon.MarathonSchedulerService:285)\r\n    [2015-06-12 14:26:26,855] INFO Will offer leadership after 500 milliseconds backoff (mesosphere.marathon.MarathonSchedulerService:334)\r\n    [2015-06-12 14:26:26,860] INFO Stopping driver (mesosphere.marathon.MarathonSchedulerService:224)\r\n    [2015-06-12 14:26:26,863] ERROR Current member ID member_0000000016 is not a candidate for leader, current voting: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:26,867] ERROR Current member ID member_0000000012 is not a candidate for leader, current voting: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:26,868] ERROR Current member ID member_0000000014 is not a candidate for leader, current voting: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:26,871] ERROR Current member ID member_0000000018 is not a candidate for leader, current voting: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:26,877] ERROR Current member ID member_0000000010 is not a candidate for leader, current voting: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:27,371] INFO Using HA and therefore offering leadership (mesosphere.marathon.MarathonSchedulerService:341)\r\n    [2015-06-12 14:26:27,376] INFO Set group member ID to member_0000000020 (com.twitter.common.zookeeper.Group:426)\r\n    [2015-06-12 14:26:27,377] ERROR Current member ID member_0000000016 is not a candidate for leader, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:27,379] ERROR Current member ID member_0000000012 is not a candidate for leader, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:27,379] INFO Candidate /marathon/leader/member_0000000020 waiting for the next leader election, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:165)\r\n    [2015-06-12 14:26:27,380] ERROR Current member ID member_0000000014 is not a candidate for leader, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:27,381] ERROR Current member ID member_0000000018 is not a candidate for leader, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:27,382] ERROR Current member ID member_0000000010 is not a candidate for leader, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n\r\nmarathon new leader log file\r\n\r\n    [2015-06-12 14:26:26,851] INFO Proxying request to leader at mesos-dev-f999998.exampl.com:8080 (mesosphere.marathon.api.LeaderProxyFilter:62)\r\n    [2015-06-12 14:26:26,876] INFO 10.0.2.2 -  -  [12/Jun/2015:12:26:26 +0000] \"DELETE /v2/leader HTTP/1.1\" 200 33 \"-\" \"curl/7.38.0\" (mesosphere.chaos.http.ChaosRequestLog:15)\r\n    [2015-06-12 14:26:26,886] INFO Candidate /marathon/leader/member_0000000019 is now leader of group: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:152)\r\n    [2015-06-12 14:26:26,886] INFO Elected (Leader Interface) (mesosphere.marathon.MarathonSchedulerService:252)\r\n    [2015-06-12 14:26:26,905] INFO Migration successfully applied for version Version(0, 8, 2) (mesosphere.marathon.state.Migration:69)\r\n    [2015-06-12 14:26:26,905] INFO Elect leadership (mesosphere.marathon.MarathonSchedulerService:299)\r\n    [2015-06-12 14:26:26,906] INFO Running driver (mesosphere.marathon.MarathonSchedulerService:187)\r\n    [2015-06-12 14:26:26,906] INFO Reset offerLeadership backoff (mesosphere.marathon.MarathonSchedulerService:329)\r\n    I0612 14:26:26.906806 15169 sched.cpp:157] Version: 0.22.1\r\n    2015-06-12 14:26:26,906:14324(0x7f0a0216e700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5\r\n    2015-06-12 14:26:26,906:14324(0x7f0a0216e700):ZOO_INFO@log_env@716: Client environment:host.name=mesos-dev-f999996.exampl.com\r\n    2015-06-12 14:26:26,906:14324(0x7f0a0216e700):ZOO_INFO@log_env@723: Client environment:os.name=Linux\r\n    2015-06-12 14:26:26,906:14324(0x7f0a0216e700):ZOO_INFO@log_env@724: Client environment:os.arch=2.6.32-279.el6.x86_64\r\n    2015-06-12 14:26:26,906:14324(0x7f0a0216e700):ZOO_INFO@log_env@725: Client environment:os.version=#1 SMP Wed Jun 13 18:24:36 EDT 2012\r\n    [INFO] [06/12/2015 14:26:26.906] [marathon-akka.actor.default-dispatcher-6] [akka://marathon/user/MarathonScheduler/$a] Starting scheduler actor\r\n    [2015-06-12 14:26:26,910] ERROR Current member ID member_0000000013 is not a candidate for leader, current voting: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:26,912] ERROR Current member ID member_0000000017 is not a candidate for leader, current voting: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    2015-06-12 14:26:26,914:14324(0x7f0a0216e700):ZOO_INFO@log_env@733: Client environment:user.name=(null)\r\n    2015-06-12 14:26:26,919:14324(0x7f0a0216e700):ZOO_INFO@log_env@741: Client environment:user.home=/root\r\n    2015-06-12 14:26:26,919:14324(0x7f0a0216e700):ZOO_INFO@log_env@753: Client environment:user.dir=/\r\n    2015-06-12 14:26:26,919:14324(0x7f0a0216e700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=mesos-dev-f999998:2181 sessionTimeout=10000 watcher=0x7f0a2dd88eb0 sessionId=0 sessionPasswd=<null> context=0x7f09b4012b70 flags=0\r\n    [INFO] [06/12/2015 14:26:26.920] [marathon-akka.actor.default-dispatcher-20] [akka://marathon/user/MarathonScheduler/$a] Scheduler actor ready\r\n    [2015-06-12 14:26:26,925] ERROR Current member ID member_0000000011 is not a candidate for leader, current voting: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    2015-06-12 14:26:26,925:14324(0x7f099ffec700):ZOO_INFO@check_events@1703: initiated connection to server [192.168.42.69:2181]\r\n    2015-06-12 14:26:26,941:14324(0x7f099ffec700):ZOO_INFO@check_events@1750: session establishment complete on server [192.168.42.69:2181], sessionId=0x14de6fbddd0002b, negotiated timeout=10000\r\n    [2015-06-12 14:26:26,942] ERROR Current member ID member_0000000015 is not a candidate for leader, current voting: [member_0000000019] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    I0612 14:26:26.942391 14368 group.cpp:313] Group process (group(5)@192.168.42.80:37340) connected to ZooKeeper\r\n    I0612 14:26:26.942440 14368 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)\r\n    I0612 14:26:26.942456 14368 group.cpp:385] Trying to create path '/mesos' in ZooKeeper\r\n    I0612 14:26:26.945544 14368 detector.cpp:138] Detected a new leader: (id='3')\r\n    I0612 14:26:26.945794 14368 group.cpp:659] Trying to get '/mesos/info_0000000003' in ZooKeeper\r\n    I0612 14:26:26.958334 14368 detector.cpp:452] A new leading master (UPID=master@192.168.42.69:17100) is detected\r\n    I0612 14:26:26.958490 14368 sched.cpp:254] New master detected at master@192.168.42.69:17100\r\n    I0612 14:26:26.958529 14368 sched.cpp:264] No credentials provided. Attempting to register without authentication\r\n    I0612 14:26:26.964764 14368 sched.cpp:448] Framework registered with 20150611-103128-1160423616-17100-12472-0001\r\n    [2015-06-12 14:26:26,966] INFO Registered as 20150611-103128-1160423616-17100-12472-0001 to master '20150612-105616-1160423616-17100-5468' (mesosphere.marathon.MarathonScheduler:55)\r\n    [INFO] [06/12/2015 14:26:26.966] [marathon-akka.actor.default-dispatcher-6] [akka://marathon/user/$b] POSTing to all endpoints.\r\n    [2015-06-12 14:26:26,976] INFO Stored framework ID '20150611-103128-1160423616-17100-12472-0001' (mesosphere.mesos.util.FrameworkIdUtil:49)\r\n    [2015-06-12 14:26:27,409] ERROR Current member ID member_0000000013 is not a candidate for leader, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:27,411] ERROR Current member ID member_0000000017 is not a candidate for leader, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:27,412] ERROR Current member ID member_0000000011 is not a candidate for leader, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:27,414] ERROR Current member ID member_0000000015 is not a candidate for leader, current voting: [member_0000000019, member_0000000020] (com.twitter.common.zookeeper.CandidateImpl:144)\r\n    [2015-06-12 14:26:28,404] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:26:28,405] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:26:34,410] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:26:34,410] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:26:40,413] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:26:40,414] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:26:41,910] INFO Syncing tasks for all apps (mesosphere.marathon.SchedulerActions:457)\r\n    [2015-06-12 14:26:41,911] INFO Requesting task reconciliation with the Mesos master (mesosphere.marathon.SchedulerActions:482)\r\n    [2015-06-12 14:26:41,919] INFO Received status update for task sleep.dfbc7be5-10fd-11e5-898b-080027a4f769: TASK_LOST (Reconciliation: Task is unknown to the slave) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:26:41,942] INFO Already running 1 instances of /sleep. Not scaling. (mesosphere.marathon.SchedulerActions:545)\r\n    [2015-06-12 14:26:41,953] INFO Already running 1 instances of /yhttpd. Not scaling. (mesosphere.marathon.SchedulerActions:545)\r\n    [2015-06-12 14:26:41,974] INFO Task sleep.dfbc7be5-10fd-11e5-898b-080027a4f769 expunged and removed from TaskTracker (mesosphere.marathon.tasks.TaskTracker:107)\r\n    [2015-06-12 14:26:41,975] INFO Sending event notification. (mesosphere.marathon.MarathonScheduler:212)\r\n    [2015-06-12 14:26:41,975] INFO Received status update for task yhttpd.885a4b8c-10fc-11e5-b846-0800276a3382: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [INFO] [06/12/2015 14:26:41.975] [marathon-akka.actor.default-dispatcher-21] [akka://marathon/user/$b] POSTing to all endpoints.\r\n    [2015-06-12 14:26:41,980] INFO Need to scale /sleep from 0 up to 1 instances (mesosphere.marathon.SchedulerActions:521)\r\n    [2015-06-12 14:26:41,980] INFO Queueing 1 new tasks for /sleep (0 queued) (mesosphere.marathon.SchedulerActions:527)\r\n    [2015-06-12 14:26:41,982] INFO Received status update for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:26:41,986] WARN No task for ID sleep.0b5119ae-10fe-11e5-b846-0800276a3382 (mesosphere.marathon.tasks.TaskTracker:149)\r\n    [2015-06-12 14:26:41,987] WARN Killing task value: \"sleep.0b5119ae-10fe-11e5-b846-0800276a3382\"\r\n     (mesosphere.marathon.MarathonScheduler:151)\r\n    [2015-06-12 14:26:41,987] INFO Received status update for task yhttpd.885a4b8c-10fc-11e5-b846-0800276a3382: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:26:42,122] INFO Received status update for task sleep.0b5119ae-10fe-11e5-b846-0800276a3382: TASK_KILLED (Command terminated with signal Terminated) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:26:42,125] WARN Couldn't post event for value: \"sleep.0b5119ae-10fe-11e5-b846-0800276a3382\"\r\n     (mesosphere.marathon.MarathonScheduler:123)\r\n    [2015-06-12 14:26:42,131] INFO Need to scale /sleep from 0 up to 1 instances (mesosphere.marathon.SchedulerActions:521)\r\n    [2015-06-12 14:26:42,131] INFO Already queued 1 tasks for /sleep. Not scaling. (mesosphere.marathon.SchedulerActions:531)\r\n    [2015-06-12 14:26:42,416] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:26:42,418] INFO Launched 1 tasks on 1 offers, declining 0 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:26:42,576] INFO Received status update for task sleep.483a0e86-10fe-11e5-898b-080027a4f769: TASK_RUNNING () (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:26:42,617] INFO Sending event notification. (mesosphere.marathon.MarathonScheduler:212)\r\n    [INFO] [06/12/2015 14:26:42.619] [marathon-akka.actor.default-dispatcher-21] [akka://marathon/user/$b] POSTing to all endpoints.\r\n    [2015-06-12 14:26:48,421] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:26:48,421] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:26:54,425] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:26:54,425] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:00,435] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:00,435] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:06,461] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:06,462] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:12,441] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:12,441] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:18,453] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:18,454] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:24,450] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:24,451] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:30,452] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:30,453] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:36,457] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:36,458] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:42,468] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:42,468] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:47,498] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:47,499] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:53,507] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:53,507] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:27:56,906] INFO Expunging orphaned tasks from store (mesosphere.marathon.tasks.TaskTracker:170)\r\n    [2015-06-12 14:27:56,909] INFO Expunging orphaned task with key task:sleep:sleep.0b5119ae-10fe-11e5-b846-0800276a3382 (mesosphere.marathon.tasks.TaskTracker:178)\r\n    [2015-06-12 14:27:56,916] INFO Syncing tasks for all apps (mesosphere.marathon.SchedulerActions:457)\r\n    [2015-06-12 14:27:56,917] INFO Requesting task reconciliation with the Mesos master (mesosphere.marathon.SchedulerActions:482)\r\n    [2015-06-12 14:27:56,934] INFO Received status update for task sleep.483a0e86-10fe-11e5-898b-080027a4f769: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:27:56,962] INFO Received status update for task yhttpd.885a4b8c-10fc-11e5-b846-0800276a3382: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:27:56,966] INFO Received status update for task sleep.483a0e86-10fe-11e5-898b-080027a4f769: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:27:56,969] INFO Received status update for task yhttpd.885a4b8c-10fc-11e5-b846-0800276a3382: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:98)\r\n    [2015-06-12 14:27:59,510] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:27:59,510] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:28:05,515] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:28:05,515] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:28:11,519] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:28:11,520] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:28:17,522] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:28:17,522] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:28:23,595] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:28:23,596] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:28:29,534] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:28:29,534] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:28:35,541] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:28:35,542] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:28:41,545] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:28:41,547] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:28:47,552] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:28:47,553] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n    [2015-06-12 14:28:53,561] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124)\r\n    [2015-06-12 14:28:53,562] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216)\r\n"},"comment":{"url":"https://api.github.com/repos/mesosphere/marathon/issues/comments/112380458","html_url":"https://github.com/mesosphere/marathon/issues/1652#issuecomment-112380458","issue_url":"https://api.github.com/repos/mesosphere/marathon/issues/1652","id":112380458,"user":{"login":"aquamatthias","id":330485,"avatar_url":"https://avatars.githubusercontent.com/u/330485?v=3","gravatar_id":"","url":"https://api.github.com/users/aquamatthias","html_url":"https://github.com/aquamatthias","followers_url":"https://api.github.com/users/aquamatthias/followers","following_url":"https://api.github.com/users/aquamatthias/following{/other_user}","gists_url":"https://api.github.com/users/aquamatthias/gists{/gist_id}","starred_url":"https://api.github.com/users/aquamatthias/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/aquamatthias/subscriptions","organizations_url":"https://api.github.com/users/aquamatthias/orgs","repos_url":"https://api.github.com/users/aquamatthias/repos","events_url":"https://api.github.com/users/aquamatthias/events{/privacy}","received_events_url":"https://api.github.com/users/aquamatthias/received_events","type":"User","site_admin":false},"created_at":"2015-06-16T10:33:29Z","updated_at":"2015-06-16T10:33:29Z","body":"@felixb Hey Felix. Thanks for the report.\r\nI did some reelections on our staging cluster - the problem did not show up.\r\nAfter digging in the logs you have provided, I think I found the problem:\r\n- you have a sleep task that has reached the sleep time and ended\r\n- the leadership election takes place, a new leader gets elected\r\n- the new leader starts task reconciliation, which means it synchronizes the local persisted state with the mesos master\r\n- at the same time the TaskTracker starts its work. It realizes that the sleep application has not enough tasks and starts a new tasks.\r\n- Mesos launches the sleep task and sends a TaskStatus\r\n- the TaskReconciliation process receives this TaskStatus and declares that Task as unknown (since there is no Reference from the last leader). In that case the TaskReconciliation process will kill the unknown task.\r\n- The TaskReconciliation process finishes\r\n- The TaskTracker again realizes, that there are not enough tasks for the application and starts another one \r\n\r\nThat said: you should see this problem (and the logs prove that) only for lost tasks and a new leader election  (e.g. task yhttpd is not killed and restarted). The title of this ticket is somewhat more drastic, so I want to make sure, we are on the same page. \r\n\r\nCan you acknowledge this observation?\r\n"}}