[
https://issues.apache.org/jira/browse/MESOS-6164?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15543289#comment-15543289
]
Greg Mann commented on MESOS-6164:
----------------------------------
Closing this ticket, since the error seems to be due to performance issues on
the machines used for CI.
> SlaveRecoveryTest/0.ReconnectHTTPExecutor is flaky
> --------------------------------------------------
>
> Key: MESOS-6164
> URL: https://issues.apache.org/jira/browse/MESOS-6164
> Project: Mesos
> Issue Type: Bug
> Components: tests
> Affects Versions: 1.0.1
> Environment: Ubuntu 12, SSL & libevent enabled
> Reporter: Greg Mann
> Labels: mesosphere, tests
>
> This was observed on our internal CI:
> {code}
> [02:57:42] : [Step 10/10] [ RUN ]
> SlaveRecoveryTest/0.ReconnectHTTPExecutor
> [02:57:43] : [Step 10/10] Received SUBSCRIBED event
> [02:57:43] : [Step 10/10] Subscribed executor on
> ip-172-30-2-23.mesosphere.io
> [02:57:43] : [Step 10/10] Received LAUNCH event
> [02:57:43] : [Step 10/10] Starting task c1ba3f0b-2f6a-46a1-b752-592394c6d726
> [02:57:43] : [Step 10/10]
> /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer launch
> --command="{"shell":true,"value":"sleep 1000"}" --help="false"
> --unshare_namespace_mnt="false"
> [02:57:43] : [Step 10/10] Forked command at 4653
> [02:57:43] : [Step 10/10] Received ERROR event
> [02:57:43] : [Step 10/10] Received ERROR event
> [02:57:58] : [Step 10/10] ../../src/tests/slave_recovery_tests.cpp:510:
> Failure
> [02:57:58] : [Step 10/10] Failed to wait 15secs for status
> [02:57:58] : [Step 10/10] ../../src/tests/slave_recovery_tests.cpp:491:
> Failure
> [02:57:58] : [Step 10/10] Actual function call count doesn't match
> EXPECT_CALL(sched, statusUpdate(_, _))...
> [02:57:58] : [Step 10/10] Expected: to be called at least once
> [02:57:58] : [Step 10/10] Actual: never called - unsatisfied and
> active
> [02:58:13] : [Step 10/10] ../../src/tests/cluster.cpp:560: Failure
> [02:58:13] : [Step 10/10] Failed to wait 15secs for wait
> [02:59:18]W: [Step 10/10] I0915 02:57:42.726838 24222
> hierarchical.cpp:1770] No inverse offers to send out!
> [02:59:18]W: [Step 10/10] I0915 02:57:42.726851 24222
> hierarchical.cpp:1271] Performed allocation for 1 agents in 80513ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.929819 24218 slave.cpp:3521]
> Cleaning up un-reregistered executors
> [02:59:18]W: [Step 10/10] I0915 02:57:42.929872 24218 slave.cpp:5197]
> Finished recovery
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930137 24218 slave.cpp:5369]
> Querying resource estimator for oversubscribable resources
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930229 24220 slave.cpp:5383]
> Received oversubscribable resources from the resource estimator
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930289 24220 slave.cpp:911] New
> master detected at [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930301 24220 slave.cpp:970]
> Authenticating with master [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930315 24220 slave.cpp:981] Using
> default CRAM-MD5 authenticatee
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930336 24217
> status_update_manager.cpp:177] Pausing sending status updates
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930364 24220 slave.cpp:943]
> Detecting new master
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930382 24217
> authenticatee.cpp:121] Creating new client SASL connection
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930631 24216 master.cpp:6234]
> Authenticating slave(353)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930697 24219
> authenticator.cpp:414] Starting authentication session for
> crammd5-authenticatee(755)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930804 24218 authenticator.cpp:98]
> Creating new server SASL connection
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930964 24218
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [02:59:18]W: [Step 10/10] I0915 02:57:42.930977 24218
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931010 24218
> authenticator.cpp:204] Received SASL authentication start
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931037 24218
> authenticator.cpp:326] Authentication requires more steps
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931064 24218
> authenticatee.cpp:259] Received SASL authentication step
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931098 24218
> authenticator.cpp:232] Received SASL authentication step
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931109 24218 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-23.mesosphere.io' server FQDN: 'ip-172-30-2-23.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931114 24218 auxprop.cpp:181]
> Looking up auxiliary property '*userPassword'
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931124 24218 auxprop.cpp:181]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931130 24218 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-23.mesosphere.io' server FQDN: 'ip-172-30-2-23.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931135 24218 auxprop.cpp:131]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931138 24218 auxprop.cpp:131]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931145 24218
> authenticator.cpp:318] Authentication success
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931195 24220
> authenticatee.cpp:299] Authentication success
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931216 24218 master.cpp:6264]
> Successfully authenticated principal 'test-principal' at
> slave(353)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931254 24221
> authenticator.cpp:432] Authentication session cleanup for
> crammd5-authenticatee(755)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931360 24220 slave.cpp:1065]
> Successfully authenticated with master [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931473 24220 slave.cpp:1471] Will
> retry registration in 11.992509ms if necessary
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931560 24221 master.cpp:5050]
> Re-registering agent d22b6309-24c3-422f-a501-a672e7c3e046-S0 at
> slave(352)@172.30.2.23:32968 (ip-172-30-2-23.mesosphere.io)
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931628 24217 slave.cpp:1213]
> Re-registered with master [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931639 24219 hierarchical.cpp:557]
> Agent d22b6309-24c3-422f-a501-a672e7c3e046-S0 reactivated
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931643 24221 master.cpp:5278]
> Sending updated checkpointed resources to agent
> d22b6309-24c3-422f-a501-a672e7c3e046-S0 at slave(353)@172.30.2.23:32968
> (ip-172-30-2-23.mesosphere.io)
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931648 24217 slave.cpp:1249]
> Forwarding total oversubscribed resources
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931659 24220
> status_update_manager.cpp:184] Resuming sending status updates
> [02:59:18]W: [Step 10/10] W0915 02:57:42.931686 24220
> status_update_manager.cpp:191] Resending status update TASK_RUNNING (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931713 24217 slave.cpp:2665]
> Updating framework d22b6309-24c3-422f-a501-a672e7c3e046-0000 pid to
> [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931711 24220
> status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 to the agent
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931740 24217 slave.cpp:2681]
> Checkpointing framework pid
> '[email protected]:32968' to
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_RecoverStatusUpdateManager_w0ToCt/meta/slaves/d22b6309-24c3-422f-a501-a672e7c3e046-S0/frameworks/d22b6309-24c3-422f-a501-a672e7c3e046-0000/framework.pid'
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931753 24221 master.cpp:5340]
> Received update of agent d22b6309-24c3-422f-a501-a672e7c3e046-S0 at
> slave(353)@172.30.2.23:32968 (ip-172-30-2-23.mesosphere.io) with total
> oversubscribed resources
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931830 24221 hierarchical.cpp:540]
> Agent d22b6309-24c3-422f-a501-a672e7c3e046-S0 (ip-172-30-2-23.mesosphere.io)
> updated with oversubscribed resources (total: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000])
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931874 24221
> hierarchical.cpp:1675] No allocations performed
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931877 24217 slave.cpp:2728]
> Ignoring new checkpointed resources identical to the current version:
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931885 24221
> hierarchical.cpp:1770] No inverse offers to send out!
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931891 24216
> status_update_manager.cpp:184] Resuming sending status updates
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931900 24221
> hierarchical.cpp:1294] Performed allocation for agent
> d22b6309-24c3-422f-a501-a672e7c3e046-S0 in 47507ns
> [02:59:18]W: [Step 10/10] W0915 02:57:42.931905 24216
> status_update_manager.cpp:191] Resending status update TASK_RUNNING (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931911 24217 slave.cpp:3982]
> Forwarding the update TASK_RUNNING (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 to [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.931921 24216
> status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 to the agent
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932000 24217 slave.cpp:3982]
> Forwarding the update TASK_RUNNING (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 to [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932044 24219 master.cpp:5475]
> Status update TASK_RUNNING (UUID: e26a5152-97e1-4146-ad72-cbd46775ab39) for
> task b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 from agent
> d22b6309-24c3-422f-a501-a672e7c3e046-S0 at slave(353)@172.30.2.23:32968
> (ip-172-30-2-23.mesosphere.io)
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932062 24219 master.cpp:5537]
> Forwarding status update TASK_RUNNING (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932106 24219 master.cpp:7187]
> Updating the state of task b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932158 24219 master.cpp:5475]
> Status update TASK_RUNNING (UUID: e26a5152-97e1-4146-ad72-cbd46775ab39) for
> task b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 from agent
> d22b6309-24c3-422f-a501-a672e7c3e046-S0 at slave(353)@172.30.2.23:32968
> (ip-172-30-2-23.mesosphere.io)
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932181 24219 master.cpp:5537]
> Forwarding status update TASK_RUNNING (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932202 24216 sched.cpp:1025]
> Scheduler::statusUpdate took 42591ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932212 24219 master.cpp:7187]
> Updating the state of task b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932345 24216 sched.cpp:1025]
> Scheduler::statusUpdate took 6908ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932353 24218 master.cpp:4598]
> Processing ACKNOWLEDGE call e26a5152-97e1-4146-ad72-cbd46775ab39 for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 (default) at
> [email protected]:32968 on agent
> d22b6309-24c3-422f-a501-a672e7c3e046-S0
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932426 24218 master.cpp:4598]
> Processing ACKNOWLEDGE call e26a5152-97e1-4146-ad72-cbd46775ab39 for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 (default) at
> [email protected]:32968 on agent
> d22b6309-24c3-422f-a501-a672e7c3e046-S0
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932448 24202 sched.cpp:1987] Asked
> to stop the driver
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932512 24218
> status_update_manager.cpp:395] Received status update acknowledgement (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932543 24223 sched.cpp:1187]
> Stopping framework d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932554 24218
> status_update_manager.cpp:832] Checkpointing ACK for status update
> TASK_RUNNING (UUID: e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932621 24219 master.cpp:6639]
> Processing TEARDOWN call for framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 (default) at
> [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932639 24219 master.cpp:6651]
> Removing framework d22b6309-24c3-422f-a501-a672e7c3e046-0000 (default) at
> [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932660 24221 slave.cpp:2928]
> Status update manager successfully handled status update acknowledgement
> (UUID: e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932674 24218
> status_update_manager.cpp:395] Received status update acknowledgement (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932689 24223 hierarchical.cpp:380]
> Deactivated framework d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932678 24219 master.cpp:7187]
> Updating the state of task b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 (latest state: TASK_KILLED, status
> update state: TASK_KILLED)
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932718 24221 slave.cpp:2496] Asked
> to shut down framework d22b6309-24c3-422f-a501-a672e7c3e046-0000 by
> [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932734 24221 slave.cpp:2521]
> Shutting down framework d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932745 24221 slave.cpp:4785]
> Shutting down executor 'b813f31e-d12d-4f66-b1a3-c520aa5fa567' of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 at executor(1)@172.30.2.23:58008
> [02:59:18]W: [Step 10/10] E0915 02:57:42.932828 24221 slave.cpp:2921]
> Failed to handle status update acknowledgement (UUID:
> e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000: Unexpected status update
> acknowledgment (UUID: e26a5152-97e1-4146-ad72-cbd46775ab39) for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932854 24219 master.cpp:7283]
> Removing task b813f31e-d12d-4f66-b1a3-c520aa5fa567 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 on agent
> d22b6309-24c3-422f-a501-a672e7c3e046-S0 at slave(353)@172.30.2.23:32968
> (ip-172-30-2-23.mesosphere.io)
> [02:59:18]W: [Step 10/10] I0915 02:57:42.932993 4588 exec.cpp:414]
> Executor asked to shutdown
> [02:59:18]W: [Step 10/10] I0915 02:57:42.933161 24220
> hierarchical.cpp:1003] Recovered cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: ) on agent
> d22b6309-24c3-422f-a501-a672e7c3e046-S0 from framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.933218 24220 hierarchical.cpp:331]
> Removed framework d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.933274 24217
> containerizer.cpp:1617] Destroying container
> 5176a894-13e8-4ca8-b9b5-3c250a920100
> [02:59:18]W: [Step 10/10] I0915 02:57:42.934232 24222 cgroups.cpp:2678]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos_test_c16d101e-11c8-4533-bab6-3fae16e4391f/5176a894-13e8-4ca8-b9b5-3c250a920100
> [02:59:18]W: [Step 10/10] I0915 02:57:42.935169 24218 cgroups.cpp:1412]
> Successfully froze cgroup
> /sys/fs/cgroup/freezer/mesos_test_c16d101e-11c8-4533-bab6-3fae16e4391f/5176a894-13e8-4ca8-b9b5-3c250a920100
> after 910848ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.936182 24222 cgroups.cpp:2696]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos_test_c16d101e-11c8-4533-bab6-3fae16e4391f/5176a894-13e8-4ca8-b9b5-3c250a920100
> [02:59:18]W: [Step 10/10] I0915 02:57:42.937182 24221 cgroups.cpp:1441]
> Successfully thawed cgroup
> /sys/fs/cgroup/freezer/mesos_test_c16d101e-11c8-4533-bab6-3fae16e4391f/5176a894-13e8-4ca8-b9b5-3c250a920100
> after 981760ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.938029 24218 slave.cpp:4110] Got
> exited event for executor(1)@172.30.2.23:58008
> [02:59:18]W: [Step 10/10] I0915 02:57:42.943333 24220
> containerizer.cpp:1841] Executor for container
> 5176a894-13e8-4ca8-b9b5-3c250a920100 has exited
> [02:59:18]W: [Step 10/10] I0915 02:57:42.943346 24220
> containerizer.cpp:1613] Destroy has already been initiated for
> 5176a894-13e8-4ca8-b9b5-3c250a920100
> [02:59:18]W: [Step 10/10] I0915 02:57:42.948518 24218 provisioner.cpp:413]
> Ignoring destroy request for unknown container
> 5176a894-13e8-4ca8-b9b5-3c250a920100
> [02:59:18]W: [Step 10/10] I0915 02:57:42.948648 24217 slave.cpp:4467]
> Executor 'b813f31e-d12d-4f66-b1a3-c520aa5fa567' of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 terminated with signal Killed
> [02:59:18]W: [Step 10/10] I0915 02:57:42.948668 24217 slave.cpp:4571]
> Cleaning up executor 'b813f31e-d12d-4f66-b1a3-c520aa5fa567' of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000 at executor(1)@172.30.2.23:58008
> [02:59:18]W: [Step 10/10] I0915 02:57:42.948845 24221 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_RecoverStatusUpdateManager_w0ToCt/slaves/d22b6309-24c3-422f-a501-a672e7c3e046-S0/frameworks/d22b6309-24c3-422f-a501-a672e7c3e046-0000/executors/b813f31e-d12d-4f66-b1a3-c520aa5fa567/runs/5176a894-13e8-4ca8-b9b5-3c250a920100'
> for gc 6.99998901859852days in the future
> [02:59:18]W: [Step 10/10] I0915 02:57:42.948905 24221 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_RecoverStatusUpdateManager_w0ToCt/slaves/d22b6309-24c3-422f-a501-a672e7c3e046-S0/frameworks/d22b6309-24c3-422f-a501-a672e7c3e046-0000/executors/b813f31e-d12d-4f66-b1a3-c520aa5fa567'
> for gc 6.99998901817185days in the future
> [02:59:18]W: [Step 10/10] I0915 02:57:42.948914 24217 slave.cpp:4659]
> Cleaning up framework d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.948940 24221 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_RecoverStatusUpdateManager_w0ToCt/meta/slaves/d22b6309-24c3-422f-a501-a672e7c3e046-S0/frameworks/d22b6309-24c3-422f-a501-a672e7c3e046-0000/executors/b813f31e-d12d-4f66-b1a3-c520aa5fa567/runs/5176a894-13e8-4ca8-b9b5-3c250a920100'
> for gc 6.99998901770963days in the future
> [02:59:18]W: [Step 10/10] I0915 02:57:42.948992 24216
> status_update_manager.cpp:285] Closing status update streams for framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.948992 24221 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_RecoverStatusUpdateManager_w0ToCt/meta/slaves/d22b6309-24c3-422f-a501-a672e7c3e046-S0/frameworks/d22b6309-24c3-422f-a501-a672e7c3e046-0000/executors/b813f31e-d12d-4f66-b1a3-c520aa5fa567'
> for gc 6.99998901731556days in the future
> [02:59:18]W: [Step 10/10] I0915 02:57:42.949008 24217 slave.cpp:783] Agent
> terminating
> [02:59:18]W: [Step 10/10] I0915 02:57:42.949028 24221 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_RecoverStatusUpdateManager_w0ToCt/slaves/d22b6309-24c3-422f-a501-a672e7c3e046-S0/frameworks/d22b6309-24c3-422f-a501-a672e7c3e046-0000'
> for gc 6.99998901655111days in the future
> [02:59:18]W: [Step 10/10] I0915 02:57:42.949012 24216
> status_update_manager.cpp:531] Cleaning up status update stream for task
> b813f31e-d12d-4f66-b1a3-c520aa5fa567 of framework
> d22b6309-24c3-422f-a501-a672e7c3e046-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:42.949081 24221 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_RecoverStatusUpdateManager_w0ToCt/meta/slaves/d22b6309-24c3-422f-a501-a672e7c3e046-S0/frameworks/d22b6309-24c3-422f-a501-a672e7c3e046-0000'
> for gc 6.99998901624889days in the future
> [02:59:18]W: [Step 10/10] I0915 02:57:42.951805 24202 master.cpp:1097]
> Master terminating
> [02:59:18]W: [Step 10/10] I0915 02:57:42.951946 24220 hierarchical.cpp:508]
> Removed agent d22b6309-24c3-422f-a501-a672e7c3e046-S0
> [02:59:18]W: [Step 10/10] I0915 02:57:42.955227 24220 cgroups.cpp:2678]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos_test_c16d101e-11c8-4533-bab6-3fae16e4391f
> [02:59:18]W: [Step 10/10] I0915 02:57:42.956090 24219 cgroups.cpp:1412]
> Successfully froze cgroup
> /sys/fs/cgroup/freezer/mesos_test_c16d101e-11c8-4533-bab6-3fae16e4391f after
> 843008ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.956971 24220 cgroups.cpp:2696]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos_test_c16d101e-11c8-4533-bab6-3fae16e4391f
> [02:59:18]W: [Step 10/10] I0915 02:57:42.957806 24221 cgroups.cpp:1441]
> Successfully thawed cgroup
> /sys/fs/cgroup/freezer/mesos_test_c16d101e-11c8-4533-bab6-3fae16e4391f after
> 818944ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.981866 24202 cluster.cpp:157]
> Creating default 'local' authorizer
> [02:59:18]W: [Step 10/10] I0915 02:57:42.991049 24202 leveldb.cpp:174]
> Opened db in 9.097659ms
> [02:59:18]W: [Step 10/10] I0915 02:57:42.993981 24202 leveldb.cpp:181]
> Compacted db in 2.91336ms
> [02:59:18]W: [Step 10/10] I0915 02:57:42.994001 24202 leveldb.cpp:196]
> Created db iterator in 3589ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.994007 24202 leveldb.cpp:202]
> Seeked to beginning of db in 602ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.994014 24202 leveldb.cpp:271]
> Iterated through 0 keys in the db in 295ns
> [02:59:18]W: [Step 10/10] I0915 02:57:42.994025 24202 replica.cpp:776]
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [02:59:18]W: [Step 10/10] I0915 02:57:42.994266 24217 recover.cpp:451]
> Starting replica recovery
> [02:59:18]W: [Step 10/10] I0915 02:57:42.994349 24221 recover.cpp:477]
> Replica is in EMPTY status
> [02:59:18]W: [Step 10/10] I0915 02:57:42.994629 24217 replica.cpp:673]
> Replica in EMPTY status received a broadcasted recover request from
> __req_res__(4586)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.994765 24222 recover.cpp:197]
> Received a recover response from a replica in EMPTY status
> [02:59:18]W: [Step 10/10] I0915 02:57:42.994889 24216 recover.cpp:568]
> Updating replica status to STARTING
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995307 24223 master.cpp:380]
> Master 53a45a7f-84a0-4c1d-bde1-78f372407a97 (ip-172-30-2-23.mesosphere.io)
> started on 172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995318 24223 master.cpp:382] Flags
> at startup: --acls="" --agent_ping_timeout="15secs"
> --agent_reregister_timeout="10mins" --allocation_interval="1secs"
> --allocator="HierarchicalDRF" --authenticate_agents="true"
> --authenticate_frameworks="true" --authenticate_http_frameworks="true"
> --authenticate_http_readonly="true" --authenticate_http_readwrite="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/DeBg1G/credentials" --framework_sorter="drf"
> --help="false" --hostname_lookup="true" --http_authenticators="basic"
> --http_framework_authenticators="basic" --initialize_driver_logging="true"
> --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
> --max_agent_ping_timeouts="5" --max_completed_frameworks="50"
> --max_completed_tasks_per_framework="1000" --quiet="false"
> --recovery_agent_removal_limit="100%" --registry="replicated_log"
> --registry_fetch_timeout="1mins" --registry_store_timeout="100secs"
> --registry_strict="true" --root_submissions="true" --user_sorter="drf"
> --version="false" --webui_dir="/usr/local/share/mesos/webui"
> --work_dir="/tmp/DeBg1G/master" --zk_session_timeout="10secs"
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995431 24223 master.cpp:432]
> Master only allowing authenticated frameworks to register
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995436 24223 master.cpp:446]
> Master only allowing authenticated agents to register
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995440 24223 master.cpp:459]
> Master only allowing authenticated HTTP frameworks to register
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995443 24223 credentials.hpp:37]
> Loading credentials for authentication from '/tmp/DeBg1G/credentials'
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995519 24223 master.cpp:504] Using
> default 'crammd5' authenticator
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995555 24223 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995604 24223 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995627 24223 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995658 24223 master.cpp:584]
> Authorization enabled
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995765 24222 hierarchical.cpp:149]
> Initialized hierarchical allocator process
> [02:59:18]W: [Step 10/10] I0915 02:57:42.995781 24219
> whitelist_watcher.cpp:77] No whitelist given
> [02:59:18]W: [Step 10/10] I0915 02:57:42.996289 24216 master.cpp:1855]
> Elected as the leading master!
> [02:59:18]W: [Step 10/10] I0915 02:57:42.996299 24216 master.cpp:1556]
> Recovering from registrar
> [02:59:18]W: [Step 10/10] I0915 02:57:42.996374 24218 registrar.cpp:332]
> Recovering registrar
> [02:59:18]W: [Step 10/10] I0915 02:57:43.007787 24221 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 12.778335ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.007803 24221 replica.cpp:320]
> Persisted replica status to STARTING
> [02:59:18]W: [Step 10/10] I0915 02:57:43.007846 24221 recover.cpp:477]
> Replica is in STARTING status
> [02:59:18]W: [Step 10/10] I0915 02:57:43.008133 24221 replica.cpp:673]
> Replica in STARTING status received a broadcasted recover request from
> __req_res__(4587)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.008241 24218 recover.cpp:197]
> Received a recover response from a replica in STARTING status
> [02:59:18]W: [Step 10/10] I0915 02:57:43.008373 24217 recover.cpp:568]
> Updating replica status to VOTING
> [02:59:18]W: [Step 10/10] I0915 02:57:43.011011 24219 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 2.54109ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.011026 24219 replica.cpp:320]
> Persisted replica status to VOTING
> [02:59:18]W: [Step 10/10] I0915 02:57:43.011056 24219 recover.cpp:582]
> Successfully joined the Paxos group
> [02:59:18]W: [Step 10/10] I0915 02:57:43.011102 24219 recover.cpp:466]
> Recover process terminated
> [02:59:18]W: [Step 10/10] I0915 02:57:43.011243 24216 log.cpp:553]
> Attempting to start the writer
> [02:59:18]W: [Step 10/10] I0915 02:57:43.011651 24221 replica.cpp:493]
> Replica received implicit promise request from
> __req_res__(4588)@172.30.2.23:32968 with proposal 1
> [02:59:18]W: [Step 10/10] I0915 02:57:43.014224 24221 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 2.554302ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.014238 24221 replica.cpp:342]
> Persisted promised to 1
> [02:59:18]W: [Step 10/10] I0915 02:57:43.014461 24218 coordinator.cpp:238]
> Coordinator attempting to fill missing positions
> [02:59:18]W: [Step 10/10] I0915 02:57:43.014891 24222 replica.cpp:388]
> Replica received explicit promise request from
> __req_res__(4589)@172.30.2.23:32968 for position 0 with proposal 2
> [02:59:18]W: [Step 10/10] I0915 02:57:43.017314 24222 leveldb.cpp:341]
> Persisting action (8 bytes) to leveldb took 2.405177ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.017330 24222 replica.cpp:708]
> Persisted action NOP at position 0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.017766 24223 replica.cpp:537]
> Replica received write request for position 0 from
> __req_res__(4590)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.017791 24223 leveldb.cpp:436]
> Reading position from leveldb took 11687ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.020202 24223 leveldb.cpp:341]
> Persisting action (14 bytes) to leveldb took 2.397951ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.020217 24223 replica.cpp:708]
> Persisted action NOP at position 0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.020406 24220 replica.cpp:691]
> Replica received learned notice for position 0 from @0.0.0.0:0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.021399 24220 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 972118ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.021411 24220 replica.cpp:708]
> Persisted action NOP at position 0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.021606 24216 log.cpp:569] Writer
> started with ending position 0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.021911 24222 leveldb.cpp:436]
> Reading position from leveldb took 7957ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.022116 24218 registrar.cpp:365]
> Successfully fetched the registry (0B) in 25.720064ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.022148 24218 registrar.cpp:464]
> Applied 1 operations in 3441ns; attempting to update the registry
> [02:59:18]W: [Step 10/10] I0915 02:57:43.022311 24216 log.cpp:577]
> Attempting to append 205 bytes to the log
> [02:59:18]W: [Step 10/10] I0915 02:57:43.022356 24216 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 1
> [02:59:18]W: [Step 10/10] I0915 02:57:43.022600 24223 replica.cpp:537]
> Replica received write request for position 1 from
> __req_res__(4591)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.025075 24223 leveldb.cpp:341]
> Persisting action (224 bytes) to leveldb took 2.457955ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.025096 24223 replica.cpp:708]
> Persisted action APPEND at position 1
> [02:59:18]W: [Step 10/10] I0915 02:57:43.025326 24216 replica.cpp:691]
> Replica received learned notice for position 1 from @0.0.0.0:0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.027681 24216 leveldb.cpp:341]
> Persisting action (226 bytes) to leveldb took 2.338297ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.027696 24216 replica.cpp:708]
> Persisted action APPEND at position 1
> [02:59:18]W: [Step 10/10] I0915 02:57:43.027904 24222 registrar.cpp:509]
> Successfully updated the registry in 5.734144ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.027952 24222 registrar.cpp:395]
> Successfully recovered registrar
> [02:59:18]W: [Step 10/10] I0915 02:57:43.027972 24219 log.cpp:596]
> Attempting to truncate the log to 1
> [02:59:18]W: [Step 10/10] I0915 02:57:43.028024 24218 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 2
> [02:59:18]W: [Step 10/10] I0915 02:57:43.028242 24219 master.cpp:1664]
> Recovered 0 agents from the registry (166B); allowing 10mins for agents to
> re-register
> [02:59:18]W: [Step 10/10] I0915 02:57:43.028311 24223 hierarchical.cpp:176]
> Skipping recovery of hierarchical allocator: nothing to recover
> [02:59:18]W: [Step 10/10] I0915 02:57:43.028319 24220 replica.cpp:537]
> Replica received write request for position 2 from
> __req_res__(4592)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.029073 24220 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 732903ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.029084 24220 replica.cpp:708]
> Persisted action TRUNCATE at position 2
> [02:59:18]W: [Step 10/10] I0915 02:57:43.029338 24216 replica.cpp:691]
> Replica received learned notice for position 2 from @0.0.0.0:0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.031718 24216 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 2.363723ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.031743 24216 leveldb.cpp:399]
> Deleting ~1 keys from leveldb took 9869ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.031749 24216 replica.cpp:708]
> Persisted action TRUNCATE at position 2
> [02:59:18]W: [Step 10/10] I0915 02:57:43.032601 24202
> containerizer.cpp:217] Using isolation:
> cgroups/cpu,cgroups/mem,filesystem/posix,network/cni
> [02:59:18]W: [Step 10/10] I0915 02:57:43.044536 24202
> linux_launcher.cpp:104] Using /sys/fs/cgroup/freezer as the freezer hierarchy
> for the Linux launcher
> [02:59:18]W: [Step 10/10] I0915 02:57:43.055829 24202 cluster.cpp:436]
> Creating default 'local' authorizer
> [02:59:18]W: [Step 10/10] I0915 02:57:43.056206 24216 slave.cpp:208] Mesos
> agent started on @172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.056218 24216 slave.cpp:209] Flags
> at startup: --acls="" --agent_subsystems="memory,cpuacct"
> --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_readonly="true"
> --authenticate_http_readwrite="true" --authenticatee="crammd5"
> --authentication_backoff_factor="1secs" --authorizer="local"
> --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
> --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
> --cgroups_root="mesos_test_cca37eb1-1444-4a3d-9b7e-a1bcac9c782c"
> --container_disk_watch_interval="15secs" --containerizers="mesos"
> --credential="/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_oKHzwo/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
> --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_oKHzwo/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --http_authenticators="basic"
> --http_command_executor="true"
> --http_credentials="/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_oKHzwo/http_credentials"
> --image_provisioner_backend="copy" --initialize_driver_logging="true"
> --isolation="cgroups/cpu,cgroups/mem"
> --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs"
> --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false"
> --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ms"
> --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true"
> --runtime_dir="/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_oKHzwo"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true"
> --switch_user="true" --systemd_enable_support="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2"
> [02:59:18]W: [Step 10/10] I0915 02:57:43.056419 24216 slave.cpp:229] Moving
> agent process into its own cgroup for subsystem: memory
> [02:59:18]W: [Step 10/10] I0915 02:57:43.056812 24202 sched.cpp:226]
> Version: 1.1.0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.056942 24219 sched.cpp:330] New
> master detected at [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.056972 24219 sched.cpp:396]
> Authenticating with master [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.056980 24219 sched.cpp:403] Using
> default CRAM-MD5 authenticatee
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057080 24217
> authenticatee.cpp:121] Creating new client SASL connection
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057257 24217 master.cpp:6234]
> Authenticating
> [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057312 24218
> authenticator.cpp:414] Starting authentication session for
> crammd5-authenticatee(756)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057374 24223 authenticator.cpp:98]
> Creating new server SASL connection
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057533 24223
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057546 24223
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057585 24223
> authenticator.cpp:204] Received SASL authentication start
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057621 24223
> authenticator.cpp:326] Authentication requires more steps
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057652 24223
> authenticatee.cpp:259] Received SASL authentication step
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057695 24223
> authenticator.cpp:232] Received SASL authentication step
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057713 24223 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-23.mesosphere.io' server FQDN: 'ip-172-30-2-23.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057724 24223 auxprop.cpp:181]
> Looking up auxiliary property '*userPassword'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057732 24223 auxprop.cpp:181]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057739 24223 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-23.mesosphere.io' server FQDN: 'ip-172-30-2-23.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057742 24223 auxprop.cpp:131]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057746 24223 auxprop.cpp:131]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057754 24223
> authenticator.cpp:318] Authentication success
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057806 24218
> authenticatee.cpp:299] Authentication success
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057832 24220
> authenticator.cpp:432] Authentication session cleanup for
> crammd5-authenticatee(756)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057849 24223 master.cpp:6264]
> Successfully authenticated principal 'test-principal' at
> [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057891 24218 sched.cpp:502]
> Successfully authenticated with master [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057901 24218 sched.cpp:820]
> Sending SUBSCRIBE call to [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057940 24218 sched.cpp:853] Will
> retry registration in 1.912153812secs if necessary
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057976 24223 master.cpp:2429]
> Received SUBSCRIBE call for framework 'default' at
> [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.057991 24223 master.cpp:1891]
> Authorizing framework principal 'test-principal' to receive offers for role
> '*'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.058095 24223 master.cpp:2505]
> Subscribing framework default with checkpointing enabled and capabilities [ ]
> [02:59:18]W: [Step 10/10] I0915 02:57:43.058231 24220 hierarchical.cpp:269]
> Added framework 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:43.058253 24220
> hierarchical.cpp:1675] No allocations performed
> [02:59:18]W: [Step 10/10] I0915 02:57:43.058259 24220
> hierarchical.cpp:1770] No inverse offers to send out!
> [02:59:18]W: [Step 10/10] I0915 02:57:43.058260 24218 sched.cpp:743]
> Framework registered with 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:43.058266 24220
> hierarchical.cpp:1271] Performed allocation for 0 agents in 22146ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.058281 24218 sched.cpp:757]
> Scheduler::registered took 8368ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.061391 24216 slave.cpp:229] Moving
> agent process into its own cgroup for subsystem: cpuacct
> [02:59:18]W: [Step 10/10] I0915 02:57:43.064374 24216 credentials.hpp:86]
> Loading credential for authentication from
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_oKHzwo/credential'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.064422 24216 slave.cpp:346] Agent
> using credential for: test-principal
> [02:59:18]W: [Step 10/10] I0915 02:57:43.064429 24216 credentials.hpp:37]
> Loading credentials for authentication from
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_oKHzwo/http_credentials'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.064484 24216 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.064519 24216 http.cpp:883] Using
> default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.064772 24216 slave.cpp:529] Agent
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [02:59:18]W: [Step 10/10] I0915 02:57:43.064796 24216 slave.cpp:537] Agent
> attributes: [ ]
> [02:59:18]W: [Step 10/10] I0915 02:57:43.064800 24216 slave.cpp:542] Agent
> hostname: ip-172-30-2-23.mesosphere.io
> [02:59:18]W: [Step 10/10] I0915 02:57:43.065109 24216 state.cpp:57]
> Recovering state from
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2/meta'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.065227 24221
> status_update_manager.cpp:203] Recovering status update manager
> [02:59:18]W: [Step 10/10] I0915 02:57:43.065271 24221
> containerizer.cpp:578] Recovering containerizer
> [02:59:18]W: [Step 10/10] I0915 02:57:43.066896 24223 provisioner.cpp:253]
> Provisioner recovery complete
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067045 24223 slave.cpp:5197]
> Finished recovery
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067189 24223 slave.cpp:5369]
> Querying resource estimator for oversubscribable resources
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067289 24218 slave.cpp:911] New
> master detected at [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067298 24219
> status_update_manager.cpp:177] Pausing sending status updates
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067304 24218 slave.cpp:970]
> Authenticating with master [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067318 24218 slave.cpp:981] Using
> default CRAM-MD5 authenticatee
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067373 24218 slave.cpp:943]
> Detecting new master
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067390 24216
> authenticatee.cpp:121] Creating new client SASL connection
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067412 24218 slave.cpp:5383]
> Received oversubscribable resources from the resource estimator
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067558 24216 master.cpp:6234]
> Authenticating [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067608 24217
> authenticator.cpp:414] Starting authentication session for
> crammd5-authenticatee(757)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067675 24216 authenticator.cpp:98]
> Creating new server SASL connection
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067809 24216
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067826 24216
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067865 24216
> authenticator.cpp:204] Received SASL authentication start
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067893 24216
> authenticator.cpp:326] Authentication requires more steps
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067924 24216
> authenticatee.cpp:259] Received SASL authentication step
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067982 24218
> authenticator.cpp:232] Received SASL authentication step
> [02:59:18]W: [Step 10/10] I0915 02:57:43.067996 24218 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-23.mesosphere.io' server FQDN: 'ip-172-30-2-23.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068001 24218 auxprop.cpp:181]
> Looking up auxiliary property '*userPassword'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068007 24218 auxprop.cpp:181]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068012 24218 auxprop.cpp:109]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-23.mesosphere.io' server FQDN: 'ip-172-30-2-23.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068017 24218 auxprop.cpp:131]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068020 24218 auxprop.cpp:131]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068027 24218
> authenticator.cpp:318] Authentication success
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068075 24218
> authenticatee.cpp:299] Authentication success
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068078 24216
> authenticator.cpp:432] Authentication session cleanup for
> crammd5-authenticatee(757)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068099 24221 master.cpp:6264]
> Successfully authenticated principal 'test-principal' at
> [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068181 24218 slave.cpp:1065]
> Successfully authenticated with master [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068229 24218 slave.cpp:1471] Will
> retry registration in 2.488364ms if necessary
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068291 24220 master.cpp:4886]
> Registering agent at [email protected]:32968 (ip-172-30-2-23.mesosphere.io)
> with id 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068377 24221 registrar.cpp:464]
> Applied 1 operations in 10678ns; attempting to update the registry
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068559 24216 log.cpp:577]
> Attempting to append 390 bytes to the log
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068596 24217 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 3
> [02:59:18]W: [Step 10/10] I0915 02:57:43.068840 24217 replica.cpp:537]
> Replica received write request for position 3 from
> __req_res__(4593)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.069675 24217 leveldb.cpp:341]
> Persisting action (409 bytes) to leveldb took 817978ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.069687 24217 replica.cpp:708]
> Persisted action APPEND at position 3
> [02:59:18]W: [Step 10/10] I0915 02:57:43.069950 24218 replica.cpp:691]
> Replica received learned notice for position 3 from @0.0.0.0:0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.071473 24222 slave.cpp:1471] Will
> retry registration in 6.766388ms if necessary
> [02:59:18]W: [Step 10/10] I0915 02:57:43.071511 24219 master.cpp:4874]
> Ignoring register agent message from [email protected]:32968
> (ip-172-30-2-23.mesosphere.io) as admission is already in progress
> [02:59:18]W: [Step 10/10] I0915 02:57:43.072458 24218 leveldb.cpp:341]
> Persisting action (411 bytes) to leveldb took 2.492646ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.072474 24218 replica.cpp:708]
> Persisted action APPEND at position 3
> [02:59:18]W: [Step 10/10] I0915 02:57:43.072746 24221 registrar.cpp:509]
> Successfully updated the registry in 4.345856ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.072773 24223 log.cpp:596]
> Attempting to truncate the log to 3
> [02:59:18]W: [Step 10/10] I0915 02:57:43.072880 24221 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 4
> [02:59:18]W: [Step 10/10] I0915 02:57:43.072932 24216 master.cpp:4956]
> Registered agent 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0 at
> [email protected]:32968 (ip-172-30-2-23.mesosphere.io) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [02:59:18]W: [Step 10/10] I0915 02:57:43.072981 24221 slave.cpp:4064]
> Received ping from slave-observer(338)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.072993 24223 hierarchical.cpp:476]
> Added agent 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0
> (ip-172-30-2-23.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (allocated: )
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073035 24221 slave.cpp:1111]
> Registered with master [email protected]:32968; given agent ID
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073045 24221 fetcher.cpp:86]
> Clearing fetcher cache
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073117 24218 replica.cpp:537]
> Replica received write request for position 4 from
> __req_res__(4594)@172.30.2.23:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073122 24216
> status_update_manager.cpp:184] Resuming sending status updates
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073195 24221 slave.cpp:1134]
> Checkpointing SlaveInfo to
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2/meta/slaves/53a45a7f-84a0-4c1d-bde1-78f372407a97-S0/slave.info'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073199 24223
> hierarchical.cpp:1770] No inverse offers to send out!
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073220 24223
> hierarchical.cpp:1294] Performed allocation for agent
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0 in 202186ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073297 24221 slave.cpp:1171]
> Forwarding total oversubscribed resources
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073297 24217 master.cpp:6063]
> Sending 1 offers to framework 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000
> (default) at [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073364 24217 master.cpp:5340]
> Received update of agent 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0 at
> [email protected]:32968 (ip-172-30-2-23.mesosphere.io) with total
> oversubscribed resources
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073463 24222 sched.cpp:917]
> Scheduler::resourceOffers took 49413ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073456 24219 hierarchical.cpp:540]
> Agent 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0 (ip-172-30-2-23.mesosphere.io)
> updated with oversubscribed resources (total: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000])
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073504 24219
> hierarchical.cpp:1675] No allocations performed
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073513 24219
> hierarchical.cpp:1770] No inverse offers to send out!
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073519 24219
> hierarchical.cpp:1294] Performed allocation for agent
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0 in 34507ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073812 24221 master.cpp:3363]
> Processing ACCEPT call for offers: [ 53a45a7f-84a0-4c1d-bde1-78f372407a97-O0
> ] on agent 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0 at [email protected]:32968
> (ip-172-30-2-23.mesosphere.io) for framework
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000 (default) at
> [email protected]:32968
> [02:59:18]W: [Step 10/10] I0915 02:57:43.073837 24221 master.cpp:2985]
> Authorizing framework principal 'test-principal' to launch task
> c1ba3f0b-2f6a-46a1-b752-592394c6d726
> [02:59:18]W: [Step 10/10] I0915 02:57:43.074189 24223 master.cpp:7809]
> Adding task c1ba3f0b-2f6a-46a1-b752-592394c6d726 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0 (ip-172-30-2-23.mesosphere.io)
> [02:59:18]W: [Step 10/10] I0915 02:57:43.074235 24223 master.cpp:3963]
> Launching task c1ba3f0b-2f6a-46a1-b752-592394c6d726 of framework
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000 (default) at
> [email protected]:32968 with
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> agent 53a45a7f-84a0-4c1d-bde1-78f372407a97-S0 at [email protected]:32968
> (ip-172-30-2-23.mesosphere.io)
> [02:59:18]W: [Step 10/10] I0915 02:57:43.074400 24220 slave.cpp:1535] Got
> assigned task 'c1ba3f0b-2f6a-46a1-b752-592394c6d726' for framework
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:43.074450 24220 slave.cpp:6009]
> Checkpointing FrameworkInfo to
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2/meta/slaves/53a45a7f-84a0-4c1d-bde1-78f372407a97-S0/frameworks/53a45a7f-84a0-4c1d-bde1-78f372407a97-0000/framework.info'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.074579 24220 slave.cpp:6020]
> Checkpointing framework pid
> '[email protected]:32968' to
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2/meta/slaves/53a45a7f-84a0-4c1d-bde1-78f372407a97-S0/frameworks/53a45a7f-84a0-4c1d-bde1-78f372407a97-0000/framework.pid'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.074764 24220 slave.cpp:1692]
> Launching task 'c1ba3f0b-2f6a-46a1-b752-592394c6d726' for framework
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:43.074960 24220 paths.cpp:536] Trying
> to chown
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2/slaves/53a45a7f-84a0-4c1d-bde1-78f372407a97-S0/frameworks/53a45a7f-84a0-4c1d-bde1-78f372407a97-0000/executors/c1ba3f0b-2f6a-46a1-b752-592394c6d726/runs/5c483d99-350a-4776-817b-f482ef332842'
> to user 'root'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.076668 24218 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 3.370024ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.076715 24218 replica.cpp:708]
> Persisted action TRUNCATE at position 4
> [02:59:18]W: [Step 10/10] I0915 02:57:43.077392 24216 replica.cpp:691]
> Replica received learned notice for position 4 from @0.0.0.0:0
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079028 24220 slave.cpp:6474]
> Checkpointing ExecutorInfo to
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2/meta/slaves/53a45a7f-84a0-4c1d-bde1-78f372407a97-S0/frameworks/53a45a7f-84a0-4c1d-bde1-78f372407a97-0000/executors/c1ba3f0b-2f6a-46a1-b752-592394c6d726/executor.info'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079258 24220 slave.cpp:6089]
> Launching executor 'c1ba3f0b-2f6a-46a1-b752-592394c6d726' of framework
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2/slaves/53a45a7f-84a0-4c1d-bde1-78f372407a97-S0/frameworks/53a45a7f-84a0-4c1d-bde1-78f372407a97-0000/executors/c1ba3f0b-2f6a-46a1-b752-592394c6d726/runs/5c483d99-350a-4776-817b-f482ef332842'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079458 24220 slave.cpp:6497]
> Checkpointing TaskInfo to
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2/meta/slaves/53a45a7f-84a0-4c1d-bde1-78f372407a97-S0/frameworks/53a45a7f-84a0-4c1d-bde1-78f372407a97-0000/executors/c1ba3f0b-2f6a-46a1-b752-592394c6d726/runs/5c483d99-350a-4776-817b-f482ef332842/tasks/c1ba3f0b-2f6a-46a1-b752-592394c6d726/task.info'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079462 24221
> containerizer.cpp:846] Starting container
> 5c483d99-350a-4776-817b-f482ef332842 for executor
> 'c1ba3f0b-2f6a-46a1-b752-592394c6d726' of framework
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079591 24220 slave.cpp:1978]
> Queued task 'c1ba3f0b-2f6a-46a1-b752-592394c6d726' for executor
> 'c1ba3f0b-2f6a-46a1-b752-592394c6d726' of framework
> 53a45a7f-84a0-4c1d-bde1-78f372407a97-0000
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079623 24220 slave.cpp:864]
> Successfully attached file
> '/mnt/teamcity/temp/buildTmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_qLSUL2/slaves/53a45a7f-84a0-4c1d-bde1-78f372407a97-S0/frameworks/53a45a7f-84a0-4c1d-bde1-78f372407a97-0000/executors/c1ba3f0b-2f6a-46a1-b752-592394c6d726/runs/5c483d99-350a-4776-817b-f482ef332842'
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079816 24216 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 2.40696ms
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079841 24216 leveldb.cpp:399]
> Deleting ~2 keys from leveldb took 12061ns
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079849 24216 replica.cpp:708]
> Persisted action TRUNCATE at position 4
> [02:59:18]W: [Step 10/10] I0915 02:57:43.079861 24221 cgroups.cpp:375]
> Creating cgroup at
> '/sys/fs/cgroup/cpu/mesos_test_cca37eb1-1444-4a3d-9b7e-a1bcac9c782c/5c483d99-350a-4776-817b-f482ef332842'
> for container 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.093528 24221 cgroups.cpp:431]
> Chown the cgroup at
> '/sys/fs/cgroup/cpu/mesos_test_cca37eb1-1444-4a3d-9b7e-a1bcac9c782c/5c483d99-350a-4776-817b-f482ef332842'
> to user 'root' for container 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.093565 24221 cgroups.cpp:375]
> Creating cgroup at
> '/sys/fs/cgroup/cpuacct/mesos_test_cca37eb1-1444-4a3d-9b7e-a1bcac9c782c/5c483d99-350a-4776-817b-f482ef332842'
> for container 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.094154 24221 cgroups.cpp:431]
> Chown the cgroup at
> '/sys/fs/cgroup/cpuacct/mesos_test_cca37eb1-1444-4a3d-9b7e-a1bcac9c782c/5c483d99-350a-4776-817b-f482ef332842'
> to user 'root' for container 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.094184 24221 cgroups.cpp:375]
> Creating cgroup at
> '/sys/fs/cgroup/memory/mesos_test_cca37eb1-1444-4a3d-9b7e-a1bcac9c782c/5c483d99-350a-4776-817b-f482ef332842'
> for container 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.094791 24221 cgroups.cpp:431]
> Chown the cgroup at
> '/sys/fs/cgroup/memory/mesos_test_cca37eb1-1444-4a3d-9b7e-a1bcac9c782c/5c483d99-350a-4776-817b-f482ef332842'
> to user 'root' for container 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.095093 24221 memory.cpp:447]
> Started listening for OOM events for container
> 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.095438 24221 memory.cpp:564]
> Started listening on 'low' memory pressure events for container
> 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.095751 24221 memory.cpp:564]
> Started listening on 'medium' memory pressure events for container
> 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.096076 24221 memory.cpp:564]
> Started listening on 'critical' memory pressure events for container
> 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.096633 24216 memory.cpp:193]
> Updated 'memory.soft_limit_in_bytes' to 1056MB for container
> 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18]W: [Step 10/10] I0915 02:57:43.097168 24216 memory.cpp:246]
> Updated 'memory.limit_in_bytes' to 1056MB for container
> 5c483d99-350a-4776-817b-f482ef332842
> [02:59:18] : [Step 10/10] [ FAILED ]
> SlaveRecoveryTest/0.ReconnectHTTPExecutor, where TypeParam =
> mesos::internal::slave::MesosContainerizer (95963 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
