Skip to content

Instantly share code, notes, and snippets.

@kolloch

kolloch/gist:081b41bb8dbbd23223fb

Created June 15, 2015 15:31
Show Gist options
  • Save kolloch/081b41bb8dbbd23223fb to your computer and use it in GitHub Desktop.
Save kolloch/081b41bb8dbbd23223fb to your computer and use it in GitHub Desktop.
Download ZIP
Log file of failing integration test
Raw
gistfile1.txt
[16:23:43][Step 3/3] Test Starting - GroupDeployIntegrationTest: update a group with applications to restart
[16:23:43][Step 3/3] [2015-06-15 14:29:13,498] INFO marathon: [2015-06-15 14:29:13,498] INFO Upgrade id:/marathonintegrationtest/test version:2015-06-15T14:29:13.497Z with force:false (mesosphere.marathon.state.GroupManager:124) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,500] INFO marathon: [2015-06-15 14:29:13,500] INFO Take next configured free port: 10000 (mesosphere.marathon.state.GroupManager:186) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,504] INFO marathon: [2015-06-15 14:29:13,504] INFO Compute DeploymentPlan from Group(/,Set(),Set(),Set(),2015-06-15T14:29:13.254Z) to Group(/,Set(),Set(Group(/marathonintegrationtest,Set(),Set(Group(/marathonintegrationtest/test,Set(AppDefinition(/marathonintegrationtest/test/app,Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1),None,None,Map(),2,0.5,128.0,0.0,//cmd,Set(),List(),List(),List(10000),false,1 second,1.15,3600 seconds,None,Set(),Set(),UpgradeStrategy(1.0,1.0),Map(),None,2015-06-15T14:29:13.497Z)),Set(),Set(),2015-06-15T14:29:13.497Z)),Set(),2015-06-15T14:29:13.497Z)),Set(),2015-06-15T14:29:13.497Z) (mesosphere.marathon.upgrade.DeploymentPlan$:211) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,505] INFO marathon: [2015-06-15 14:29:13,505] INFO Computed new deployment plan: DeploymentPlan(2015-06-15T14:29:13.497Z, (Step(Vector(Start(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 0))), Step(Vector(Scale(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 2))))) (mesosphere.marathon.upgrade.DeploymentPlan$:265) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,505] INFO marathon: [2015-06-15 14:29:13,505] INFO Deploy plan:DeploymentPlan(2015-06-15T14:29:13.497Z, (Step(Vector(Start(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 0))), Step(Vector(Scale(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 2))))) with force:false (mesosphere.marathon.MarathonSchedulerService:104) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,513] INFO marathon: [2015-06-15 14:29:13,512] INFO Compute DeploymentPlan from Group(/,Set(),Set(),Set(),2015-06-15T14:29:13.254Z) to Group(/,Set(),Set(Group(/marathonintegrationtest,Set(),Set(Group(/marathonintegrationtest/test,Set(AppDefinition(/marathonintegrationtest/test/app,Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1),None,None,Map(),2,0.5,128.0,0.0,//cmd,Set(),Vector(),Vector(),Vector(10000),false,1000 milliseconds,1.15,3600000 milliseconds,None,Set(),Set(),UpgradeStrategy(1.0,1.0),Map(),None,2015-06-15T14:29:13.497Z)),Set(),Set(),2015-06-15T14:29:13.497Z)),Set(),2015-06-15T14:29:13.497Z)),Set(),2015-06-15T14:29:13.497Z) (mesosphere.marathon.upgrade.DeploymentPlan$:211) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,514] INFO marathon: [2015-06-15 14:29:13,514] INFO Computed new deployment plan: DeploymentPlan(2015-06-15T14:29:13.497Z, (Step(Vector(Start(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 0))), Step(Vector(Scale(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 2))))) (mesosphere.marathon.upgrade.DeploymentPlan$:265) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,521] INFO marathon: [2015-06-15 14:29:13,520] INFO Compute DeploymentPlan from Group(/,Set(),Set(),Set(),2015-06-15T14:29:13.254Z) to Group(/,Set(),Set(Group(/marathonintegrationtest,Set(),Set(Group(/marathonintegrationtest/test,Set(AppDefinition(/marathonintegrationtest/test/app,Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1),None,None,Map(),2,0.5,128.0,0.0,//cmd,Set(),Vector(),Vector(),Vector(10000),false,1000 milliseconds,1.15,3600000 milliseconds,None,Set(),Set(),UpgradeStrategy(1.0,1.0),Map(),None,2015-06-15T14:29:13.497Z)),Set(),Set(),2015-06-15T14:29:13.497Z)),Set(),2015-06-15T14:29:13.497Z)),Set(),2015-06-15T14:29:13.497Z) (mesosphere.marathon.upgrade.DeploymentPlan$:211) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,521] INFO marathon: [2015-06-15 14:29:13,521] INFO Deployment acknowledged. Waiting to get processed: DeploymentPlan(2015-06-15T14:29:13.497Z, (Step(Vector(Start(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 0))), Step(Vector(Scale(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 2))))) (mesosphere.marathon.state.GroupManager:143) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,523] INFO marathon: [INFO] [06/15/2015 14:29:13.522] [marathon-akka.actor.default-dispatcher-14] [akka://marathon/user/$b] POSTing to all endpoints. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,523] INFO marathon: [2015-06-15 14:29:13,522] INFO 127.0.0.1 - - [15/Jun/2015:14:29:13 +0000] "POST /v2/groups HTTP/1.1" 201 92 "-" "spray-can/1.3.2" (mesosphere.chaos.http.ChaosRequestLog:15) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,524] INFO marathon: [2015-06-15 14:29:13,523] INFO Computed new deployment plan: DeploymentPlan(2015-06-15T14:29:13.497Z, (Step(Vector(Start(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 0))), Step(Vector(Scale(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1))), 2))))) (mesosphere.marathon.upgrade.DeploymentPlan$:265) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,526] INFO marathon: [INFO] [06/15/2015 14:29:13.525] [pool-2-thread-3] [akka://marathon/user/$b] Sending POST to:http://localhost:11253/callback (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,527] INFO marathon: [INFO] [06/15/2015 14:29:13.527] [marathon-akka.actor.default-dispatcher-5] [akka://marathon/user/$b] POSTing to all endpoints. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,529] INFO Received callback event: group_change_success with props Map(groupId -> /marathonintegrationtest/test, version -> 2015-06-15T14:29:13.497Z, eventType -> group_change_success, timestamp -> 2015-06-15T14:29:13.522Z) (mesosphere.marathon.integration.setup.CallbackEventHandler:118)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,529] INFO 127.0.0.1 - - [15/Jun/2015:14:29:13 +0000] "POST /callback HTTP/1.1" 204 0 "-" "spray-can/1.3.2" (mesosphere.chaos.http.ChaosRequestLog:15)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,529] INFO marathon: [INFO] [06/15/2015 14:29:13.529] [pool-2-thread-3] [akka://marathon/user/$b] Sending POST to:http://localhost:11253/callback (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,539] INFO marathon: [INFO] [06/15/2015 14:29:13.539] [marathon-akka.actor.default-dispatcher-3] [akka://marathon/user/MarathonScheduler/$a/UpgradeManager/58f82280-9cf3-4145-9f27-eec4c3b12d16/$a] Successfully started 0 instances of /marathonintegrationtest/test/app (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,540] INFO marathon: [INFO] [06/15/2015 14:29:13.539] [marathon-akka.actor.default-dispatcher-4] [akka://marathon/user/$b] POSTing to all endpoints. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,540] INFO marathon: [INFO] [06/15/2015 14:29:13.539] [marathon-akka.actor.default-dispatcher-12] [akka://marathon/user/$b] POSTing to all endpoints. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,548] INFO marathon: [INFO] [06/15/2015 14:29:13.544] [pool-2-thread-3] [akka://marathon/user/$b] Sending POST to:http://localhost:11253/callback (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,548] INFO marathon: [INFO] [06/15/2015 14:29:13.544] [pool-2-thread-4] [akka://marathon/user/$b] Sending POST to:http://localhost:11253/callback (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,558] INFO marathon: [2015-06-15 14:29:13,558] DEBUG Fetching app from store /marathonintegrationtest/test/app (mesosphere.marathon.tasks.TaskTracker:186) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,597] INFO Received callback event: deployment_info with props Map(plan -> Map(version -> 2015-06-15T14:29:13.497Z, id -> 58f82280-9cf3-4145-9f27-eec4c3b12d16, target -> Map(groups -> List(Map(groups -> List(Map(groups -> List(), version -> 2015-06-15T14:29:13.497Z, id -> /marathonintegrationtest/test, dependencies -> List(), apps -> List(Map(storeUrls -> List(), requirePorts -> false, disk -> 0.0, acceptedResourceRoles -> null, instances -> 2, container -> null, ports -> List(10000), cmd -> /tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1, uris -> List(), healthChecks -> List(), version -> 2015-06-15T14:29:13.497Z, id -> /marathonintegrationtest/test/app, backoffFactor -> 1.15, labels -> Map(), constraints -> List(), mem -> 128.0, cpus -> 0.5, upgradeStrategy -> Map(minimumHealthCapacity -> 1.0, maximumOverCapacity -> 1.0), args -> null, maxLaunchDelaySeconds -> 3600, executor -> //cmd, dependencies -> List(), user -> null, env -> Map(), backoffSeconds -> 1)))), version -> 2015-06-15T14:29:13.497Z, id -> /marathonintegrationtest, dependencies -> List(), apps -> List())), version -> 2015-06-15T14:29:13.497Z, id -> /, dependencies -> List(), apps -> List()), original -> Map(groups -> List(), version -> 2015-06-15T14:29:13.254Z, id -> /, dependencies -> List(), apps -> List()), steps -> List(Map(actions -> List(Map(type -> StartApplication, app -> /marathonintegrationtest/test/app))), Map(actions -> List(Map(type -> ScaleApplication, app -> /marathonintegrationtest/test/app))))), currentStep -> Map(actions -> List(Map(type -> StartApplication, app -> /marathonintegrationtest/test/app))), eventType -> deployment_info, timestamp -> 2015-06-15T14:29:13.527Z) (mesosphere.marathon.integration.setup.CallbackEventHandler:118)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,597] INFO 127.0.0.1 - - [15/Jun/2015:14:29:13 +0000] "POST /callback HTTP/1.1" 204 0 "-" "spray-can/1.3.2" (mesosphere.chaos.http.ChaosRequestLog:15)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,601] INFO Received callback event: deployment_info with props Map(plan -> Map(version -> 2015-06-15T14:29:13.497Z, id -> 58f82280-9cf3-4145-9f27-eec4c3b12d16, target -> Map(groups -> List(Map(groups -> List(Map(groups -> List(), version -> 2015-06-15T14:29:13.497Z, id -> /marathonintegrationtest/test, dependencies -> List(), apps -> List(Map(storeUrls -> List(), requirePorts -> false, disk -> 0.0, acceptedResourceRoles -> null, instances -> 2, container -> null, ports -> List(10000), cmd -> /tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1, uris -> List(), healthChecks -> List(), version -> 2015-06-15T14:29:13.497Z, id -> /marathonintegrationtest/test/app, backoffFactor -> 1.15, labels -> Map(), constraints -> List(), mem -> 128.0, cpus -> 0.5, upgradeStrategy -> Map(minimumHealthCapacity -> 1.0, maximumOverCapacity -> 1.0), args -> null, maxLaunchDelaySeconds -> 3600, executor -> //cmd, dependencies -> List(), user -> null, env -> Map(), backoffSeconds -> 1)))), version -> 2015-06-15T14:29:13.497Z, id -> /marathonintegrationtest, dependencies -> List(), apps -> List())), version -> 2015-06-15T14:29:13.497Z, id -> /, dependencies -> List(), apps -> List()), original -> Map(groups -> List(), version -> 2015-06-15T14:29:13.254Z, id -> /, dependencies -> List(), apps -> List()), steps -> List(Map(actions -> List(Map(type -> StartApplication, app -> /marathonintegrationtest/test/app))), Map(actions -> List(Map(type -> ScaleApplication, app -> /marathonintegrationtest/test/app))))), currentStep -> Map(actions -> List(Map(type -> ScaleApplication, app -> /marathonintegrationtest/test/app))), eventType -> deployment_info, timestamp -> 2015-06-15T14:29:13.539Z) (mesosphere.marathon.integration.setup.CallbackEventHandler:118)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,601] INFO 127.0.0.1 - - [15/Jun/2015:14:29:13 +0000] "POST /callback HTTP/1.1" 204 0 "-" "spray-can/1.3.2" (mesosphere.chaos.http.ChaosRequestLog:15)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,611] INFO Received callback event: deployment_step_success with props Map(plan -> Map(version -> 2015-06-15T14:29:13.497Z, id -> 58f82280-9cf3-4145-9f27-eec4c3b12d16, target -> Map(groups -> List(Map(groups -> List(Map(groups -> List(), version -> 2015-06-15T14:29:13.497Z, id -> /marathonintegrationtest/test, dependencies -> List(), apps -> List(Map(storeUrls -> List(), requirePorts -> false, disk -> 0.0, acceptedResourceRoles -> null, instances -> 2, container -> null, ports -> List(10000), cmd -> /tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1, uris -> List(), healthChecks -> List(), version -> 2015-06-15T14:29:13.497Z, id -> /marathonintegrationtest/test/app, backoffFactor -> 1.15, labels -> Map(), constraints -> List(), mem -> 128.0, cpus -> 0.5, upgradeStrategy -> Map(minimumHealthCapacity -> 1.0, maximumOverCapacity -> 1.0), args -> null, maxLaunchDelaySeconds -> 3600, executor -> //cmd, dependencies -> List(), user -> null, env -> Map(), backoffSeconds -> 1)))), version -> 2015-06-15T14:29:13.497Z, id -> /marathonintegrationtest, dependencies -> List(), apps -> List())), version -> 2015-06-15T14:29:13.497Z, id -> /, dependencies -> List(), apps -> List()), original -> Map(groups -> List(), version -> 2015-06-15T14:29:13.254Z, id -> /, dependencies -> List(), apps -> List()), steps -> List(Map(actions -> List(Map(type -> StartApplication, app -> /marathonintegrationtest/test/app))), Map(actions -> List(Map(type -> ScaleApplication, app -> /marathonintegrationtest/test/app))))), currentStep -> Map(actions -> List(Map(type -> StartApplication, app -> /marathonintegrationtest/test/app))), eventType -> deployment_step_success, timestamp -> 2015-06-15T14:29:13.539Z) (mesosphere.marathon.integration.setup.CallbackEventHandler:118)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,611] INFO 127.0.0.1 - - [15/Jun/2015:14:29:13 +0000] "POST /callback HTTP/1.1" 204 0 "-" "spray-can/1.3.2" (mesosphere.chaos.http.ChaosRequestLog:15)
[16:23:43][Step 3/3] [2015-06-15 14:29:13,814] INFO marathon: [INFO] [06/15/2015 14:29:13.814] [marathon-akka.actor.default-dispatcher-4] [akka://marathon/user/MarathonScheduler/$a/UpgradeManager/85e09b78-ecbb-4df5-91e1-5b29f3a4da13/$b] Message [mesosphere.marathon.upgrade.StartingBehavior$Sync$] from Actor[akka://marathon/user/MarathonScheduler/$a/UpgradeManager/85e09b78-ecbb-4df5-91e1-5b29f3a4da13/$b#-1650820777] to Actor[akka://marathon/user/MarathonScheduler/$a/UpgradeManager/85e09b78-ecbb-4df5-91e1-5b29f3a4da13/$b#-1650820777] was not delivered. [3] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:13,994] INFO mesos: I0615 14:29:13.993948 2146 master.cpp:3760] Sending 1 offers to framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:13,998] INFO marathon: [2015-06-15 14:29:13,998] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:13,998] INFO marathon: [2015-06-15 14:29:13,998] DEBUG processing 1 hot offers (mesosphere.marathon.tasks.IterativeOfferMatcher$:166) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:13,999] INFO marathon: [2015-06-15 14:29:13,999] DEBUG try matching offer = cpus 4.0; mem 14015.0; disk 32541.0; ports 31000->32000 (mesosphere.marathon.tasks.IterativeOfferMatcher$:133) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,000] INFO marathon: [2015-06-15 14:29:13,999] DEBUG newTask (mesosphere.marathon.tasks.DefaultTaskFactory:26) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,004] INFO marathon: [2015-06-15 14:29:14,003] DEBUG Adding task for launching (999 tasks left in cycle): name: "app.test.marathonintegrationtest" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,004] INFO marathon: task_id { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,004] INFO marathon: value: "marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,004] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,004] INFO marathon: slave_id { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,004] INFO marathon: value: "20150615-142854-16777343-5050-2138-S0" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: resources { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: name: "cpus" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: type: SCALAR (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: scalar { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: value: 0.5 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: role: "*" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: resources { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: name: "mem" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: type: SCALAR (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: scalar { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: value: 128.0 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,005] INFO marathon: role: "*" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO marathon: resources { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO marathon: name: "ports" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO marathon: type: RANGES (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO marathon: ranges { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO marathon: range { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO marathon: begin: 31823 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO mesos: I0615 14:29:14.006360 2144 master.cpp:2273] Processing ACCEPT call for offers: [ 20150615-142854-16777343-5050-2138-O3 ] on slave 20150615-142854-16777343-5050-2138-S0 at slave(1)@127.0.0.1:5050 (localhost) for framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO marathon: end: 31823 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO mesos: I0615 14:29:14.006806 2147 master.hpp:822] Adding task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 with resources cpus(*):0.5; mem(*):128; ports(*):[31823-31823] on slave 20150615-142854-16777343-5050-2138-S0 (localhost) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,007] INFO mesos: I0615 14:29:14.006853 2147 master.cpp:2550] Launching task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 with resources cpus(*):0.5; mem(*):128; ports(*):[31823-31823] on slave 20150615-142854-16777343-5050-2138-S0 at slave(1)@127.0.0.1:5050 (localhost) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,007] INFO mesos: I0615 14:29:14.006995 2148 slave.cpp:1144] Got assigned task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 for framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,007] INFO mesos: I0615 14:29:14.006986 2147 hierarchical.hpp:648] Recovered cpus(*):3.5; mem(*):13887; disk(*):32541; ports(*):[31000-31822, 31824-32000] (total allocatable: cpus(*):3.5; mem(*):13887; disk(*):32541; ports(*):[31000-31822, 31824-32000]) on slave 20150615-142854-16777343-5050-2138-S0 from framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,006] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,007] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,007] INFO marathon: role: "*" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,007] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,007] INFO marathon: command { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,008] INFO mesos: I0615 14:29:14.007850 2148 slave.cpp:1254] Launching task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 for framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,008] INFO marathon: environment { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,008] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,008] INFO marathon: name: "MARATHON_APP_VERSION" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,008] INFO marathon: value: "2015-06-15T14:29:13.497Z" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,009] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,009] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,009] INFO marathon: name: "HOST" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,009] INFO marathon: value: "localhost" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,009] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,010] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,010] INFO marathon: name: "PORT_10000" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,010] INFO marathon: value: "31823" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,010] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,010] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,011] INFO marathon: name: "MESOS_TASK_ID" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,011] INFO marathon: value: "marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,011] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,011] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,011] INFO marathon: name: "PORT" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,011] INFO marathon: value: "31823" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,011] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,011] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,012] INFO marathon: name: "PORTS" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,012] INFO marathon: value: "31823" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,012] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,012] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,012] INFO marathon: name: "MARATHON_APP_ID" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,012] INFO marathon: value: "/marathonintegrationtest/test/app" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,012] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,012] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,012] INFO marathon: name: "PORT0" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,013] INFO marathon: value: "31823" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,013] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,013] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,013] INFO marathon: value: "/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,013] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,013] INFO marathon: (mesosphere.marathon.tasks.IterativeOfferMatcher$:147) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,013] INFO marathon: [2015-06-15 14:29:14,004] DEBUG used resources cpus 0.5; mem 128.0; ports 31823->31823 (mesosphere.marathon.tasks.IterativeOfferMatcher$:83) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,013] INFO marathon: [2015-06-15 14:29:14,004] DEBUG for offer value: "20150615-142854-16777343-5050-2138-O3" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,013] INFO marathon: launch tasks marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 (mesosphere.marathon.tasks.IterativeOfferMatcher$:199) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,014] INFO marathon: [2015-06-15 14:29:14,005] INFO Launched 1 tasks on 1 offers, declining 0 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,017] INFO mesos: I0615 14:29:14.017400 2148 slave.cpp:4208] Launching executor marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 in work directory '/tmp/marathon-itest-mesos/0/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010/runs/17326c3d-5f52-46e7-b3f7-23d5bbfb381c' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,017] INFO mesos: I0615 14:29:14.017639 2147 containerizer.cpp:484] Starting container '17326c3d-5f52-46e7-b3f7-23d5bbfb381c' for executor 'marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010' of framework '20150615-142854-16777343-5050-2138-0000' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,018] INFO mesos: I0615 14:29:14.018055 2148 slave.cpp:1401] Queuing task 'marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010' for executor marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework '20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,020] INFO mesos: I0615 14:29:14.019975 2144 launcher.cpp:130] Forked child with pid '2313' for container '17326c3d-5f52-46e7-b3f7-23d5bbfb381c' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,020] INFO mesos: I0615 14:29:14.020851 2144 containerizer.cpp:694] Checkpointing executor's forked pid 2313 to '/tmp/marathon-itest-mesos/meta/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010/runs/17326c3d-5f52-46e7-b3f7-23d5bbfb381c/pids/forked.pid' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,021] INFO mesos: I0615 14:29:14.021832 2146 slave.cpp:3165] Monitoring executor 'marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010' of framework '20150615-142854-16777343-5050-2138-0000' in container '17326c3d-5f52-46e7-b3f7-23d5bbfb381c' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,048] INFO mesos: I0615 14:29:14.048388 2314 exec.cpp:132] Version: 0.22.1 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,049] INFO mesos: I0615 14:29:14.049573 2146 slave.cpp:2164] Got registration for executor 'marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010' of framework 20150615-142854-16777343-5050-2138-0000 from executor(1)@127.0.0.1:46282 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,050] INFO mesos: I0615 14:29:14.050403 2149 slave.cpp:1555] Sending queued task 'marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010' to executor 'marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010' of framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,051] INFO mesos: Registered executor on localhost (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,051] INFO mesos: I0615 14:29:14.050812 2322 exec.cpp:206] Executor registered on slave 20150615-142854-16777343-5050-2138-S0 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,052] INFO mesos: Starting task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,052] INFO mesos: sh -c '/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,052] INFO mesos: Forked command at 2324 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,053] INFO mesos: I0615 14:29:14.053812 2150 slave.cpp:2531] Handling status update TASK_RUNNING (UUID: 35df332c-4390-493b-ace1-1b8e68a1cf64) for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 from executor(1)@127.0.0.1:46282 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,053] INFO mesos: I0615 14:29:14.053910 2150 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: 35df332c-4390-493b-ace1-1b8e68a1cf64) for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,054] INFO mesos: I0615 14:29:14.054251 2150 status_update_manager.hpp:346] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 35df332c-4390-493b-ace1-1b8e68a1cf64) for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,056] INFO mesos: I0615 14:29:14.056396 2147 slave.cpp:2776] Forwarding the update TASK_RUNNING (UUID: 35df332c-4390-493b-ace1-1b8e68a1cf64) for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 to master@127.0.0.1:5050 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,056] INFO mesos: I0615 14:29:14.056453 2147 slave.cpp:2709] Sending acknowledgement for status update TASK_RUNNING (UUID: 35df332c-4390-493b-ace1-1b8e68a1cf64) for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 to executor(1)@127.0.0.1:46282 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,056] INFO mesos: I0615 14:29:14.056499 2150 master.cpp:3300] Status update TASK_RUNNING (UUID: 35df332c-4390-493b-ace1-1b8e68a1cf64) for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 from slave 20150615-142854-16777343-5050-2138-S0 at slave(1)@127.0.0.1:5050 (localhost) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,056] INFO mesos: I0615 14:29:14.056521 2150 master.cpp:3341] Forwarding status update TASK_RUNNING (UUID: 35df332c-4390-493b-ace1-1b8e68a1cf64) for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,056] INFO mesos: I0615 14:29:14.056592 2150 master.cpp:4623] Updating the latest state of task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 to TASK_RUNNING (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,058] INFO marathon: [2015-06-15 14:29:14,058] INFO Received status update for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010: TASK_RUNNING () (mesosphere.marathon.MarathonScheduler:96) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,061] INFO mesos: I0615 14:29:14.061604 2147 master.cpp:2787] Forwarding status update acknowledgement 35df332c-4390-493b-ace1-1b8e68a1cf64 for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 to slave 20150615-142854-16777343-5050-2138-S0 at slave(1)@127.0.0.1:5050 (localhost) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,061] INFO mesos: I0615 14:29:14.061679 2147 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 35df332c-4390-493b-ace1-1b8e68a1cf64) for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,061] INFO mesos: I0615 14:29:14.061702 2147 status_update_manager.hpp:346] Checkpointing ACK for status update TASK_RUNNING (UUID: 35df332c-4390-493b-ace1-1b8e68a1cf64) for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,063] INFO marathon: [2015-06-15 14:29:14,063] INFO Sending event notification. (mesosphere.marathon.MarathonScheduler:203) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,064] INFO marathon: [INFO] [06/15/2015 14:29:14.064] [marathon-akka.actor.default-dispatcher-13] [akka://marathon/user/$b] POSTing to all endpoints. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,065] INFO marathon: [INFO] [06/15/2015 14:29:14.064] [marathon-akka.actor.default-dispatcher-3] [akka://marathon/user/MarathonScheduler/$a/UpgradeManager/58f82280-9cf3-4145-9f27-eec4c3b12d16/$b] New task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010 now running during app /marathonintegrationtest/test/app scaling, 1 more to go (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,070] INFO marathon: [INFO] [06/15/2015 14:29:14.068] [pool-2-thread-3] [akka://marathon/user/$b] Sending POST to:http://localhost:11253/callback (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,073] INFO Received callback event: status_update_event with props Map(eventType -> status_update_event, timestamp -> 2015-06-15T14:29:14.064Z, host -> localhost, slaveId -> 20150615-142854-16777343-5050-2138-S0, ports -> List(31823), version -> 2015-06-15T14:29:13.497Z, taskStatus -> TASK_RUNNING, message -> , appId -> /marathonintegrationtest/test/app, taskId -> marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010) (mesosphere.marathon.integration.setup.CallbackEventHandler:118)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,074] INFO 127.0.0.1 - - [15/Jun/2015:14:29:14 +0000] "POST /callback HTTP/1.1" 204 0 "-" "spray-can/1.3.2" (mesosphere.chaos.http.ChaosRequestLog:15)
[16:23:44][Step 3/3] 2015-06-15 14:29:14,302:463(0x7fc5a7997700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:2186] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
[16:23:44][Step 3/3] [2015-06-15 14:29:14,426] INFO mesos: I0615 14:29:14.425982 2145 containerizer.cpp:1123] Executor for container '2923047a-9d3b-4406-a73f-cf82dce96591' has exited (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,426] INFO mesos: I0615 14:29:14.426018 2145 containerizer.cpp:918] Destroying container '2923047a-9d3b-4406-a73f-cf82dce96591' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,428] INFO mesos: I0615 14:29:14.427973 2145 containerizer.cpp:1123] Executor for container 'ee166365-6eac-49bf-ace6-c9c8e835c6fb' has exited (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,428] INFO mesos: I0615 14:29:14.427997 2145 containerizer.cpp:918] Destroying container 'ee166365-6eac-49bf-ace6-c9c8e835c6fb' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,430] INFO mesos: I0615 14:29:14.430035 2149 slave.cpp:3223] Executor 'marathonintegrationtest_test_app.e1311788-136a-11e5-a6f2-0242ac110010' of framework 20150615-142854-16777343-5050-2138-0000 exited with status 0 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,430] INFO mesos: I0615 14:29:14.430120 2149 slave.cpp:3332] Cleaning up executor 'marathonintegrationtest_test_app.e1311788-136a-11e5-a6f2-0242ac110010' of framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,430] INFO mesos: I0615 14:29:14.430379 2145 gc.cpp:56] Scheduling '/tmp/marathon-itest-mesos/0/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e1311788-136a-11e5-a6f2-0242ac110010/runs/2923047a-9d3b-4406-a73f-cf82dce96591' for gc 6.99999501928days in the future (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,430] INFO mesos: I0615 14:29:14.430608 2145 gc.cpp:56] Scheduling '/tmp/marathon-itest-mesos/0/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e1311788-136a-11e5-a6f2-0242ac110010' for gc 6.9999950170963days in the future (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,430] INFO mesos: I0615 14:29:14.430651 2145 gc.cpp:56] Scheduling '/tmp/marathon-itest-mesos/0/meta/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e1311788-136a-11e5-a6f2-0242ac110010/runs/2923047a-9d3b-4406-a73f-cf82dce96591' for gc 6.99999501638815days in the future (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,430] INFO mesos: I0615 14:29:14.430729 2149 slave.cpp:3223] Executor 'marathonintegrationtest_test_app.e4c14329-136a-11e5-a6f2-0242ac110010' of framework 20150615-142854-16777343-5050-2138-0000 exited with status 0 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,431] INFO mesos: I0615 14:29:14.430768 2149 slave.cpp:3332] Cleaning up executor 'marathonintegrationtest_test_app.e4c14329-136a-11e5-a6f2-0242ac110010' of framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,431] INFO mesos: I0615 14:29:14.431249 2145 gc.cpp:56] Scheduling '/tmp/marathon-itest-mesos/0/meta/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e1311788-136a-11e5-a6f2-0242ac110010' for gc 6.99999501502222days in the future (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,431] INFO mesos: I0615 14:29:14.431288 2145 gc.cpp:56] Scheduling '/tmp/marathon-itest-mesos/0/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e4c14329-136a-11e5-a6f2-0242ac110010/runs/ee166365-6eac-49bf-ace6-c9c8e835c6fb' for gc 6.9999950118163days in the future (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,431] INFO mesos: I0615 14:29:14.431314 2145 gc.cpp:56] Scheduling '/tmp/marathon-itest-mesos/0/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e4c14329-136a-11e5-a6f2-0242ac110010' for gc 6.99999501026667days in the future (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,431] INFO mesos: I0615 14:29:14.431340 2145 gc.cpp:56] Scheduling '/tmp/marathon-itest-mesos/0/meta/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e4c14329-136a-11e5-a6f2-0242ac110010/runs/ee166365-6eac-49bf-ace6-c9c8e835c6fb' for gc 6.99999500950222days in the future (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:44][Step 3/3] [2015-06-15 14:29:14,431] INFO mesos: I0615 14:29:14.431357 2145 gc.cpp:56] Scheduling '/tmp/marathon-itest-mesos/0/meta/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e4c14329-136a-11e5-a6f2-0242ac110010' for gc 6.99999500794963days in the future (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:45][Step 3/3] [2015-06-15 14:29:15,273] INFO mesos: [2015-06-15 14:29:15,271] INFO jetty-8.1.15.v20140411 (org.eclipse.jetty.server.Server:272) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:45][Step 3/3] [2015-06-15 14:29:15,307] INFO mesos: [2015-06-15 14:29:15,306] INFO Started SelectChannelConnector@0.0.0.0:31823 (org.eclipse.jetty.server.AbstractConnector:338) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:45][Step 3/3] [2015-06-15 14:29:15,309] INFO mesos: AppMock[/marathonintegrationtest/test/app v1]: has taken the stage at port 31823. Will query http://localhost:11253/health/marathonintegrationtest/test/app/v1/31823 for health status. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,977] INFO marathon: [2015-06-15 14:29:15,977] INFO Syncing tasks for all apps (mesosphere.marathon.SchedulerActions:465) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,978] INFO marathon: [INFO] [06/15/2015 14:29:15.977] [marathon-akka.actor.default-dispatcher-11] [akka://marathon/deadLetters] Message [mesosphere.marathon.MarathonSchedulerActor$TasksReconciled$] from Actor[akka://marathon/user/MarathonScheduler/$a#1289091812] to Actor[akka://marathon/deadLetters] was not delivered. [4] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,981] INFO marathon: [2015-06-15 14:29:15,981] INFO Requesting task reconciliation with the Mesos master (mesosphere.marathon.SchedulerActions:490) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,985] INFO marathon: [2015-06-15 14:29:15,984] DEBUG Tasks to reconcile: Set(task_id { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,985] INFO marathon: value: "marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,985] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,985] INFO marathon: state: TASK_RUNNING (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,985] INFO marathon: slave_id { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,986] INFO marathon: value: "20150615-142854-16777343-5050-2138-S0" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,986] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,987] INFO marathon: timestamp: 1.434378554052749E9 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,987] INFO marathon: source: SOURCE_EXECUTOR (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,987] INFO marathon: uuid: "5\3373,C\220I;\254\341\033\216h\241\317d" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,987] INFO marathon: ) (mesosphere.marathon.SchedulerActions:491) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,989] INFO mesos: I0615 14:29:15.989006 2143 master.cpp:3522] Performing explicit task state reconciliation for 1 tasks of framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,990] INFO marathon: [2015-06-15 14:29:15,990] INFO Received status update for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:96) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,995] INFO mesos: I0615 14:29:15.990206 2143 master.cpp:3461] Performing implicit task state reconciliation for framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,997] INFO marathon: [2015-06-15 14:29:15,997] DEBUG Ignoring status for [marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010] with no health information (mesosphere.marathon.health.MarathonHealthCheckManager:169) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,997] INFO marathon: [2015-06-15 14:29:15,997] DEBUG Ignoring status update for marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010. Status did not change. (mesosphere.marathon.tasks.TaskTracker:144) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:15,999] INFO marathon: [2015-06-15 14:29:15,998] INFO Received status update for task marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010: TASK_RUNNING (Reconciliation: Latest task state) (mesosphere.marathon.MarathonScheduler:96) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:16,001] INFO marathon: [2015-06-15 14:29:16,000] DEBUG Ignoring status for [marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010] with no health information (mesosphere.marathon.health.MarathonHealthCheckManager:169) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:46][Step 3/3] [2015-06-15 14:29:16,001] INFO marathon: [2015-06-15 14:29:16,001] DEBUG Ignoring status update for marathonintegrationtest_test_app.e55a00ba-136a-11e5-a6f2-0242ac110010. Status did not change. (mesosphere.marathon.tasks.TaskTracker:144) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:48][Step 3/3] [2015-06-15 14:29:18,554] INFO marathon: [INFO] [06/15/2015 14:29:18.554] [marathon-akka.actor.default-dispatcher-3] [akka://marathon/user/MarathonScheduler/$a/UpgradeManager/58f82280-9cf3-4145-9f27-eec4c3b12d16/$a] Message [mesosphere.marathon.upgrade.StartingBehavior$Sync$] from Actor[akka://marathon/user/MarathonScheduler/$a/UpgradeManager/58f82280-9cf3-4145-9f27-eec4c3b12d16/$a#-2073040383] to Actor[akka://marathon/user/MarathonScheduler/$a/UpgradeManager/58f82280-9cf3-4145-9f27-eec4c3b12d16/$a#-2073040383] was not delivered. [5] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:19,998] INFO mesos: I0615 14:29:19.998450 2149 master.cpp:3760] Sending 1 offers to framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,002] INFO marathon: [2015-06-15 14:29:20,002] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,003] INFO marathon: [2015-06-15 14:29:20,002] DEBUG processing 1 hot offers (mesosphere.marathon.tasks.IterativeOfferMatcher$:166) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,003] INFO marathon: [2015-06-15 14:29:20,003] DEBUG try matching offer = cpus 3.5; mem 13887.0; disk 32541.0; ports 31000->31822,31824->32000 (mesosphere.marathon.tasks.IterativeOfferMatcher$:133) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,003] INFO marathon: [2015-06-15 14:29:20,003] DEBUG newTask (mesosphere.marathon.tasks.DefaultTaskFactory:26) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,007] INFO marathon: [2015-06-15 14:29:20,007] DEBUG Adding task for launching (999 tasks left in cycle): name: "app.test.marathonintegrationtest" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,007] INFO marathon: task_id { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,007] INFO marathon: value: "marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: slave_id { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: value: "20150615-142854-16777343-5050-2138-S0" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: resources { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: name: "cpus" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: type: SCALAR (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: scalar { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: value: 0.5 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: role: "*" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,008] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: resources { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: name: "mem" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: type: SCALAR (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: scalar { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: value: 128.0 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: role: "*" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: resources { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: name: "ports" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: type: RANGES (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: ranges { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: range { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,009] INFO marathon: begin: 31942 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO marathon: end: 31942 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO mesos: I0615 14:29:20.009991 2145 master.cpp:2273] Processing ACCEPT call for offers: [ 20150615-142854-16777343-5050-2138-O4 ] on slave 20150615-142854-16777343-5050-2138-S0 at slave(1)@127.0.0.1:5050 (localhost) for framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO marathon: role: "*" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO mesos: I0615 14:29:20.010409 2144 master.hpp:822] Adding task marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010 with resources cpus(*):0.5; mem(*):128; ports(*):[31942-31942] on slave 20150615-142854-16777343-5050-2138-S0 (localhost) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO mesos: I0615 14:29:20.010478 2144 master.cpp:2550] Launching task marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 with resources cpus(*):0.5; mem(*):128; ports(*):[31942-31942] on slave 20150615-142854-16777343-5050-2138-S0 at slave(1)@127.0.0.1:5050 (localhost) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO marathon: command { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO marathon: environment { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,010] INFO mesos: I0615 14:29:20.010613 2144 slave.cpp:1144] Got assigned task marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010 for framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,011] INFO mesos: I0615 14:29:20.010715 2143 hierarchical.hpp:648] Recovered cpus(*):3; mem(*):13759; disk(*):32541; ports(*):[31000-31822, 31824-31941, 31943-32000] (total allocatable: cpus(*):3; mem(*):13759; disk(*):32541; ports(*):[31000-31822, 31824-31941, 31943-32000]) on slave 20150615-142854-16777343-5050-2138-S0 from framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,011] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,011] INFO marathon: name: "MARATHON_APP_VERSION" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,011] INFO mesos: I0615 14:29:20.010967 2144 slave.cpp:1254] Launching task marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010 for framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,011] INFO marathon: value: "2015-06-15T14:29:13.497Z" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,012] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,012] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,012] INFO marathon: name: "HOST" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,012] INFO marathon: value: "localhost" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,012] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,012] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,012] INFO marathon: name: "PORT_10000" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: value: "31942" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: name: "MESOS_TASK_ID" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: value: "marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: name: "PORT" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: value: "31942" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,013] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: name: "PORTS" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: value: "31942" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: name: "MARATHON_APP_ID" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: value: "/marathonintegrationtest/test/app" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: variables { (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: name: "PORT0" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: value: "31942" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,014] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,015] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,015] INFO marathon: value: "/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,015] INFO marathon: } (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,015] INFO marathon: (mesosphere.marathon.tasks.IterativeOfferMatcher$:147) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,015] INFO marathon: [2015-06-15 14:29:20,008] DEBUG used resources cpus 0.5; mem 128.0; ports 31942->31942 (mesosphere.marathon.tasks.IterativeOfferMatcher$:83) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,015] INFO marathon: [2015-06-15 14:29:20,008] DEBUG for offer value: "20150615-142854-16777343-5050-2138-O4" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,015] INFO marathon: launch tasks marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010 (mesosphere.marathon.tasks.IterativeOfferMatcher$:199) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,015] INFO marathon: [2015-06-15 14:29:20,009] INFO Launched 1 tasks on 1 offers, declining 0 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,018] INFO mesos: I0615 14:29:20.018270 2144 slave.cpp:4208] Launching executor marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010 of framework 20150615-142854-16777343-5050-2138-0000 in work directory '/tmp/marathon-itest-mesos/0/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010/runs/487971d3-4d6d-4019-9bf9-c9dc1f64be6f' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,020] INFO mesos: I0615 14:29:20.018484 2149 containerizer.cpp:484] Starting container '487971d3-4d6d-4019-9bf9-c9dc1f64be6f' for executor 'marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010' of framework '20150615-142854-16777343-5050-2138-0000' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,020] INFO mesos: I0615 14:29:20.019078 2144 slave.cpp:1401] Queuing task 'marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010' for executor marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010 of framework '20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,021] INFO mesos: I0615 14:29:20.019487 2149 launcher.cpp:130] Forked child with pid '2353' for container '487971d3-4d6d-4019-9bf9-c9dc1f64be6f' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,021] INFO mesos: I0615 14:29:20.020301 2149 containerizer.cpp:694] Checkpointing executor's forked pid 2353 to '/tmp/marathon-itest-mesos/meta/slaves/20150615-142854-16777343-5050-2138-S0/frameworks/20150615-142854-16777343-5050-2138-0000/executors/marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010/runs/487971d3-4d6d-4019-9bf9-c9dc1f64be6f/pids/forked.pid' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,021] INFO mesos: I0615 14:29:20.021308 2149 slave.cpp:3165] Monitoring executor 'marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010' of framework '20150615-142854-16777343-5050-2138-0000' in container '487971d3-4d6d-4019-9bf9-c9dc1f64be6f' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,046] INFO mesos: I0615 14:29:20.045941 2354 exec.cpp:132] Version: 0.22.1 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,047] INFO mesos: I0615 14:29:20.047132 2143 slave.cpp:2164] Got registration for executor 'marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010' of framework 20150615-142854-16777343-5050-2138-0000 from executor(1)@127.0.0.1:58225 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,047] INFO mesos: I0615 14:29:20.047945 2149 slave.cpp:1555] Sending queued task 'marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010' to executor 'marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010' of framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,048] INFO mesos: I0615 14:29:20.048224 2362 exec.cpp:206] Executor registered on slave 20150615-142854-16777343-5050-2138-S0 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,049] INFO mesos: Registered executor on localhost (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,050] INFO mesos: Starting task marathonintegrationtest_test_app.e8ee23fb-136a-11e5-a6f2-0242ac110010 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,050] INFO mesos: sh -c '/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1' (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:50][Step 3/3] [2015-06-15 14:29:20,050] INFO mesos: Forked command at 2364 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:51][Step 3/3] [2015-06-15 14:29:21,262] INFO mesos: [2015-06-15 14:29:21,260] INFO jetty-8.1.15.v20140411 (org.eclipse.jetty.server.Server:272) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:51][Step 3/3] [2015-06-15 14:29:21,296] INFO mesos: [2015-06-15 14:29:21,296] INFO Started SelectChannelConnector@0.0.0.0:31942 (org.eclipse.jetty.server.AbstractConnector:338) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:51][Step 3/3] [2015-06-15 14:29:21,299] INFO mesos: AppMock[/marathonintegrationtest/test/app v1]: has taken the stage at port 31942. Will query http://localhost:11253/health/marathonintegrationtest/test/app/v1/31942 for health status. (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:54][Step 3/3] 2015-06-15 14:29:24,308:463(0x7fc5a7997700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:2186] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
[16:23:56][Step 3/3] [2015-06-15 14:29:26,003] INFO mesos: I0615 14:29:26.003904 2144 master.cpp:3760] Sending 1 offers to framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:56][Step 3/3] [2015-06-15 14:29:26,008] INFO marathon: [2015-06-15 14:29:26,008] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:56][Step 3/3] [2015-06-15 14:29:26,008] INFO marathon: [2015-06-15 14:29:26,008] DEBUG processing 1 hot offers (mesosphere.marathon.tasks.IterativeOfferMatcher$:166) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:56][Step 3/3] [2015-06-15 14:29:26,009] INFO marathon: [2015-06-15 14:29:26,009] DEBUG try matching offer = cpus 3.0; mem 13759.0; disk 32541.0; ports 31000->31822,31824->31941,31943->32000 (mesosphere.marathon.tasks.IterativeOfferMatcher$:133) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:56][Step 3/3] [2015-06-15 14:29:26,009] INFO marathon: [2015-06-15 14:29:26,009] DEBUG declining offer value: "20150615-142854-16777343-5050-2138-O5" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:56][Step 3/3] [2015-06-15 14:29:26,009] INFO marathon: (mesosphere.marathon.tasks.IterativeOfferMatcher$:208) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:56][Step 3/3] [2015-06-15 14:29:26,009] INFO marathon: [2015-06-15 14:29:26,009] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:56][Step 3/3] [2015-06-15 14:29:26,010] INFO mesos: I0615 14:29:26.010177 2148 master.cpp:2273] Processing ACCEPT call for offers: [ 20150615-142854-16777343-5050-2138-O5 ] on slave 20150615-142854-16777343-5050-2138-S0 at slave(1)@127.0.0.1:5050 (localhost) for framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:23:56][Step 3/3] [2015-06-15 14:29:26,010] INFO mesos: I0615 14:29:26.010361 2148 hierarchical.hpp:648] Recovered cpus(*):3; mem(*):13759; disk(*):32541; ports(*):[31000-31822, 31824-31941, 31943-32000] (total allocatable: cpus(*):3; mem(*):13759; disk(*):32541; ports(*):[31000-31822, 31824-31941, 31943-32000]) on slave 20150615-142854-16777343-5050-2138-S0 from framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:02][Step 3/3] [2015-06-15 14:29:32,008] INFO mesos: I0615 14:29:32.008157 2144 master.cpp:3760] Sending 1 offers to framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:02][Step 3/3] [2015-06-15 14:29:32,012] INFO marathon: [2015-06-15 14:29:32,012] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:02][Step 3/3] [2015-06-15 14:29:32,012] INFO marathon: [2015-06-15 14:29:32,012] DEBUG processing 1 hot offers (mesosphere.marathon.tasks.IterativeOfferMatcher$:166) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:02][Step 3/3] [2015-06-15 14:29:32,012] INFO marathon: [2015-06-15 14:29:32,012] DEBUG try matching offer = cpus 3.0; mem 13759.0; disk 32541.0; ports 31000->31822,31824->31941,31943->32000 (mesosphere.marathon.tasks.IterativeOfferMatcher$:133) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:02][Step 3/3] [2015-06-15 14:29:32,013] INFO marathon: [2015-06-15 14:29:32,013] DEBUG declining offer value: "20150615-142854-16777343-5050-2138-O6" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:02][Step 3/3] [2015-06-15 14:29:32,013] INFO marathon: (mesosphere.marathon.tasks.IterativeOfferMatcher$:208) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:02][Step 3/3] [2015-06-15 14:29:32,013] INFO marathon: [2015-06-15 14:29:32,013] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:02][Step 3/3] [2015-06-15 14:29:32,013] INFO mesos: I0615 14:29:32.013888 2143 master.cpp:2273] Processing ACCEPT call for offers: [ 20150615-142854-16777343-5050-2138-O6 ] on slave 20150615-142854-16777343-5050-2138-S0 at slave(1)@127.0.0.1:5050 (localhost) for framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:02][Step 3/3] [2015-06-15 14:29:32,014] INFO mesos: I0615 14:29:32.013995 2143 hierarchical.hpp:648] Recovered cpus(*):3; mem(*):13759; disk(*):32541; ports(*):[31000-31822, 31824-31941, 31943-32000] (total allocatable: cpus(*):3; mem(*):13759; disk(*):32541; ports(*):[31000-31822, 31824-31941, 31943-32000]) on slave 20150615-142854-16777343-5050-2138-S0 from framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:04][Step 3/3] 2015-06-15 14:29:34,318:463(0x7fc5a7997700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:2186] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
[16:24:08][Step 3/3] [2015-06-15 14:29:38,012] INFO mesos: I0615 14:29:38.012811 2143 master.cpp:3760] Sending 1 offers to framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:08][Step 3/3] [2015-06-15 14:29:38,017] INFO marathon: [2015-06-15 14:29:38,017] INFO started processing 1 offers, launching at most 1 tasks per offer and 1000 tasks in total (mesosphere.marathon.tasks.IterativeOfferMatcher$:124) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:08][Step 3/3] [2015-06-15 14:29:38,017] INFO marathon: [2015-06-15 14:29:38,017] DEBUG processing 1 hot offers (mesosphere.marathon.tasks.IterativeOfferMatcher$:166) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:08][Step 3/3] [2015-06-15 14:29:38,017] INFO marathon: [2015-06-15 14:29:38,017] DEBUG try matching offer = cpus 3.0; mem 13759.0; disk 32541.0; ports 31000->31822,31824->31941,31943->32000 (mesosphere.marathon.tasks.IterativeOfferMatcher$:133) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:08][Step 3/3] [2015-06-15 14:29:38,018] INFO marathon: [2015-06-15 14:29:38,018] DEBUG declining offer value: "20150615-142854-16777343-5050-2138-O7" (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:08][Step 3/3] [2015-06-15 14:29:38,018] INFO marathon: (mesosphere.marathon.tasks.IterativeOfferMatcher$:208) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:08][Step 3/3] [2015-06-15 14:29:38,018] INFO marathon: [2015-06-15 14:29:38,018] INFO Launched 0 tasks on 0 offers, declining 1 (mesosphere.marathon.tasks.IterativeOfferMatcher$:216) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:08][Step 3/3] [2015-06-15 14:29:38,018] INFO mesos: I0615 14:29:38.018817 2145 master.cpp:2273] Processing ACCEPT call for offers: [ 20150615-142854-16777343-5050-2138-O7 ] on slave 20150615-142854-16777343-5050-2138-S0 at slave(1)@127.0.0.1:5050 (localhost) for framework 20150615-142854-16777343-5050-2138-0000 (marathon) at scheduler-dd1ce1cb-1dcd-494b-a71d-5ee7152af64c@172.17.0.16:52590 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:08][Step 3/3] [2015-06-15 14:29:38,019] INFO mesos: I0615 14:29:38.018995 2147 hierarchical.hpp:648] Recovered cpus(*):3; mem(*):13759; disk(*):32541; ports(*):[31000-31822, 31824-31941, 31943-32000] (total allocatable: cpus(*):3; mem(*):13759; disk(*):32541; ports(*):[31000-31822, 31824-31941, 31943-32000]) on slave 20150615-142854-16777343-5050-2138-S0 from framework 20150615-142854-16777343-5050-2138-0000 (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:13][Step 3/3] [info] - update a group with applications to restart *** FAILED ***
[16:24:13][Step 3/3] [info] java.lang.AssertionError: Waiting for event deployment_success to arrive took longer than 30 seconds. Give up.
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.setup.WaitTestSupport$.next$1(WaitTestSupport.scala:30)
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.setup.WaitTestSupport$.waitFor(WaitTestSupport.scala:36)
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.setup.MarathonCallbackTestSupport$class.waitForEventMatching(MarathonCallbackTestSupport.scala:46)
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.GroupDeployIntegrationTest.waitForEventMatching(GroupDeployIntegrationTest.scala:12)
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.setup.MarathonCallbackTestSupport$class.waitForEventWith(MarathonCallbackTestSupport.scala:50)
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.GroupDeployIntegrationTest.waitForEventWith(GroupDeployIntegrationTest.scala:12)
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.setup.MarathonCallbackTestSupport$class.waitForDeploymentId(MarathonCallbackTestSupport.scala:33)
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.GroupDeployIntegrationTest.waitForDeploymentId(GroupDeployIntegrationTest.scala:12)
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.setup.MarathonCallbackTestSupport$class.waitForChange(MarathonCallbackTestSupport.scala:37)
[16:24:13][Step 3/3] [info] at mesosphere.marathon.integration.GroupDeployIntegrationTest.waitForChange(GroupDeployIntegrationTest.scala:12)
[16:24:13][Step 3/3] [info] ...
[16:24:13][Step 3/3] [info] + Given A group with one application started
[16:24:13][Step 3/3] [2015-06-15 14:29:43,587] INFO marathon: [2015-06-15 14:29:43,587] INFO Upgrade id:/ version:2015-06-15T14:29:43.586Z with force:true (mesosphere.marathon.state.GroupManager:124) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:13][Step 3/3] TEST FAILED - GroupDeployIntegrationTest: update a group with applications to restart: Waiting for event deployment_success to arrive took longer than 30 seconds. Give up. (30 seconds, 77 milliseconds)
[16:24:13][Step 3/3] java.lang.AssertionError: Waiting for event deployment_success to arrive took longer than 30 seconds. Give up.
[16:24:13][Step 3/3] at mesosphere.marathon.integration.setup.WaitTestSupport$.next$1(WaitTestSupport.scala:30)
[16:24:13][Step 3/3] at mesosphere.marathon.integration.setup.WaitTestSupport$.waitFor(WaitTestSupport.scala:36)
[16:24:13][Step 3/3] at mesosphere.marathon.integration.setup.MarathonCallbackTestSupport$class.waitForEventMatching(MarathonCallbackTestSupport.scala:46)
[16:24:13][Step 3/3] at mesosphere.marathon.integration.GroupDeployIntegrationTest.waitForEventMatching(GroupDeployIntegrationTest.scala:12)
[16:24:13][Step 3/3] at mesosphere.marathon.integration.setup.MarathonCallbackTestSupport$class.waitForEventWith(MarathonCallbackTestSupport.scala:50)
[16:24:13][Step 3/3] at mesosphere.marathon.integration.GroupDeployIntegrationTest.waitForEventWith(GroupDeployIntegrationTest.scala:12)
[16:24:13][Step 3/3] at mesosphere.marathon.integration.setup.MarathonCallbackTestSupport$class.waitForDeploymentId(MarathonCallbackTestSupport.scala:33)
[16:24:13][Step 3/3] at mesosphere.marathon.integration.GroupDeployIntegrationTest.waitForDeploymentId(GroupDeployIntegrationTest.scala:12)
[16:24:13][Step 3/3] [2015-06-15 14:29:43,594] INFO marathon: [2015-06-15 14:29:43,594] INFO Compute DeploymentPlan from Group(/,Set(),Set(Group(/marathonintegrationtest,Set(),Set(Group(/marathonintegrationtest/test,Set(AppDefinition(/marathonintegrationtest/test/app,Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1),None,None,Map(),2,0.5,128.0,0.0,//cmd,Set(),Vector(),Vector(),Vector(10000),false,1000 milliseconds,1.15,3600000 milliseconds,None,Set(),Set(),UpgradeStrategy(1.0,1.0),Map(),None,2015-06-15T14:29:13.497Z)),Set(),Set(),2015-06-15T14:29:13.497Z)),Set(),2015-06-15T14:29:13.497Z)),Set(),2015-06-15T14:29:13.497Z) to Group(/,Set(),Set(),Set(),2015-06-15T14:29:43.586Z) (mesosphere.marathon.upgrade.DeploymentPlan$:211) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:13][Step 3/3] at mesosphere.marathon.integration.setup.MarathonCallbackTestSupport$class.waitForChange(MarathonCallbackTestSupport.scala:37)
[16:24:13][Step 3/3] at mesosphere.marathon.integration.GroupDeployIntegrationTest.waitForChange(GroupDeployIntegrationTest.scala:12)
[16:24:13][Step 3/3] [2015-06-15 14:29:43,595] INFO marathon: [2015-06-15 14:29:43,595] INFO Computed new deployment plan: DeploymentPlan(2015-06-15T14:29:43.586Z, (Step(Vector(Stop(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1)))))))) (mesosphere.marathon.upgrade.DeploymentPlan$:265) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:13][Step 3/3] ...
[16:24:13][Step 3/3] Info Provided - GroupDeployIntegrationTest: update a group with applications to restart: Given A group with one application started
[16:24:13][Step 3/3] [2015-06-15 14:29:43,595] INFO marathon: [2015-06-15 14:29:43,595] INFO Deploy plan:DeploymentPlan(2015-06-15T14:29:43.586Z, (Step(Vector(Stop(App(/marathonintegrationtest/test/app, Some(/tmp/appProxy663822139930722272.sh /marathonintegrationtest/test/app v1 http://localhost:11253/health/marathonintegrationtest/test/app/v1)))))))) with force:true (mesosphere.marathon.MarathonSchedulerService:104) (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[16:24:13][Step 3/3] [2015-06-15 14:29:43,601] INFO marathon: [INFO] [06/15/2015 14:29:43.600] [marathon-akka.actor.default-dispatcher-3] [akka://marathon/user/MarathonScheduler/$a/UpgradeManager] Removing 58f82280-9cf3-4145-9f27-eec4c3b12d16 from list of running deployments (mesosphere.marathon.integration.setup.ProcessKeeper$:100)
[1
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment