See <https://builds.apache.org/job/mesos-reviewbot/15693/>

------------------------------------------
[...truncated 160687 lines...]
I1017 06:20:21.004127 29250 slave.cpp:546] Agent hostname: 8082f3c85866
I1017 06:20:21.004272 29251 authenticatee.cpp:121] Creating new client SASL 
connection
I1017 06:20:21.004662 29251 master.cpp:6663] Authenticating 
scheduler-19cb9763-1515-4dc8-a9e5-81c142f5b93e@172.17.0.2:41176
I1017 06:20:21.004992 29252 authenticator.cpp:414] Starting authentication 
session for crammd5-authenticatee(875)@172.17.0.2:41176
I1017 06:20:21.005939 29246 authenticator.cpp:98] Creating new server SASL 
connection
I1017 06:20:21.006249 29242 authenticatee.cpp:213] Received SASL authentication 
mechanisms: CRAM-MD5
I1017 06:20:21.006259 29245 state.cpp:57] Recovering state from 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta'
I1017 06:20:21.006407 29242 authenticatee.cpp:239] Attempting to authenticate 
with mechanism 'CRAM-MD5'
I1017 06:20:21.006593 29246 authenticator.cpp:204] Received SASL authentication 
start
I1017 06:20:21.006733 29246 authenticator.cpp:326] Authentication requires more 
steps
I1017 06:20:21.006757 29250 status_update_manager.cpp:203] Recovering status 
update manager
I1017 06:20:21.006974 29246 authenticatee.cpp:259] Received SASL authentication 
step
I1017 06:20:21.007128 29241 containerizer.cpp:555] Recovering containerizer
I1017 06:20:21.007228 29246 authenticator.cpp:232] Received SASL authentication 
step
I1017 06:20:21.007268 29246 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '8082f3c85866' server FQDN: '8082f3c85866' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: false 
I1017 06:20:21.007315 29246 auxprop.cpp:181] Looking up auxiliary property 
'*userPassword'
I1017 06:20:21.007417 29246 auxprop.cpp:181] Looking up auxiliary property 
'*cmusaslsecretCRAM-MD5'
I1017 06:20:21.007452 29246 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '8082f3c85866' server FQDN: '8082f3c85866' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: true 
I1017 06:20:21.007469 29246 auxprop.cpp:131] Skipping auxiliary property 
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1017 06:20:21.007516 29246 auxprop.cpp:131] Skipping auxiliary property 
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1017 06:20:21.007565 29246 authenticator.cpp:318] Authentication success
I1017 06:20:21.007709 29243 authenticatee.cpp:299] Authentication success
I1017 06:20:21.007910 29248 authenticator.cpp:432] Authentication session 
cleanup for crammd5-authenticatee(875)@172.17.0.2:41176
I1017 06:20:21.007913 29247 master.cpp:6693] Successfully authenticated 
principal 'test-principal' at 
scheduler-19cb9763-1515-4dc8-a9e5-81c142f5b93e@172.17.0.2:41176
I1017 06:20:21.008230 29244 sched.cpp:502] Successfully authenticated with 
master master@172.17.0.2:41176
I1017 06:20:21.008352 29244 sched.cpp:820] Sending SUBSCRIBE call to 
master@172.17.0.2:41176
I1017 06:20:21.008479 29244 sched.cpp:853] Will retry registration in 
1.62563168secs if necessary
I1017 06:20:21.008610 29246 master.cpp:2587] Received SUBSCRIBE call for 
framework 'default' at 
scheduler-19cb9763-1515-4dc8-a9e5-81c142f5b93e@172.17.0.2:41176
I1017 06:20:21.008678 29246 master.cpp:2049] Authorizing framework principal 
'test-principal' to receive offers for role '*'
I1017 06:20:21.008878 29245 provisioner.cpp:253] Provisioner recovery complete
I1017 06:20:21.009145 29242 master.cpp:2663] Subscribing framework default with 
checkpointing enabled and capabilities [  ]
I1017 06:20:21.009150 29238 slave.cpp:5281] Finished recovery
I1017 06:20:21.009601 29238 slave.cpp:5455] Querying resource estimator for 
oversubscribable resources
I1017 06:20:21.009698 29253 sched.cpp:743] Framework registered with 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.009757 29253 sched.cpp:757] Scheduler::registered took 29489ns
I1017 06:20:21.009892 29243 hierarchical.cpp:275] Added framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.009914 29238 slave.cpp:915] New master detected at 
master@172.17.0.2:41176
I1017 06:20:21.009922 29241 status_update_manager.cpp:177] Pausing sending 
status updates
I1017 06:20:21.009990 29238 slave.cpp:974] Authenticating with master 
master@172.17.0.2:41176
I1017 06:20:21.010058 29238 slave.cpp:985] Using default CRAM-MD5 authenticatee
I1017 06:20:21.010058 29243 hierarchical.cpp:1694] No allocations performed
I1017 06:20:21.010105 29243 hierarchical.cpp:1789] No inverse offers to send 
out!
I1017 06:20:21.010169 29243 hierarchical.cpp:1286] Performed allocation for 0 
agents in 190245ns
I1017 06:20:21.010206 29238 slave.cpp:947] Detecting new master
I1017 06:20:21.010251 29242 authenticatee.cpp:121] Creating new client SASL 
connection
I1017 06:20:21.010433 29238 slave.cpp:5469] Received oversubscribable resources 
{} from the resource estimator
I1017 06:20:21.010556 29247 master.cpp:6663] Authenticating 
slave(414)@172.17.0.2:41176
I1017 06:20:21.010677 29242 authenticator.cpp:414] Starting authentication 
session for crammd5-authenticatee(876)@172.17.0.2:41176
I1017 06:20:21.010920 29252 authenticator.cpp:98] Creating new server SASL 
connection
I1017 06:20:21.011101 29238 authenticatee.cpp:213] Received SASL authentication 
mechanisms: CRAM-MD5
I1017 06:20:21.011144 29238 authenticatee.cpp:239] Attempting to authenticate 
with mechanism 'CRAM-MD5'
I1017 06:20:21.011277 29253 authenticator.cpp:204] Received SASL authentication 
start
I1017 06:20:21.011358 29253 authenticator.cpp:326] Authentication requires more 
steps
I1017 06:20:21.011448 29238 authenticatee.cpp:259] Received SASL authentication 
step
I1017 06:20:21.011548 29253 authenticator.cpp:232] Received SASL authentication 
step
I1017 06:20:21.011586 29253 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '8082f3c85866' server FQDN: '8082f3c85866' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: false 
I1017 06:20:21.011605 29253 auxprop.cpp:181] Looking up auxiliary property 
'*userPassword'
I1017 06:20:21.011637 29253 auxprop.cpp:181] Looking up auxiliary property 
'*cmusaslsecretCRAM-MD5'
I1017 06:20:21.011664 29253 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '8082f3c85866' server FQDN: '8082f3c85866' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: true 
I1017 06:20:21.011680 29253 auxprop.cpp:131] Skipping auxiliary property 
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1017 06:20:21.011693 29253 auxprop.cpp:131] Skipping auxiliary property 
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1017 06:20:21.011713 29253 authenticator.cpp:318] Authentication success
I1017 06:20:21.011811 29238 authenticatee.cpp:299] Authentication success
I1017 06:20:21.012011 29243 master.cpp:6693] Successfully authenticated 
principal 'test-principal' at slave(414)@172.17.0.2:41176
I1017 06:20:21.012069 29251 authenticator.cpp:432] Authentication session 
cleanup for crammd5-authenticatee(876)@172.17.0.2:41176
I1017 06:20:21.012359 29242 slave.cpp:1069] Successfully authenticated with 
master master@172.17.0.2:41176
I1017 06:20:21.012550 29242 slave.cpp:1475] Will retry registration in 
9.265773ms if necessary
I1017 06:20:21.012735 29238 master.cpp:5097] Registering agent at 
slave(414)@172.17.0.2:41176 (8082f3c85866) with id 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0
I1017 06:20:21.013164 29239 registrar.cpp:461] Applied 1 operations in 56016ns; 
attempting to update the registry
I1017 06:20:21.013926 29240 log.cpp:577] Attempting to append 337 bytes to the 
log
I1017 06:20:21.014070 29247 coordinator.cpp:348] Coordinator attempting to 
write APPEND action at position 3
I1017 06:20:21.014950 29253 replica.cpp:537] Replica received write request for 
position 3 from __req_res__(5731)@172.17.0.2:41176
I1017 06:20:21.023195 29249 slave.cpp:1475] Will retry registration in 14174ns 
if necessary
I1017 06:20:21.023353 29238 master.cpp:5085] Ignoring register agent message 
from slave(414)@172.17.0.2:41176 (8082f3c85866) as admission is already in 
progress
I1017 06:20:21.024683 29247 slave.cpp:1475] Will retry registration in 
54.889423ms if necessary
I1017 06:20:21.024878 29248 master.cpp:5085] Ignoring register agent message 
from slave(414)@172.17.0.2:41176 (8082f3c85866) as admission is already in 
progress
I1017 06:20:21.057132 29253 leveldb.cpp:341] Persisting action (356 bytes) to 
leveldb took 42.122511ms
I1017 06:20:21.057214 29253 replica.cpp:708] Persisted action APPEND at 
position 3
I1017 06:20:21.058182 29242 replica.cpp:691] Replica received learned notice 
for position 3 from @0.0.0.0:0
I1017 06:20:21.080374 29239 slave.cpp:1475] Will retry registration in 
35.700495ms if necessary
I1017 06:20:21.080641 29244 master.cpp:5085] Ignoring register agent message 
from slave(414)@172.17.0.2:41176 (8082f3c85866) as admission is already in 
progress
I1017 06:20:21.102171 29242 leveldb.cpp:341] Persisting action (358 bytes) to 
leveldb took 43.943675ms
I1017 06:20:21.102233 29242 replica.cpp:708] Persisted action APPEND at 
position 3
I1017 06:20:21.104447 29238 registrar.cpp:506] Successfully updated the 
registry in 91.190272ms
I1017 06:20:21.104811 29246 log.cpp:596] Attempting to truncate the log to 3
I1017 06:20:21.104971 29242 coordinator.cpp:348] Coordinator attempting to 
write TRUNCATE action at position 4
I1017 06:20:21.105650 29243 slave.cpp:4133] Received ping from 
slave-observer(387)@172.17.0.2:41176
I1017 06:20:21.105779 29247 master.cpp:5168] Registered agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 at slave(414)@172.17.0.2:41176 
(8082f3c85866) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1017 06:20:21.106297 29243 slave.cpp:1115] Registered with master 
master@172.17.0.2:41176; given agent ID 1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0
I1017 06:20:21.106335 29243 fetcher.cpp:86] Clearing fetcher cache
I1017 06:20:21.106503 29250 replica.cpp:537] Replica received write request for 
position 4 from __req_res__(5732)@172.17.0.2:41176
I1017 06:20:21.106874 29249 hierarchical.cpp:485] Added agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 (8082f3c85866) with cpus(*):2; 
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I1017 06:20:21.107005 29239 status_update_manager.cpp:184] Resuming sending 
status updates
I1017 06:20:21.107431 29243 slave.cpp:1138] Checkpointing SlaveInfo to 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/slave.info'
I1017 06:20:21.108157 29243 slave.cpp:1175] Forwarding total oversubscribed 
resources {}
I1017 06:20:21.108340 29243 master.cpp:5565] Received update of agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 at slave(414)@172.17.0.2:41176 
(8082f3c85866) with total oversubscribed resources {}
I1017 06:20:21.108724 29249 hierarchical.cpp:1789] No inverse offers to send 
out!
I1017 06:20:21.108878 29249 hierarchical.cpp:1309] Performed allocation for 
agent 1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 in 1.936999ms
I1017 06:20:21.109082 29249 hierarchical.cpp:555] Agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 (8082f3c85866) updated with 
oversubscribed resources {} (total: cpus(*):2; mem(*):1024; disk(*):1024; 
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; 
ports(*):[31000-32000])
I1017 06:20:21.109220 29249 hierarchical.cpp:1694] No allocations performed
I1017 06:20:21.109261 29249 hierarchical.cpp:1789] No inverse offers to send 
out!
I1017 06:20:21.109344 29249 hierarchical.cpp:1309] Performed allocation for 
agent 1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 in 219717ns
I1017 06:20:21.109359 29252 master.cpp:6492] Sending 1 offers to framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000 (default) at 
scheduler-19cb9763-1515-4dc8-a9e5-81c142f5b93e@172.17.0.2:41176
I1017 06:20:21.109858 29239 sched.cpp:917] Scheduler::resourceOffers took 
114186ns
I1017 06:20:21.111673 29249 master.cpp:3538] Processing ACCEPT call for offers: 
[ 1e69aad0-d5e7-47b5-8d30-41192e2ade17-O0 ] on agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 at slave(414)@172.17.0.2:41176 
(8082f3c85866) for framework 1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000 
(default) at scheduler-19cb9763-1515-4dc8-a9e5-81c142f5b93e@172.17.0.2:41176
I1017 06:20:21.111810 29249 master.cpp:3143] Authorizing framework principal 
'test-principal' to launch task f83c5fdc-ed77-4d41-90ed-afcb6f9a191a
I1017 06:20:21.113780 29253 master.cpp:8245] Adding task 
f83c5fdc-ed77-4d41-90ed-afcb6f9a191a with resources cpus(*):2; mem(*):1024; 
disk(*):1024; ports(*):[31000-32000] on agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 (8082f3c85866)
I1017 06:20:21.114033 29253 master.cpp:4176] Launching task 
f83c5fdc-ed77-4d41-90ed-afcb6f9a191a of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000 (default) at 
scheduler-19cb9763-1515-4dc8-a9e5-81c142f5b93e@172.17.0.2:41176 with resources 
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 at slave(414)@172.17.0.2:41176 
(8082f3c85866)
I1017 06:20:21.114713 29239 slave.cpp:1539] Got assigned task 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' for framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.114907 29239 slave.cpp:6093] Checkpointing FrameworkInfo to 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/framework.info'
I1017 06:20:21.115465 29239 slave.cpp:6104] Checkpointing framework pid 
'scheduler-19cb9763-1515-4dc8-a9e5-81c142f5b93e@172.17.0.2:41176' to 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/framework.pid'
I1017 06:20:21.116526 29239 slave.cpp:1701] Launching task 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' for framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.117355 29239 paths.cpp:536] Trying to chown 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/executors/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/runs/90fa9865-e813-4e21-9bc9-602789c12c78'
 to user 'mesos'
I1017 06:20:21.162441 29239 slave.cpp:6572] Checkpointing ExecutorInfo to 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/executors/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/executor.info'
I1017 06:20:21.163183 29239 slave.cpp:6179] Launching executor 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000 with resources cpus(*):0.1; mem(*):32 
in work directory 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/executors/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/runs/90fa9865-e813-4e21-9bc9-602789c12c78'
I1017 06:20:21.163991 29247 containerizer.cpp:938] Starting container 
90fa9865-e813-4e21-9bc9-602789c12c78 for executor 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.164162 29239 slave.cpp:6595] Checkpointing TaskInfo to 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/executors/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/runs/90fa9865-e813-4e21-9bc9-602789c12c78/tasks/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/task.info'
I1017 06:20:21.164703 29239 slave.cpp:1987] Queued task 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' for executor 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.164805 29239 slave.cpp:868] Successfully attached file 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/executors/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/runs/90fa9865-e813-4e21-9bc9-602789c12c78'
I1017 06:20:21.167628 29250 leveldb.cpp:341] Persisting action (16 bytes) to 
leveldb took 60.937751ms
I1017 06:20:21.167672 29250 replica.cpp:708] Persisted action TRUNCATE at 
position 4
I1017 06:20:21.167788 29243 containerizer.cpp:1452] Launching 
'mesos-containerizer' with flags 
'--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.1.0\/_build\/src"],"shell":false,"value":"\/mesos\/mesos-1.1.0\/_build\/src\/mesos-executor"}"
 
--environment="{"LIBPROCESS_PORT":"0","MESOS_AGENT_ENDPOINT":"172.17.0.2:41176","MESOS_CHECKPOINT":"1","MESOS_DIRECTORY":"\/tmp\/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e\/slaves\/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0\/frameworks\/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000\/executors\/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a\/runs\/90fa9865-e813-4e21-9bc9-602789c12c78","MESOS_EXECUTOR_ID":"f83c5fdc-ed77-4d41-90ed-afcb6f9a191a","MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD":"5secs","MESOS_FRAMEWORK_ID":"1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000","MESOS_HTTP_COMMAND_EXECUTOR":"0","MESOS_RECOVERY_TIMEOUT":"15mins","MESOS_SANDBOX":"\/tmp\/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e\/slaves\/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0\/frameworks\/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000\/executors\/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a\/runs\/90fa9865-e813-4e21-9bc9-602789c12c78","MESOS_SLAVE_ID":"1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0","MESOS_SLAVE_PID":"slave(414)@172.17.0.2:41176","MESOS_SUBSCRIPTION_BACKOFF_MAX":"2secs","PATH":"\/usr\/local\/sbin:\/usr\/local\/bin:\/usr\/sbin:\/usr\/bin:\/sbin:\/bin"}"
 --help="false" --pipe_read="22" --pipe_write="27" --pre_exec_commands="[]" 
--runtime_directory="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_JbWdWX/containers/90fa9865-e813-4e21-9bc9-602789c12c78"
 --unshare_namespace_mnt="false" --user="mesos" 
--working_directory="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/executors/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/runs/90fa9865-e813-4e21-9bc9-602789c12c78"'
I1017 06:20:21.171249 29243 launcher.cpp:127] Forked child with pid '7278' for 
container '90fa9865-e813-4e21-9bc9-602789c12c78'
I1017 06:20:21.171564 29243 containerizer.cpp:1489] Checkpointing container's 
forked pid 7278 to 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/executors/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/runs/90fa9865-e813-4e21-9bc9-602789c12c78/pids/forked.pid'
I1017 06:20:21.171757 29244 replica.cpp:691] Replica received learned notice 
for position 4 from @0.0.0.0:0
I1017 06:20:21.235347 29244 leveldb.cpp:341] Persisting action (18 bytes) to 
leveldb took 63.492395ms
I1017 06:20:21.235489 29244 leveldb.cpp:399] Deleting ~2 keys from leveldb took 
70147ns
I1017 06:20:21.235525 29244 replica.cpp:708] Persisted action TRUNCATE at 
position 4
I1017 06:20:21.357409  7314 exec.cpp:162] Version: 1.1.0
I1017 06:20:21.361183 29241 slave.cpp:3231] Got registration for executor 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000 from executor(1)@172.17.0.2:55628
I1017 06:20:21.361867 29241 slave.cpp:3317] Checkpointing executor pid 
'executor(1)@172.17.0.2:55628' to 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/executors/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/runs/90fa9865-e813-4e21-9bc9-602789c12c78/pids/libprocess.pid'
I1017 06:20:21.363008 29241 slave.cpp:787] Agent terminating
I1017 06:20:21.363404 29241 master.cpp:1258] Agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 at slave(414)@172.17.0.2:41176 
(8082f3c85866) disconnected
I1017 06:20:21.363433 29245 hierarchical.cpp:1694] No allocations performed
I1017 06:20:21.363436 29241 master.cpp:2947] Disconnecting agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 at slave(414)@172.17.0.2:41176 
(8082f3c85866)
I1017 06:20:21.363483 29245 hierarchical.cpp:1789] No inverse offers to send 
out!
I1017 06:20:21.363531 29241 master.cpp:2966] Deactivating agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 at slave(414)@172.17.0.2:41176 
(8082f3c85866)
I1017 06:20:21.363564 29245 hierarchical.cpp:1286] Performed allocation for 1 
agents in 325515ns
I1017 06:20:21.363690 29245 hierarchical.cpp:584] Agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0 deactivated
I1017 06:20:21.364490 29219 containerizer.cpp:200] Using isolation: 
posix/cpu,posix/mem,filesystem/posix,network/cni
I1017 06:20:21.365317  7315 exec.cpp:237] Executor registered on agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0
W1017 06:20:21.365375 29219 backend.cpp:75] Failed to create 'aufs' backend: 
AufsBackend requires root privileges, but is running as user mesos
W1017 06:20:21.365687 29219 backend.cpp:75] Failed to create 'bind' backend: 
BindBackend requires root privileges
Received SUBSCRIBED event
Subscribed executor on 8082f3c85866
I1017 06:20:21.371932 29219 cluster.cpp:435] Creating default 'local' authorizer
I1017 06:20:21.373802 29251 slave.cpp:208] Mesos agent started on 
(415)@172.17.0.2:41176
I1017 06:20:21.373832 29251 slave.cpp:209] Flags at startup: --acls="" 
--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" --container_disk_watch_interval="15secs" 
--containerizers="mesos" 
--credential="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_JbWdWX/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="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_JbWdWX/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="false" 
--http_credentials="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_JbWdWX/http_credentials"
 --image_provisioner_backend="copy" --initialize_driver_logging="true" 
--isolation="posix/cpu,posix/mem" --launcher="posix" 
--launcher_dir="/mesos/mesos-1.1.0/_build/src" --logbufsecs="0" 
--logging_level="INFO" --max_completed_executors_per_framework="150" 
--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="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_JbWdWX"
 --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" 
--systemd_enable_support="true" 
--systemd_runtime_directory="/run/systemd/system" --version="false" 
--work_dir="/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e"
I1017 06:20:21.374781 29251 credentials.hpp:86] Loading credential for 
authentication from 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_JbWdWX/credential'
I1017 06:20:21.375134 29251 slave.cpp:346] Agent using credential for: 
test-principal
I1017 06:20:21.375169 29251 credentials.hpp:37] Loading credentials for 
authentication from 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_JbWdWX/http_credentials'
I1017 06:20:21.375592 29251 http.cpp:887] Using default 'basic' HTTP 
authenticator for realm 'mesos-agent-readonly'
I1017 06:20:21.375805 29251 http.cpp:887] Using default 'basic' HTTP 
authenticator for realm 'mesos-agent-readwrite'
I1017 06:20:21.378207 29251 slave.cpp:533] Agent resources: cpus(*):2; 
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1017 06:20:21.378343 29251 slave.cpp:541] Agent attributes: [  ]
I1017 06:20:21.378360 29251 slave.cpp:546] Agent hostname: 8082f3c85866
I1017 06:20:21.380522 29242 state.cpp:57] Recovering state from 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta'
I1017 06:20:21.380635 29242 state.cpp:698] No committed checkpointed resources 
found at 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta/resources/resources.info'
../../src/tests/slave_recovery_tests.cpp:4058: Failure
Value of: containers.get().size()
  Actual: 0
Expected: 1u
Which is: 1
*** Aborted at 1476685221 (unix time) try "date -d @1476685221" if you are 
using GNU date ***
W1017 06:20:21.382722 29242 state.cpp:606] Failed to find status updates file 
'/tmp/MesosContainerizerSlaveRecoveryTest_ResourceStatistics_kEPG5e/meta/slaves/1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0/frameworks/1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000/executors/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/runs/90fa9865-e813-4e21-9bc9-602789c12c78/tasks/f83c5fdc-ed77-4d41-90ed-afcb6f9a191a/task.updates'
I1017 06:20:21.385927 29245 fetcher.cpp:86] Clearing fetcher cache
I1017 06:20:21.386095 29245 slave.cpp:5369] Recovering framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.386236 29245 slave.cpp:6329] Recovering executor 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.387619 29242 status_update_manager.cpp:203] Recovering status 
update manager
I1017 06:20:21.387687 29242 status_update_manager.cpp:211] Recovering executor 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
W1017 06:20:21.387749 29242 status_update_manager.cpp:250] No updates found for 
task f83c5fdc-ed77-4d41-90ed-afcb6f9a191a of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.389015 29252 containerizer.cpp:555] Recovering containerizer
I1017 06:20:21.389104 29252 containerizer.cpp:611] Recovering container 
90fa9865-e813-4e21-9bc9-602789c12c78 for executor 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.391762 29247 provisioner.cpp:253] Provisioner recovery complete
I1017 06:20:21.392659 29243 slave.cpp:5221] Sending reconnect request to 
executor 'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000 at executor(1)@172.17.0.2:55628
I1017 06:20:21.393618  7318 exec.cpp:283] Received reconnect request from agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0
I1017 06:20:21.394454 29250 slave.cpp:3421] Re-registering executor 
'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a' of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.394932 29250 slave.cpp:3507] Transitioning STAGED task 
f83c5fdc-ed77-4d41-90ed-afcb6f9a191a to LOST because it is unknown to the 
executor 'f83c5fdc-ed77-4d41-90ed-afcb6f9a191a'
I1017 06:20:21.395026 29250 slave.cpp:3634] Handling status update TASK_LOST 
(UUID: 815296cb-0570-4654-90af-0206b8b5fdab) for task 
f83c5fdc-ed77-4d41-90ed-afcb6f9a191a of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000 from @0.0.0.0:0
I1017 06:20:21.396057  7314 exec.cpp:260] Executor re-registered on agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0
Received SUBSCRIBED event
Subscribed executor on 8082f3c85866
I1017 06:20:21.397830 29248 status_update_manager.cpp:323] Received status 
update TASK_LOST (UUID: 815296cb-0570-4654-90af-0206b8b5fdab) for task 
f83c5fdc-ed77-4d41-90ed-afcb6f9a191a of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.397884 29248 status_update_manager.cpp:500] Creating 
StatusUpdate stream for task f83c5fdc-ed77-4d41-90ed-afcb6f9a191a of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.398752 29248 status_update_manager.cpp:832] Checkpointing UPDATE 
for status update TASK_LOST (UUID: 815296cb-0570-4654-90af-0206b8b5fdab) for 
task f83c5fdc-ed77-4d41-90ed-afcb6f9a191a of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
I1017 06:20:21.399133 29248 status_update_manager.cpp:377] Forwarding update 
TASK_LOST (UUID: 815296cb-0570-4654-90af-0206b8b5fdab) for task 
f83c5fdc-ed77-4d41-90ed-afcb6f9a191a of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000 to the agent
PC: @     0x2ab9d1ad50ac mesos::ContainerID::MergeFrom()
W1017 06:20:21.399471 29250 slave.cpp:3997] Dropping status update TASK_LOST 
(UUID: 815296cb-0570-4654-90af-0206b8b5fdab) for task 
f83c5fdc-ed77-4d41-90ed-afcb6f9a191a of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000 sent by status update manager because 
the agent is in RECOVERING state
*** SIGSEGV (@0x18) received by PID 29219 (TID 0x2ab9cccf7a80) from PID 24; 
stack trace: ***
I1017 06:20:21.399626 29250 slave.cpp:3945] Status update manager successfully 
handled status update TASK_LOST (UUID: 815296cb-0570-4654-90af-0206b8b5fdab) 
for task f83c5fdc-ed77-4d41-90ed-afcb6f9a191a of framework 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-0000
    @     0x2aba28f8b2c7 (unknown)
    @     0x2aba28f8f5a9 (unknown)
    @     0x2ab9d4209330 (unknown)
    @     0x2ab9d1ad50ac mesos::ContainerID::MergeFrom()
    @     0x2ab9d1ad44c2 mesos::ContainerID::ContainerID()
    @          0x167c812 
mesos::internal::tests::MesosContainerizerSlaveRecoveryTest_ResourceStatistics_Test::TestBody()
    @          0x1b51dba 
testing::internal::HandleSehExceptionsInMethodIfSupported<>()
    @          0x1b4cee0 
testing::internal::HandleExceptionsInMethodIfSupported<>()
    @          0x1b2e6a1 testing::Test::Run()
    @          0x1b2ee24 testing::TestInfo::Run()
    @          0x1b2f46a testing::TestCase::Run()
    @          0x1b35bb2 testing::internal::UnitTestImpl::RunAllTests()
    @          0x1b529df 
testing::internal::HandleSehExceptionsInMethodIfSupported<>()
    @          0x1b4da20 
testing::internal::HandleExceptionsInMethodIfSupported<>()
    @          0x1b3494e testing::UnitTest::Run()
    @          0x10bd1bd RUN_ALL_TESTS()
    @          0x10bcd83 main
    @     0x2ab9d4438f45 (unknown)
    @           0xa1c5f9 (unknown)
make[4]: *** [check-local] Segmentation fault
I1017 06:20:21.519263  7318 exec.cpp:487] Agent exited, but framework has 
checkpointing enabled. Waiting 15mins to reconnect with agent 
1e69aad0-d5e7-47b5-8d30-41192e2ade17-S0
make[4]: Leaving directory `/mesos/mesos-1.1.0/_build/src'
I1017 06:20:21.519732  7311 exec.cpp:496] Agent exited ... shutting down
make[3]: *** [check-am] Error 2
Received SHUTDOWN event
Shutting down
make[3]: Leaving directory `/mesos/mesos-1.1.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-1.1.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-1.1.0/_build'
make: *** [distcheck] Error 1
+ docker rmi mesos-1476681773-4592
Untagged: mesos-1476681773-4592:latest
Deleted: sha256:381913c041614478b991958bbc609cd035db1bf9d30de39bc7343097263b94dc
Deleted: sha256:5a7482c59f74f36956f9b09453404216a19435fd4a489fa1232f8bb4e6d8f922
Deleted: sha256:0a0ab215031d2cd583f45de51ad49cc18bce6f83f4e1edb6d3aad6209d84958b
Deleted: sha256:6e35ba2a9a7c8b4f892db9401e662315f4b7abfc142c53a75947d047c409fc9b
Deleted: sha256:7e444bfb1f7849fa9497d7515c4011b85a6a1be61c39cda5acd81e6c90ac3ff1
Deleted: sha256:09fa7fe716e01de35ed5632f145372f1d7139dc6562fd9a15718220f7df41c1b
Deleted: sha256:62e1443fac4853efad5543e8ddbdefcbb9fe3a27c95e5e583508f9aa166d5b41
Deleted: sha256:2cf51108bc1bcba45ac38568126a8ba2367ce256ae6b5e894b831036f89dc69d
Deleted: sha256:cdf1894674e971a8413f9910fe22cd302a06c6b6281bb1406b1b5166ae43f9ff
Deleted: sha256:6fb454b8290aa82e5effe9cb1deac0e93c7b4b2ec949e27abe2e36c1042dd3dc
Deleted: sha256:bf0332706aa09270aa0cf1165ffe658278e18e279a8b20ea0e042c2e5873c699
Deleted: sha256:acebfe71c06abe7dc675933b277637316a0414683675beda951d570635a80d8c
Deleted: sha256:8718cc4643200c45f05b671958b252981b25c009c638dfaa28339d47aacbf279
Deleted: sha256:1113bd8b996f223769cd05e783f572b68422af304a19b41c419cadb269a59709
Deleted: sha256:15ee5dc40be5c14a93d4d2d8ffa7b7af0b6db09e6c4f589ac833b366f19a5af3
Deleted: sha256:1f691a1953c3af96f1499ad9bf6a733b7d5f011499d24955d72b8f651a70aaea
Deleted: sha256:807bd7b0748201d193decc9a5d5554134cd780ffe3b62dda81b8dd633f64bc5b
Deleted: sha256:12fc1eadba52ab10f2c5f771f1190bec3d7b9393214c99910eda36a1e89d9e75
Deleted: sha256:4d1a9da3e9d02700f7b767e7781c54374703a90b6ea7dac73a51867fc127eca1
Deleted: sha256:b3f570f692affe48f0eff40ca7be613223070259815461ed1c609ab7f2a42967
Deleted: sha256:8a95a78632e07e684d459153d531a314a5d2443286bfcbf85e4324d4e3b6b001
Deleted: sha256:647059914069462eb6691a8b2da8c6dea253f1ffaae5374e9021780d28e3adbd
Deleted: sha256:fb2858ce22a7c6d6fbc530929f4711b3bf93acb357bec93d61040a8c0c413b4f
Deleted: sha256:6a212a6859dba3e33e6b8fc8d055ca3ebbb3c3ed9ace1ce4f7e60c2632195540
Build step 'Execute shell' marked build as failure

Reply via email to