You are viewing a plain text version of this content. The canonical link for it is here.

Posted to builds@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2017/12/01 16:16:32 UTC

Build failed in Jenkins: Mesos-Buildbot » cmake,gcc,--verbose --disable-libtool-wrappers,GLOG_v=1 MESOS_VERBOSE=1,ubuntu:14.04,(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23) #4527

See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4527/display/redirect?page=changes>

Changes:

[mpark] Fixed inconsistent naming in index sequence.

------------------------------------------
[...truncated 5.18 MB...]
3: I1201 16:16:28.378538 17394 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0d2131d4ffd2' server FQDN: '0d2131d4ffd2' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
3: I1201 16:16:28.378551 17394 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.378561 17394 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.378590 17394 authenticator.cpp:318] Authentication success
3: I1201 16:16:28.378753 17396 authenticatee.cpp:299] Authentication success
3: I1201 16:16:28.378907 17397 master.cpp:8619] Successfully authenticated principal 'test-principal' at scheduler-70a74fb6-a097-4f61-8899-a65387da0922@172.17.0.2:45312
3: I1201 16:16:28.379041 17391 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(216)@172.17.0.2:45312
3: I1201 16:16:28.379304 17409 sched.cpp:502] Successfully authenticated with master master@172.17.0.2:45312
3: I1201 16:16:28.379345 17409 sched.cpp:824] Sending SUBSCRIBE call to master@172.17.0.2:45312
3: I1201 16:16:28.379520 17409 sched.cpp:857] Will retry registration in 1.802370932secs if necessary
3: I1201 16:16:28.379839 17401 master.cpp:2969] Received SUBSCRIBE call for framework 'default' at scheduler-70a74fb6-a097-4f61-8899-a65387da0922@172.17.0.2:45312
3: I1201 16:16:28.379977 17401 master.cpp:2286] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
3: I1201 16:16:28.380152 17389 state.cpp:64] Recovering state from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterPendingTask_ZAo1Bw/meta'
3: I1201 16:16:28.380595 17389 task_status_update_manager.cpp:207] Recovering task status update manager
3: I1201 16:16:28.380784 17404 master.cpp:3049] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
3: I1201 16:16:28.380913 17407 containerizer.cpp:672] Recovering containerizer
3: I1201 16:16:28.381659 17404 sched.cpp:751] Framework registered with b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000
3: I1201 16:16:28.381767 17404 sched.cpp:765] Scheduler::registered took 70792ns
3: I1201 16:16:28.381904 17408 hierarchical.cpp:293] Added framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000
3: I1201 16:16:28.382208 17408 hierarchical.cpp:1431] Performed allocation for 0 agents in 110318ns
3: I1201 16:16:28.383029 17410 provisioner.cpp:493] Provisioner recovery complete
3: I1201 16:16:28.383576 17400 slave.cpp:6513] Finished recovery
3: I1201 16:16:28.384538 17403 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1201 16:16:28.384541 17389 slave.cpp:999] New master detected at master@172.17.0.2:45312
3: I1201 16:16:28.384687 17389 slave.cpp:1034] Detecting new master
3: I1201 16:16:28.393079 17393 slave.cpp:1061] Authenticating with master master@172.17.0.2:45312
3: I1201 16:16:28.393177 17393 slave.cpp:1070] Using default CRAM-MD5 authenticatee
3: I1201 16:16:28.393487 17402 authenticatee.cpp:121] Creating new client SASL connection
3: I1201 16:16:28.393882 17399 master.cpp:8589] Authenticating slave(103)@172.17.0.2:45312
3: I1201 16:16:28.394044 17392 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(217)@172.17.0.2:45312
3: I1201 16:16:28.394398 17387 authenticator.cpp:98] Creating new server SASL connection
3: I1201 16:16:28.394695 17396 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1201 16:16:28.394731 17396 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1201 16:16:28.394882 17396 authenticator.cpp:204] Received SASL authentication start
3: I1201 16:16:28.394946 17396 authenticator.cpp:326] Authentication requires more steps
3: I1201 16:16:28.395100 17404 authenticatee.cpp:259] Received SASL authentication step
3: I1201 16:16:28.395261 17404 authenticator.cpp:232] Received SASL authentication step
3: I1201 16:16:28.395298 17404 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0d2131d4ffd2' server FQDN: '0d2131d4ffd2' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
3: I1201 16:16:28.395313 17404 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1201 16:16:28.395346 17404 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1201 16:16:28.395375 17404 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0d2131d4ffd2' server FQDN: '0d2131d4ffd2' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
3: I1201 16:16:28.395390 17404 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.395398 17404 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.395416 17404 authenticator.cpp:318] Authentication success
3: I1201 16:16:28.395589 17390 authenticatee.cpp:299] Authentication success
3: I1201 16:16:28.395642 17401 master.cpp:8619] Successfully authenticated principal 'test-principal' at slave(103)@172.17.0.2:45312
3: I1201 16:16:28.395686 17391 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(217)@172.17.0.2:45312
3: I1201 16:16:28.396025 17390 slave.cpp:1153] Successfully authenticated with master master@172.17.0.2:45312
3: I1201 16:16:28.396469 17390 slave.cpp:1696] Will retry registration in 5.187814ms if necessary
3: I1201 16:16:28.396767 17410 master.cpp:6042] Received register agent message from slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.396956 17410 master.cpp:3878] Authorizing agent with principal 'test-principal'
3: I1201 16:16:28.397523 17400 master.cpp:6104] Authorized registration of agent at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.397680 17400 master.cpp:6197] Registering agent at slave(103)@172.17.0.2:45312 (0d2131d4ffd2) with id b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0
3: I1201 16:16:28.398372 17398 registrar.cpp:495] Applied 1 operations in 94918ns; attempting to update the registry
3: I1201 16:16:28.399209 17398 registrar.cpp:552] Successfully updated the registry in 740864ns
3: I1201 16:16:28.399547 17393 master.cpp:6246] Admitted agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.400588 17393 master.cpp:6282] Registered agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I1201 16:16:28.400688 17399 slave.cpp:1199] Registered with master master@172.17.0.2:45312; given agent ID b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0
3: I1201 16:16:28.400883 17407 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I1201 16:16:28.401118 17392 hierarchical.cpp:553] Added agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 (0d2131d4ffd2) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
3: I1201 16:16:28.401201 17399 slave.cpp:1219] Checkpointing SlaveInfo to '/tmp/MasterSlaveReconciliationTest_SlaveReregisterPendingTask_ZAo1Bw/meta/slaves/b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0/slave.info'
3: I1201 16:16:28.401924 17399 slave.cpp:1298] Forwarding total oversubscribed resources {}
3: I1201 16:16:28.402220 17397 master.cpp:7049] Received update of agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2) with total oversubscribed resources {}
3: I1201 16:16:28.402504 17397 master.cpp:7092] Ignoring update on agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2) as it reports no changes
3: I1201 16:16:28.402910 17392 hierarchical.cpp:1431] Performed allocation for 1 agents in 1.550762ms
3: I1201 16:16:28.403576 17404 master.cpp:8419] Sending 1 offers to framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 (default) at scheduler-70a74fb6-a097-4f61-8899-a65387da0922@172.17.0.2:45312
3: I1201 16:16:28.404418 17408 sched.cpp:921] Scheduler::resourceOffers took 164974ns
3: I1201 16:16:28.407236 17395 master.cpp:10331] Removing offer b5ad9c04-24f9-4b62-9820-5a9255d08e8e-O0
3: I1201 16:16:28.407480 17395 master.cpp:4236] Processing ACCEPT call for offers: [ b5ad9c04-24f9-4b62-9820-5a9255d08e8e-O0 ] on agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2) for framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 (default) at scheduler-70a74fb6-a097-4f61-8899-a65387da0922@172.17.0.2:45312
3: I1201 16:16:28.407634 17395 master.cpp:3605] Authorizing framework principal 'test-principal' to launch task 1
3: W1201 16:16:28.410436 17405 validation.cpp:1391] Executor 'default' for task '1' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
3: W1201 16:16:28.410487 17405 validation.cpp:1403] Executor 'default' for task '1' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
3: I1201 16:16:28.411298 17405 master.cpp:11091] Adding task 1 with resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] on agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.411818 17405 master.cpp:4984] Launching task 1 of framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 (default) at scheduler-70a74fb6-a097-4f61-8899-a65387da0922@172.17.0.2:45312 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] on agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.412900 17398 slave.cpp:1817] Got assigned task '1' for framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000
3: I1201 16:16:28.414897 17392 slave.cpp:999] New master detected at master@172.17.0.2:45312
3: I1201 16:16:28.414923 17404 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1201 16:16:28.415032 17392 slave.cpp:1034] Detecting new master
3: I1201 16:16:28.422510 17401 slave.cpp:1061] Authenticating with master master@172.17.0.2:45312
3: I1201 16:16:28.422590 17401 slave.cpp:1070] Using default CRAM-MD5 authenticatee
3: I1201 16:16:28.422888 17388 authenticatee.cpp:121] Creating new client SASL connection
3: I1201 16:16:28.423254 17406 master.cpp:8589] Authenticating slave(103)@172.17.0.2:45312
3: I1201 16:16:28.423435 17409 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(218)@172.17.0.2:45312
3: I1201 16:16:28.423759 17390 authenticator.cpp:98] Creating new server SASL connection
3: I1201 16:16:28.424106 17410 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1201 16:16:28.424154 17410 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1201 16:16:28.424394 17391 authenticator.cpp:204] Received SASL authentication start
3: I1201 16:16:28.424487 17391 authenticator.cpp:326] Authentication requires more steps
3: I1201 16:16:28.424695 17400 authenticatee.cpp:259] Received SASL authentication step
3: I1201 16:16:28.424883 17400 authenticator.cpp:232] Received SASL authentication step
3: I1201 16:16:28.424923 17400 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0d2131d4ffd2' server FQDN: '0d2131d4ffd2' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
3: I1201 16:16:28.424942 17400 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1201 16:16:28.424978 17400 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1201 16:16:28.425006 17400 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0d2131d4ffd2' server FQDN: '0d2131d4ffd2' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
3: I1201 16:16:28.425021 17400 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.425030 17400 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.425048 17400 authenticator.cpp:318] Authentication success
3: I1201 16:16:28.425180 17403 authenticatee.cpp:299] Authentication success
3: I1201 16:16:28.425297 17389 master.cpp:8619] Successfully authenticated principal 'test-principal' at slave(103)@172.17.0.2:45312
3: I1201 16:16:28.425401 17394 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(218)@172.17.0.2:45312
3: I1201 16:16:28.425631 17405 slave.cpp:1153] Successfully authenticated with master master@172.17.0.2:45312
3: I1201 16:16:28.426267 17405 slave.cpp:1696] Will retry registration in 6.72622ms if necessary
3: I1201 16:16:28.426834 17407 master.cpp:6371] Received re-register agent message from agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.427098 17407 master.cpp:3878] Authorizing agent with principal 'test-principal'
3: I1201 16:16:28.427820 17397 master.cpp:6442] Authorized re-registration of agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.427953 17397 master.cpp:6507] Re-registering agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: W1201 16:16:28.428445 17397 master.cpp:8749] Executor 'default' of framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 possibly unknown to the agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.428548 17397 master.cpp:9942] Removing executor 'default' with resources [] of framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 on agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.428725 17404 slave.cpp:1343] Re-registered with master master@172.17.0.2:45312
3: I1201 16:16:28.428907 17401 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I1201 16:16:28.429014 17397 master.cpp:6614] Sending updated checkpointed resources {} to agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.429026 17404 slave.cpp:1411] Forwarding total oversubscribed resources {}
3: I1201 16:16:28.429370 17397 master.cpp:7049] Received update of agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2) with total oversubscribed resources {}
3: I1201 16:16:28.429391 17404 slave.cpp:3452] Updating info for framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 with pid updated to scheduler-70a74fb6-a097-4f61-8899-a65387da0922@172.17.0.2:45312
3: I1201 16:16:28.429613 17410 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I1201 16:16:28.429633 17404 slave.cpp:3530] Ignoring new checkpointed resources identical to the current version: {}
3: I1201 16:16:28.429638 17397 master.cpp:7092] Ignoring update on agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2) as it reports no changes
3: I1201 16:16:28.429795 17386 sched.cpp:2009] Asked to stop the driver
3: I1201 16:16:28.429929 17391 sched.cpp:1191] Stopping framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000
3: I1201 16:16:28.430304 17395 master.cpp:9096] Processing TEARDOWN call for framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 (default) at scheduler-70a74fb6-a097-4f61-8899-a65387da0922@172.17.0.2:45312
3: I1201 16:16:28.430352 17395 master.cpp:9108] Removing framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 (default) at scheduler-70a74fb6-a097-4f61-8899-a65387da0922@172.17.0.2:45312
3: I1201 16:16:28.430373 17395 master.cpp:3339] Deactivating framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 (default) at scheduler-70a74fb6-a097-4f61-8899-a65387da0922@172.17.0.2:45312
3: I1201 16:16:28.430595 17389 hierarchical.cpp:406] Deactivated framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000
3: I1201 16:16:28.430688 17395 master.cpp:9807] Updating the state of task 1 of framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
3: I1201 16:16:28.430693 17398 slave.cpp:3281] Asked to shut down framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 by master@172.17.0.2:45312
3: I1201 16:16:28.430784 17398 slave.cpp:3306] Shutting down framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000
3: I1201 16:16:28.431252 17407 slave.cpp:875] Agent terminating
3: I1201 16:16:28.431332 17407 slave.cpp:3281] Asked to shut down framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 by @0.0.0.0:0
3: W1201 16:16:28.431377 17407 slave.cpp:3302] Ignoring shutdown framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 because it is terminating
3: I1201 16:16:28.431980 17395 master.cpp:9913] Removing task 1 with resources cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] of framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000 on agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.432548 17394 hierarchical.cpp:1106] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 from framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000
3: I1201 16:16:28.432749 17395 master.cpp:1317] Agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2) disconnected
3: I1201 16:16:28.432786 17395 master.cpp:3376] Disconnecting agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.432852 17395 master.cpp:3395] Deactivating agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 at slave(103)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.432962 17394 hierarchical.cpp:345] Removed framework b5ad9c04-24f9-4b62-9820-5a9255d08e8e-0000
3: I1201 16:16:28.433053 17394 hierarchical.cpp:671] Agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0 deactivated
3: I1201 16:16:28.442092 17386 master.cpp:1159] Master terminating
3: I1201 16:16:28.442996 17404 hierarchical.cpp:586] Removed agent b5ad9c04-24f9-4b62-9820-5a9255d08e8e-S0
3: [       OK ] MasterSlaveReconciliationTest.SlaveReregisterPendingTask (105 ms)
3: [ RUN      ] MasterSlaveReconciliationTest.SlaveReregisterTerminalTask
3: I1201 16:16:28.452378 17386 cluster.cpp:170] Creating default 'local' authorizer
3: I1201 16:16:28.456794 17387 master.cpp:454] Master 36b28f17-bd6d-426b-a787-0b06eb8c7b6e (0d2131d4ffd2) started on 172.17.0.2:45312
3: I1201 16:16:28.456818 17387 master.cpp:456] 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/uMh6LK/credentials" --filter_gpu_resources="true" --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" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/uMh6LK/master" --zk_session_timeout="10secs"
3: I1201 16:16:28.457226 17387 master.cpp:505] Master only allowing authenticated frameworks to register
3: I1201 16:16:28.457237 17387 master.cpp:511] Master only allowing authenticated agents to register
3: I1201 16:16:28.457245 17387 master.cpp:517] Master only allowing authenticated HTTP frameworks to register
3: I1201 16:16:28.457255 17387 credentials.hpp:37] Loading credentials for authentication from '/tmp/uMh6LK/credentials'
3: I1201 16:16:28.457648 17387 master.cpp:561] Using default 'crammd5' authenticator
3: I1201 16:16:28.457861 17387 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
3: I1201 16:16:28.458071 17387 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
3: I1201 16:16:28.458261 17387 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
3: I1201 16:16:28.458441 17387 master.cpp:640] Authorization enabled
3: I1201 16:16:28.458703 17390 whitelist_watcher.cpp:77] No whitelist given
3: I1201 16:16:28.458706 17403 hierarchical.cpp:173] Initialized hierarchical allocator process
3: I1201 16:16:28.462640 17409 master.cpp:2221] Elected as the leading master!
3: I1201 16:16:28.462678 17409 master.cpp:1701] Recovering from registrar
3: I1201 16:16:28.462893 17392 registrar.cpp:347] Recovering registrar
3: I1201 16:16:28.463680 17392 registrar.cpp:391] Successfully fetched the registry (0B) in 736us
3: I1201 16:16:28.463824 17392 registrar.cpp:495] Applied 1 operations in 39019ns; attempting to update the registry
3: I1201 16:16:28.464558 17392 registrar.cpp:552] Successfully updated the registry in 674048ns
3: I1201 16:16:28.464699 17392 registrar.cpp:424] Successfully recovered registrar
3: I1201 16:16:28.465139 17394 master.cpp:1814] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
3: I1201 16:16:28.465167 17393 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover
3: W1201 16:16:28.470963 17386 process.cpp:2756] Attempted to spawn already running process files@172.17.0.2:45312
3: I1201 16:16:28.471312 17386 cluster.cpp:458] Creating default 'local' authorizer
3: I1201 16:16:28.475163 17391 slave.cpp:253] Mesos agent started on (104)@172.17.0.2:45312
3: I1201 16:16:28.475186 17391 slave.cpp:254] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_VWHMaS/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/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_VWHMaS/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --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/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_VWHMaS/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_VWHMaS/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_VWHMaS/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --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/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_VWHMaS" --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/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_vpSqtO" --zk_session_timeout="10secs"
3: I1201 16:16:28.475742 17391 credentials.hpp:86] Loading credential for authentication from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_VWHMaS/credential'
3: W1201 16:16:28.475867 17386 process.cpp:2756] Attempted to spawn already running process version@172.17.0.2:45312
3: I1201 16:16:28.475940 17391 slave.cpp:286] Agent using credential for: test-principal
3: I1201 16:16:28.475965 17391 credentials.hpp:37] Loading credentials for authentication from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_VWHMaS/http_credentials'
3: I1201 16:16:28.476328 17391 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1201 16:16:28.476564 17391 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1201 16:16:28.477377 17386 sched.cpp:232] Version: 1.5.0
3: I1201 16:16:28.478255 17390 sched.cpp:336] New master detected at master@172.17.0.2:45312
3: I1201 16:16:28.478422 17390 sched.cpp:396] Authenticating with master master@172.17.0.2:45312
3: I1201 16:16:28.478447 17390 sched.cpp:403] Using default CRAM-MD5 authenticatee
3: I1201 16:16:28.478842 17407 authenticatee.cpp:121] Creating new client SASL connection
3: I1201 16:16:28.479255 17405 master.cpp:8589] Authenticating scheduler-771fc74d-3beb-4004-87da-47544c63f6ea@172.17.0.2:45312
3: I1201 16:16:28.479001 17391 slave.cpp:585] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
3: I1201 16:16:28.479372 17391 slave.cpp:593] Agent attributes: [  ]
3: I1201 16:16:28.479395 17391 slave.cpp:602] Agent hostname: 0d2131d4ffd2
3: I1201 16:16:28.479429 17403 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(219)@172.17.0.2:45312
3: I1201 16:16:28.479573 17405 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1201 16:16:28.479792 17409 authenticator.cpp:98] Creating new server SASL connection
3: I1201 16:16:28.480140 17389 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1201 16:16:28.480201 17389 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1201 16:16:28.480413 17389 authenticator.cpp:204] Received SASL authentication start
3: I1201 16:16:28.480496 17389 authenticator.cpp:326] Authentication requires more steps
3: I1201 16:16:28.480672 17404 authenticatee.cpp:259] Received SASL authentication step
3: I1201 16:16:28.480904 17402 authenticator.cpp:232] Received SASL authentication step
3: I1201 16:16:28.480952 17402 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0d2131d4ffd2' server FQDN: '0d2131d4ffd2' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
3: I1201 16:16:28.480969 17402 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1201 16:16:28.481015 17402 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1201 16:16:28.481045 17402 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0d2131d4ffd2' server FQDN: '0d2131d4ffd2' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
3: I1201 16:16:28.481056 17402 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.481065 17402 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.481086 17402 authenticator.cpp:318] Authentication success
3: I1201 16:16:28.481242 17410 authenticatee.cpp:299] Authentication success
3: I1201 16:16:28.481328 17400 master.cpp:8619] Successfully authenticated principal 'test-principal' at scheduler-771fc74d-3beb-4004-87da-47544c63f6ea@172.17.0.2:45312
3: I1201 16:16:28.481391 17392 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(219)@172.17.0.2:45312
3: I1201 16:16:28.481644 17396 sched.cpp:502] Successfully authenticated with master master@172.17.0.2:45312
3: I1201 16:16:28.481673 17396 sched.cpp:824] Sending SUBSCRIBE call to master@172.17.0.2:45312
3: I1201 16:16:28.481812 17396 sched.cpp:857] Will retry registration in 570.893026ms if necessary
3: I1201 16:16:28.481858 17394 state.cpp:64] Recovering state from '/tmp/MasterSlaveReconciliationTest_SlaveReregisterTerminalTask_vpSqtO/meta'
3: I1201 16:16:28.482062 17408 master.cpp:2969] Received SUBSCRIBE call for framework 'default' at scheduler-771fc74d-3beb-4004-87da-47544c63f6ea@172.17.0.2:45312
3: I1201 16:16:28.482174 17408 master.cpp:2286] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }'
3: I1201 16:16:28.482218 17394 task_status_update_manager.cpp:207] Recovering task status update manager
3: I1201 16:16:28.482691 17405 slave.cpp:6513] Finished recovery
3: I1201 16:16:28.482776 17403 master.cpp:3049] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
3: I1201 16:16:28.483572 17397 sched.cpp:751] Framework registered with 36b28f17-bd6d-426b-a787-0b06eb8c7b6e-0000
3: I1201 16:16:28.483590 17400 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1201 16:16:28.483585 17402 slave.cpp:999] New master detected at master@172.17.0.2:45312
3: I1201 16:16:28.483629 17397 sched.cpp:765] Scheduler::registered took 26040ns
3: I1201 16:16:28.483721 17409 hierarchical.cpp:293] Added framework 36b28f17-bd6d-426b-a787-0b06eb8c7b6e-0000
3: I1201 16:16:28.483726 17402 slave.cpp:1034] Detecting new master
3: I1201 16:16:28.484025 17409 hierarchical.cpp:1431] Performed allocation for 0 agents in 129229ns
3: I1201 16:16:28.492148 17393 slave.cpp:1061] Authenticating with master master@172.17.0.2:45312
3: I1201 16:16:28.492290 17393 slave.cpp:1070] Using default CRAM-MD5 authenticatee
3: I1201 16:16:28.492604 17392 authenticatee.cpp:121] Creating new client SASL connection
3: I1201 16:16:28.493036 17391 master.cpp:8589] Authenticating slave(104)@172.17.0.2:45312
3: I1201 16:16:28.493232 17396 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(220)@172.17.0.2:45312
3: I1201 16:16:28.493582 17398 authenticator.cpp:98] Creating new server SASL connection
3: I1201 16:16:28.493901 17390 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1201 16:16:28.493935 17390 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1201 16:16:28.494081 17390 authenticator.cpp:204] Received SASL authentication start
3: I1201 16:16:28.494154 17390 authenticator.cpp:326] Authentication requires more steps
3: I1201 16:16:28.494297 17390 authenticatee.cpp:259] Received SASL authentication step
3: I1201 16:16:28.494480 17394 authenticator.cpp:232] Received SASL authentication step
3: I1201 16:16:28.494526 17394 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0d2131d4ffd2' server FQDN: '0d2131d4ffd2' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
3: I1201 16:16:28.494545 17394 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1201 16:16:28.494582 17394 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1201 16:16:28.494613 17394 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '0d2131d4ffd2' server FQDN: '0d2131d4ffd2' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
3: I1201 16:16:28.494626 17394 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.494633 17394 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1201 16:16:28.494652 17394 authenticator.cpp:318] Authentication success
3: I1201 16:16:28.494773 17407 authenticatee.cpp:299] Authentication success
3: I1201 16:16:28.494874 17401 master.cpp:8619] Successfully authenticated principal 'test-principal' at slave(104)@172.17.0.2:45312
3: I1201 16:16:28.494946 17387 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(220)@172.17.0.2:45312
3: I1201 16:16:28.495162 17407 slave.cpp:1153] Successfully authenticated with master master@172.17.0.2:45312
3: I1201 16:16:28.495458 17407 slave.cpp:1696] Will retry registration in 5.587632ms if necessary
3: I1201 16:16:28.495764 17410 master.cpp:6042] Received register agent message from slave(104)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.495960 17410 master.cpp:3878] Authorizing agent with principal 'test-principal'
3: I1201 16:16:28.496562 17397 master.cpp:6104] Authorized registration of agent at slave(104)@172.17.0.2:45312 (0d2131d4ffd2)
3: I1201 16:16:28.496692 17397 master.cpp:6197] Registering agent at slave(104)@172.17.0.2:45312 (0d2131d4ffd2) with id 36b28f17-bd6d-426b-a787-0b06eb8c7b6e-S0
3: I1201 16:16:28.497208 17395 registrar.cpp:495] Applied 1 operations in 75281ns; attempting to update the registry
write /dev/stdout: resource temporarily unavailable
Error response from daemon: conflict: unable to remove repository reference "mesos-1512142204-26060" (must force) - container 0d2131d4ffd2 is using its referenced image 3915649b84be
Build step 'Execute shell' marked build as failure

Jenkins build is back to normal : Mesos-Buildbot » cmake,gcc,--verbose --disable-libtool-wrappers,GLOG_v=1 MESOS_VERBOSE=1,ubuntu:14.04,(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23) #4529

Posted by Apache Jenkins Server <je...@builds.apache.org>.

See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4529/display/redirect?page=changes>

Build failed in Jenkins: Mesos-Buildbot » cmake,gcc,--verbose --disable-libtool-wrappers,GLOG_v=1 MESOS_VERBOSE=1,ubuntu:14.04,(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23) #4528

Posted by Apache Jenkins Server <je...@builds.apache.org>.

See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4528/display/redirect>

------------------------------------------
[...truncated 29.79 MB...]
3: I1201 21:21:55.549130 17401 hierarchical.cpp:1431] Performed allocation for 1 agents in 186196ns
3: I1201 21:21:55.552635 17400 master.cpp:10331] Removing offer 0a035826-5fbe-4872-855d-804ebac238d7-O0
3: I1201 21:21:55.552919 17400 master.cpp:4236] Processing ACCEPT call for offers: [ 0a035826-5fbe-4872-855d-804ebac238d7-O0 ] on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82) for framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575
3: I1201 21:21:55.553128 17400 master.cpp:3798] Authorizing principal 'test-principal' to create volumes '[{"allocation_info":{"role":"default-role"},"disk":{"persistence":{"id":"id1","principal":"test-principal"},"source":{"path":{"root":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA\/disk1"},"type":"PATH"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
3: I1201 21:21:55.553843 17400 master.cpp:3605] Authorizing framework principal 'test-principal' to launch task 0bb119be-d164-4f6e-9524-24920e795e94
3: I1201 21:21:55.555929 17399 master.cpp:4712] Applying CREATE operation for volumes [{"allocation_info":{"role":"default-role"},"disk":{"persistence":{"id":"id1","principal":"test-principal"},"source":{"path":{"root":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA\/disk1"},"type":"PATH"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}] from framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575 to agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:55.557052 17399 master.cpp:10228] Sending offer operation '' (uuid: 5249323c-62ab-4992-a5e9-0a0a8e5254b8) to agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:55.559291 17412 slave.cpp:3605] Updated checkpointed resources from {} to disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048
3: I1201 21:21:55.559432 17412 slave.cpp:7079] Updating the state of offer operation '' (uuid: 5249323c-62ab-4992-a5e9-0a0a8e5254b8) of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
3: I1201 21:21:55.559563 17399 master.cpp:11091] Adding task 0bb119be-d164-4f6e-9524-24920e795e94 with resources cpus(allocated: default-role):1; mem(allocated: default-role):128; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048 on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:55.560037 17399 master.cpp:4984] Launching task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575 with resources [{"allocation_info":{"role":"default-role"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"default-role"},"name":"mem","scalar":{"value":128.0},"type":"SCALAR"},{"allocation_info":{"role":"default-role"},"disk":{"persistence":{"id":"id1","principal":"test-principal"},"source":{"path":{"root":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA\/disk1"},"type":"PATH"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}] on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:55.561280 17399 master.cpp:10015] Updating the state of offer operation '' (uuid: 5249323c-62ab-4992-a5e9-0a0a8e5254b8) of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
3: I1201 21:21:55.561594 17409 slave.cpp:1817] Got assigned task '0bb119be-d164-4f6e-9524-24920e795e94' for framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.562324 17409 slave.cpp:2085] Authorizing task '0bb119be-d164-4f6e-9524-24920e795e94' for framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.562396 17409 slave.cpp:7411] Authorizing framework principal 'test-principal' to launch task 0bb119be-d164-4f6e-9524-24920e795e94
3: I1201 21:21:55.563328 17397 slave.cpp:2253] Launching task '0bb119be-d164-4f6e-9524-24920e795e94' for framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.564579 17397 paths.cpp:692] Trying to chown '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/5bbd75a6-b986-4893-b5e2-30362571c478' to user 'mesos'
3: I1201 21:21:55.565106 17407 hierarchical.cpp:830] Updated allocation of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 from cpus(allocated: default-role):2; mem(allocated: default-role):2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk2]:2048; ports(allocated: default-role):[31000-32000] to cpus(allocated: default-role):2; mem(allocated: default-role):2048; ports(allocated: default-role):[31000-32000]; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048
3: I1201 21:21:55.564911 17397 slave.cpp:7885] Launching executor '0bb119be-d164-4f6e-9524-24920e795e94' of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 with resources [{"allocation_info":{"role":"default-role"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"default-role"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}] in work directory '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/5bbd75a6-b986-4893-b5e2-30362571c478'
3: I1201 21:21:55.566344 17397 slave.cpp:2944] Launching container 5bbd75a6-b986-4893-b5e2-30362571c478 for executor '0bb119be-d164-4f6e-9524-24920e795e94' of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.566516 17407 hierarchical.cpp:1106] Recovered cpus(allocated: default-role):1; mem(allocated: default-role):1920; ports(allocated: default-role):[31000-32000]; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk2]:2048 (total: cpus:2; mem:2048; ports:[31000-32000]; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk2]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048, allocated: cpus(allocated: default-role):1; mem(allocated: default-role):128; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048) on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 from framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.566624 17407 hierarchical.cpp:1152] Framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 filtered agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 for 5secs
3: I1201 21:21:55.566763 17406 containerizer.cpp:1199] Starting container 5bbd75a6-b986-4893-b5e2-30362571c478
3: I1201 21:21:55.566881 17397 slave.cpp:2481] Queued task '0bb119be-d164-4f6e-9524-24920e795e94' for executor '0bb119be-d164-4f6e-9524-24920e795e94' of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.567020 17397 slave.cpp:950] Successfully attached '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/5bbd75a6-b986-4893-b5e2-30362571c478' to virtual path '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/latest'
3: I1201 21:21:55.567087 17397 slave.cpp:950] Successfully attached '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/5bbd75a6-b986-4893-b5e2-30362571c478' to virtual path '/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/latest'
3: I1201 21:21:55.567144 17397 slave.cpp:950] Successfully attached '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/5bbd75a6-b986-4893-b5e2-30362571c478' to virtual path '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/5bbd75a6-b986-4893-b5e2-30362571c478'
3: I1201 21:21:55.567917 17406 containerizer.cpp:1371] Checkpointed ContainerConfig at '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_s9Wo9b/containers/5bbd75a6-b986-4893-b5e2-30362571c478/config'
3: I1201 21:21:55.567957 17406 containerizer.cpp:2923] Transitioning the state of container 5bbd75a6-b986-4893-b5e2-30362571c478 from PROVISIONING to PREPARING
3: I1201 21:21:55.568645 17411 posix.cpp:204] Changing the ownership of the persistent volume at '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1/volumes/roles/default-role/id1' with uid 1000 and gid 1000
3: I1201 21:21:55.568740 17411 posix.cpp:250] Adding symlink from '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1/volumes/roles/default-role/id1' to '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/5bbd75a6-b986-4893-b5e2-30362571c478/path1' for persistent volume disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048 of container 5bbd75a6-b986-4893-b5e2-30362571c478
3: I1201 21:21:55.574328 17396 containerizer.cpp:1840] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["mesos-executor","--launcher_dir=\/mesos\/build\/src"],"shell":false,"value":"\/mesos\/build\/src\/mesos-executor"},"environment":{"variables":[{"name":"LIBPROCESS_PORT","type":"VALUE","value":"0"},{"name":"MESOS_AGENT_ENDPOINT","type":"VALUE","value":"172.17.0.3:33575"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT\/slaves\/0a035826-5fbe-4872-855d-804ebac238d7-S0\/frameworks\/0a035826-5fbe-4872-855d-804ebac238d7-0000\/executors\/0bb119be-d164-4f6e-9524-24920e795e94\/runs\/5bbd75a6-b986-4893-b5e2-30362571c478"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"0bb119be-d164-4f6e-9524-24920e795e94"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"0a035826-5fbe-4872-855d-804ebac238d7-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"0a035826-5fbe-4872-855d-804ebac238d7-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(883)@172.17.0.3:33575"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT\/slaves\/0a035826-5fbe-4872-855d-804ebac238d7-S0\/frameworks\/0a035826-5fbe-4872-855d-804ebac238d7-0000\/executors\/0bb119be-d164-4f6e-9524-24920e795e94\/runs\/5bbd75a6-b986-4893-b5e2-30362571c478"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT\/slaves\/0a035826-5fbe-4872-855d-804ebac238d7-S0\/frameworks\/0a035826-5fbe-4872-855d-804ebac238d7-0000\/executors\/0bb119be-d164-4f6e-9524-24920e795e94\/runs\/5bbd75a6-b986-4893-b5e2-30362571c478"}" --pipe_read="19" --pipe_write="20" --runtime_directory="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_s9Wo9b/containers/5bbd75a6-b986-4893-b5e2-30362571c478" --unshare_namespace_mnt="false"'
3: I1201 21:21:55.578845 17396 launcher.cpp:140] Forked child with pid '26363' for container '5bbd75a6-b986-4893-b5e2-30362571c478'
3: I1201 21:21:55.579566 17396 containerizer.cpp:2923] Transitioning the state of container 5bbd75a6-b986-4893-b5e2-30362571c478 from PREPARING to ISOLATING
3: I1201 21:21:55.581864 17397 containerizer.cpp:2923] Transitioning the state of container 5bbd75a6-b986-4893-b5e2-30362571c478 from ISOLATING to FETCHING
3: I1201 21:21:55.582350 17411 fetcher.cpp:379] Starting to fetch URIs for container: 5bbd75a6-b986-4893-b5e2-30362571c478, directory: /tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/5bbd75a6-b986-4893-b5e2-30362571c478
3: I1201 21:21:55.583529 17394 containerizer.cpp:2923] Transitioning the state of container 5bbd75a6-b986-4893-b5e2-30362571c478 from FETCHING to RUNNING
3: I1201 21:21:55.883426 26364 exec.cpp:162] Version: 1.5.0
3: I1201 21:21:55.897497 17392 slave.cpp:4133] Got registration for executor '0bb119be-d164-4f6e-9524-24920e795e94' of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 from executor(1)@172.17.0.3:42542
3: I1201 21:21:55.901533 17409 slave.cpp:2683] Sending queued task '0bb119be-d164-4f6e-9524-24920e795e94' to executor '0bb119be-d164-4f6e-9524-24920e795e94' of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 at executor(1)@172.17.0.3:42542
3: I1201 21:21:55.906600 26385 exec.cpp:237] Executor registered on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0
3: I1201 21:21:55.912957 26368 executor.cpp:171] Received SUBSCRIBED event
3: I1201 21:21:55.914980 26368 executor.cpp:175] Subscribed executor on 3e08591a7e82
3: I1201 21:21:55.915364 26368 executor.cpp:171] Received LAUNCH event
3: I1201 21:21:55.918195 26368 executor.cpp:637] Starting task 0bb119be-d164-4f6e-9524-24920e795e94
3: I1201 21:21:55.922457 17393 slave.cpp:4587] Handling status update TASK_STARTING (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 from executor(1)@172.17.0.3:42542
3: I1201 21:21:55.925065 17392 task_status_update_manager.cpp:328] Received task status update TASK_STARTING (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.925129 17392 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.926065 17392 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 to the agent
3: I1201 21:21:55.926461 17389 slave.cpp:5070] Forwarding the update TASK_STARTING (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 to master@172.17.0.3:33575
3: I1201 21:21:55.926841 17389 slave.cpp:4963] Task status update manager successfully handled status update TASK_STARTING (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.926915 17389 slave.cpp:4979] Sending acknowledgement for status update TASK_STARTING (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 to executor(1)@172.17.0.3:42542
3: I1201 21:21:55.927124 17408 master.cpp:7557] Status update TASK_STARTING (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 from agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:55.927212 17408 master.cpp:7613] Forwarding status update TASK_STARTING (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.927505 17408 master.cpp:9807] Updating the state of task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (latest state: TASK_STARTING, status update state: TASK_STARTING)
3: I1201 21:21:55.927911 17412 sched.cpp:1029] Scheduler::statusUpdate took 122740ns
3: I1201 21:21:55.928480 17399 master.cpp:5799] Processing ACKNOWLEDGE call 33947034-47b0-470e-85cf-10c2b0907fa1 for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575 on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0
3: I1201 21:21:55.929065 17407 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.929522 17404 slave.cpp:3871] Task status update manager successfully handled status update acknowledgement (UUID: 33947034-47b0-470e-85cf-10c2b0907fa1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.942176 26368 executor.cpp:477] Running '/mesos/build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>'
3: I1201 21:21:55.946410 26368 executor.cpp:650] Forked command at 26390
3: I1201 21:21:55.948549 17398 slave.cpp:4587] Handling status update TASK_RUNNING (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 from executor(1)@172.17.0.3:42542
3: I1201 21:21:55.951036 17403 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.951231 17403 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 to the agent
3: I1201 21:21:55.951557 17401 slave.cpp:5070] Forwarding the update TASK_RUNNING (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 to master@172.17.0.3:33575
3: I1201 21:21:55.951843 17401 slave.cpp:4963] Task status update manager successfully handled status update TASK_RUNNING (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.951907 17401 slave.cpp:4979] Sending acknowledgement for status update TASK_RUNNING (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 to executor(1)@172.17.0.3:42542
3: I1201 21:21:55.952059 17405 master.cpp:7557] Status update TASK_RUNNING (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 from agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:55.952131 17405 master.cpp:7613] Forwarding status update TASK_RUNNING (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.952378 17405 master.cpp:9807] Updating the state of task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
3: I1201 21:21:55.952669 17392 sched.cpp:1029] Scheduler::statusUpdate took 84998ns
3: I1201 21:21:55.953038 17389 master.cpp:5799] Processing ACKNOWLEDGE call b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575 on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0
3: I1201 21:21:55.953483 17412 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:55.953804 17399 slave.cpp:3871] Task status update manager successfully handled status update acknowledgement (UUID: b5fef6ca-3a67-4b74-ba7f-b9f8d77fc66f) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.183513 26373 executor.cpp:929] Command exited with status 0 (pid: 26390)
3: I1201 21:21:56.191213 17400 slave.cpp:4587] Handling status update TASK_FINISHED (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 from executor(1)@172.17.0.3:42542
3: I1201 21:21:56.194428 17391 posix.cpp:142] Removing symlink '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bwgOhT/slaves/0a035826-5fbe-4872-855d-804ebac238d7-S0/frameworks/0a035826-5fbe-4872-855d-804ebac238d7-0000/executors/0bb119be-d164-4f6e-9524-24920e795e94/runs/5bbd75a6-b986-4893-b5e2-30362571c478/path1' for persistent volume disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048 of container 5bbd75a6-b986-4893-b5e2-30362571c478
3: I1201 21:21:56.195569 17412 task_status_update_manager.cpp:328] Received task status update TASK_FINISHED (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.195785 17412 task_status_update_manager.cpp:383] Forwarding task status update TASK_FINISHED (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 to the agent
3: I1201 21:21:56.196113 17407 slave.cpp:5070] Forwarding the update TASK_FINISHED (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 to master@172.17.0.3:33575
3: I1201 21:21:56.196458 17407 slave.cpp:4963] Task status update manager successfully handled status update TASK_FINISHED (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.196532 17407 slave.cpp:4979] Sending acknowledgement for status update TASK_FINISHED (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 to executor(1)@172.17.0.3:42542
3: I1201 21:21:56.196704 17400 master.cpp:7557] Status update TASK_FINISHED (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 from agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:56.196789 17400 master.cpp:7613] Forwarding status update TASK_FINISHED (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.197082 17400 master.cpp:9807] Updating the state of task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
3: I1201 21:21:56.197619 17393 sched.cpp:1029] Scheduler::statusUpdate took 134560ns
3: I1201 21:21:56.198318 17400 master.cpp:5799] Processing ACKNOWLEDGE call 939ece14-4c95-4634-b66d-60fc625757d1 for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575 on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0
3: I1201 21:21:56.198537 17400 master.cpp:9913] Removing task 0bb119be-d164-4f6e-9524-24920e795e94 with resources cpus(allocated: default-role):1; mem(allocated: default-role):128; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:56.199139 17409 hierarchical.cpp:1106] Recovered cpus(allocated: default-role):1; mem(allocated: default-role):128; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048 (total: cpus:2; mem:2048; ports:[31000-32000]; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk2]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048, allocated: {}) on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 from framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.199373 17409 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.199587 17409 task_status_update_manager.cpp:538] Cleaning up status update stream for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.200369 17397 slave.cpp:3871] Task status update manager successfully handled status update acknowledgement (UUID: 939ece14-4c95-4634-b66d-60fc625757d1) for task 0bb119be-d164-4f6e-9524-24920e795e94 of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.200448 17397 slave.cpp:8490] Completing task 0bb119be-d164-4f6e-9524-24920e795e94
3: I1201 21:21:56.205734 17390 hierarchical.cpp:1431] Performed allocation for 1 agents in 2.840393ms
3: I1201 21:21:56.206909 17398 master.cpp:8419] Sending 1 offers to framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575
3: I1201 21:21:56.207880 17411 sched.cpp:921] Scheduler::resourceOffers took 186393ns
3: I1201 21:21:56.211165 17394 master.cpp:10331] Removing offer 0a035826-5fbe-4872-855d-804ebac238d7-O1
3: I1201 21:21:56.211372 17394 master.cpp:4236] Processing ACCEPT call for offers: [ 0a035826-5fbe-4872-855d-804ebac238d7-O1 ] on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82) for framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575
3: I1201 21:21:56.211628 17394 master.cpp:3850] Authorizing principal 'test-principal' to destroy volumes '[{"allocation_info":{"role":"default-role"},"disk":{"persistence":{"id":"id1","principal":"test-principal"},"source":{"path":{"root":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA\/disk1"},"type":"PATH"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
3: I1201 21:21:56.214228 17402 master.cpp:4805] Applying DESTROY operation for volumes [{"allocation_info":{"role":"default-role"},"disk":{"persistence":{"id":"id1","principal":"test-principal"},"source":{"path":{"root":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA\/disk1"},"type":"PATH"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}] from framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575 to agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:56.215545 17402 master.cpp:10228] Sending offer operation '' (uuid: 79f35532-de5a-4aae-8bc8-e6e2bed861fb) to agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:56.218049 17389 slave.cpp:3677] Deleting persistent volume 'id1' at '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1/volumes/roles/default-role/id1'
3: I1201 21:21:56.218551 17389 slave.cpp:3605] Updated checkpointed resources from disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048 to {}
3: I1201 21:21:56.218698 17389 slave.cpp:7079] Updating the state of offer operation '' (uuid: 79f35532-de5a-4aae-8bc8-e6e2bed861fb) of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
3: I1201 21:21:56.219085 17408 master.cpp:10015] Updating the state of offer operation '' (uuid: 79f35532-de5a-4aae-8bc8-e6e2bed861fb) of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
3: I1201 21:21:56.222651 17399 hierarchical.cpp:830] Updated allocation of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 from cpus(allocated: default-role):2; mem(allocated: default-role):2048; ports(allocated: default-role):[31000-32000]; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1,id1:path1]:2048 to cpus(allocated: default-role):2; mem(allocated: default-role):2048; ports(allocated: default-role):[31000-32000]; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1]:2048
3: I1201 21:21:56.224982 17399 hierarchical.cpp:1106] Recovered cpus(allocated: default-role):2; mem(allocated: default-role):2048; ports(allocated: default-role):[31000-32000]; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1]:2048 (total: cpus:2; mem:2048; ports:[31000-32000]; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk2]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_5d5eqA/disk1]:2048, allocated: {}) on agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 from framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.225119 17399 hierarchical.cpp:1152] Framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 filtered agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 for 5secs
3: I1201 21:21:56.225687 17388 sched.cpp:2009] Asked to stop the driver
3: I1201 21:21:56.225875 17412 sched.cpp:1191] Stopping framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.226222 17407 master.cpp:9096] Processing TEARDOWN call for framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575
3: I1201 21:21:56.226263 17407 master.cpp:9108] Removing framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575
3: I1201 21:21:56.226279 17407 master.cpp:3339] Deactivating framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 (default) at scheduler-93d79ab8-56b6-4324-a8d1-682edfdada76@172.17.0.3:33575
3: I1201 21:21:56.226496 17410 hierarchical.cpp:406] Deactivated framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.226593 17395 slave.cpp:3281] Asked to shut down framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 by master@172.17.0.3:33575
3: I1201 21:21:56.226649 17395 slave.cpp:3306] Shutting down framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.226716 17395 slave.cpp:5946] Shutting down executor '0bb119be-d164-4f6e-9524-24920e795e94' of framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 at executor(1)@172.17.0.3:42542
3: I1201 21:21:56.227285 17397 hierarchical.cpp:345] Removed framework 0a035826-5fbe-4872-855d-804ebac238d7-0000
3: I1201 21:21:56.227676 17388 slave.cpp:875] Agent terminating
3: I1201 21:21:56.227751 17388 slave.cpp:3281] Asked to shut down framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 by @0.0.0.0:0
3: W1201 21:21:56.227787 17388 slave.cpp:3302] Ignoring shutdown framework 0a035826-5fbe-4872-855d-804ebac238d7-0000 because it is terminating
3: I1201 21:21:56.227964 26384 exec.cpp:435] Executor asked to shutdown
3: I1201 21:21:56.228092 17389 master.cpp:1317] Agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82) disconnected
3: I1201 21:21:56.228130 17389 master.cpp:3376] Disconnecting agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:56.228202 17389 master.cpp:3395] Deactivating agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 at slave(883)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:56.228374 26387 executor.cpp:171] Received SHUTDOWN event
3: I1201 21:21:56.228396 17404 hierarchical.cpp:671] Agent 0a035826-5fbe-4872-855d-804ebac238d7-S0 deactivated
3: I1201 21:21:56.228416 26387 executor.cpp:747] Shutting down
3: I1201 21:21:56.228895 17395 containerizer.cpp:2326] Destroying container 5bbd75a6-b986-4893-b5e2-30362571c478 in RUNNING state
3: I1201 21:21:56.228925 17395 containerizer.cpp:2923] Transitioning the state of container 5bbd75a6-b986-4893-b5e2-30362571c478 from RUNNING to DESTROYING
3: I1201 21:21:56.229420 17395 launcher.cpp:156] Asked to destroy container 5bbd75a6-b986-4893-b5e2-30362571c478
3: I1201 21:21:56.328783 17394 containerizer.cpp:2777] Container 5bbd75a6-b986-4893-b5e2-30362571c478 has exited
3: I1201 21:21:56.332080 17394 provisioner.cpp:595] Ignoring destroy request for unknown container 5bbd75a6-b986-4893-b5e2-30362571c478
3: I1201 21:21:56.344092 17388 master.cpp:1159] Master terminating
3: I1201 21:21:56.346093 17401 hierarchical.cpp:586] Removed agent 0a035826-5fbe-4872-855d-804ebac238d7-S0
3: [       OK ] DiskResource/PersistentVolumeTest.AccessPersistentVolume/3 (881 ms)
3: [ RUN      ] DiskResource/PersistentVolumeTest.SharedPersistentVolumeMultipleTasks/0
3: I1201 21:21:56.356837 17388 cluster.cpp:170] Creating default 'local' authorizer
3: I1201 21:21:56.361552 17401 master.cpp:454] Master 3430238b-59ef-4944-af8b-133f24d85c2d (3e08591a7e82) started on 172.17.0.3:33575
3: I1201 21:21:56.361582 17401 master.cpp:456] 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/sAOOAH/credentials" --filter_gpu_resources="true" --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" --max_unreachable_tasks_per_framework="1000" --port="5050" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/sAOOAH/master" --zk_session_timeout="10secs"
3: I1201 21:21:56.361965 17401 master.cpp:505] Master only allowing authenticated frameworks to register
3: I1201 21:21:56.361975 17401 master.cpp:511] Master only allowing authenticated agents to register
3: I1201 21:21:56.361981 17401 master.cpp:517] Master only allowing authenticated HTTP frameworks to register
3: I1201 21:21:56.361987 17401 credentials.hpp:37] Loading credentials for authentication from '/tmp/sAOOAH/credentials'
3: I1201 21:21:56.362383 17401 master.cpp:561] Using default 'crammd5' authenticator
3: I1201 21:21:56.362588 17401 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
3: I1201 21:21:56.362797 17401 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
3: I1201 21:21:56.362967 17401 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
3: I1201 21:21:56.363137 17401 master.cpp:640] Authorization enabled
3: I1201 21:21:56.363416 17397 hierarchical.cpp:173] Initialized hierarchical allocator process
3: I1201 21:21:56.363446 17406 whitelist_watcher.cpp:77] No whitelist given
3: I1201 21:21:56.366986 17394 master.cpp:2221] Elected as the leading master!
3: I1201 21:21:56.367019 17394 master.cpp:1701] Recovering from registrar
3: I1201 21:21:56.367164 17408 registrar.cpp:347] Recovering registrar
3: I1201 21:21:56.367879 17408 registrar.cpp:391] Successfully fetched the registry (0B) in 672768ns
3: I1201 21:21:56.368006 17408 registrar.cpp:495] Applied 1 operations in 36338ns; attempting to update the registry
3: I1201 21:21:56.368703 17408 registrar.cpp:552] Successfully updated the registry in 631040ns
3: I1201 21:21:56.368847 17408 registrar.cpp:424] Successfully recovered registrar
3: I1201 21:21:56.369444 17410 master.cpp:1814] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
3: I1201 21:21:56.369472 17409 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover
3: W1201 21:21:56.377003 17388 process.cpp:2756] Attempted to spawn already running process files@172.17.0.3:33575
3: I1201 21:21:56.378469 17388 containerizer.cpp:304] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W1201 21:21:56.379253 17388 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W1201 21:21:56.379432 17388 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I1201 21:21:56.379484 17388 provisioner.cpp:297] Using default backend 'copy'
3: I1201 21:21:56.382375 17388 cluster.cpp:458] Creating default 'local' authorizer
3: I1201 21:21:56.386008 17410 slave.cpp:253] Mesos agent started on (884)@172.17.0.3:33575
3: I1201 21:21:56.386042 17410 slave.cpp:254] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_G1Y9cI/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/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_G1Y9cI/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --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/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_G1Y9cI/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_G1Y9cI/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_G1Y9cI/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk(default-role):1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_G1Y9cI" --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/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_Nxr8jn" --zk_session_timeout="10secs"
3: I1201 21:21:56.386587 17410 credentials.hpp:86] Loading credential for authentication from '/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_G1Y9cI/credential'
3: I1201 21:21:56.386811 17410 slave.cpp:286] Agent using credential for: test-principal
3: I1201 21:21:56.386837 17410 credentials.hpp:37] Loading credentials for authentication from '/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_G1Y9cI/http_credentials'
3: W1201 21:21:56.386880 17388 process.cpp:2756] Attempted to spawn already running process version@172.17.0.3:33575
3: I1201 21:21:56.387176 17410 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1201 21:21:56.387392 17410 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1201 21:21:56.388223 17388 sched.cpp:232] Version: 1.5.0
3: I1201 21:21:56.389042 17408 sched.cpp:336] New master detected at master@172.17.0.3:33575
3: I1201 21:21:56.389257 17408 sched.cpp:396] Authenticating with master master@172.17.0.3:33575
3: I1201 21:21:56.389286 17408 sched.cpp:403] Using default CRAM-MD5 authenticatee
3: I1201 21:21:56.389717 17390 authenticatee.cpp:121] Creating new client SASL connection
3: I1201 21:21:56.390250 17396 master.cpp:8589] Authenticating scheduler-a2c84887-ec9f-4501-a400-9f6dd576f426@172.17.0.3:33575
3: I1201 21:21:56.389811 17410 slave.cpp:585] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
3: I1201 21:21:56.390445 17410 slave.cpp:593] Agent attributes: [  ]
3: I1201 21:21:56.390475 17410 slave.cpp:602] Agent hostname: 3e08591a7e82
3: I1201 21:21:56.390522 17407 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1525)@172.17.0.3:33575
3: I1201 21:21:56.390705 17409 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1201 21:21:56.390931 17409 authenticator.cpp:98] Creating new server SASL connection
3: I1201 21:21:56.391320 17406 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1201 21:21:56.391362 17406 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1201 21:21:56.391523 17406 authenticator.cpp:204] Received SASL authentication start
3: I1201 21:21:56.391613 17406 authenticator.cpp:326] Authentication requires more steps
3: I1201 21:21:56.391803 17397 authenticatee.cpp:259] Received SASL authentication step
3: I1201 21:21:56.392015 17401 authenticator.cpp:232] Received SASL authentication step
3: I1201 21:21:56.392071 17401 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '3e08591a7e82' server FQDN: '3e08591a7e82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
3: I1201 21:21:56.392089 17401 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1201 21:21:56.392148 17401 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1201 21:21:56.392176 17401 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '3e08591a7e82' server FQDN: '3e08591a7e82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
3: I1201 21:21:56.392190 17401 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1201 21:21:56.392199 17401 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1201 21:21:56.392220 17401 authenticator.cpp:318] Authentication success
3: I1201 21:21:56.392395 17391 authenticatee.cpp:299] Authentication success
3: I1201 21:21:56.392539 17403 master.cpp:8619] Successfully authenticated principal 'test-principal' at scheduler-a2c84887-ec9f-4501-a400-9f6dd576f426@172.17.0.3:33575
3: I1201 21:21:56.392580 17399 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1525)@172.17.0.3:33575
3: I1201 21:21:56.392940 17401 sched.cpp:502] Successfully authenticated with master master@172.17.0.3:33575
3: I1201 21:21:56.392978 17401 sched.cpp:824] Sending SUBSCRIBE call to master@172.17.0.3:33575
3: I1201 21:21:56.393162 17401 sched.cpp:857] Will retry registration in 974.404325ms if necessary
3: I1201 21:21:56.393353 17412 state.cpp:64] Recovering state from '/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_Nxr8jn/meta'
3: I1201 21:21:56.393448 17395 master.cpp:2969] Received SUBSCRIBE call for framework 'default' at scheduler-a2c84887-ec9f-4501-a400-9f6dd576f426@172.17.0.3:33575
3: I1201 21:21:56.393560 17395 master.cpp:2286] Authorizing framework principal 'test-principal' to receive offers for roles '{ default-role }'
3: I1201 21:21:56.393781 17394 task_status_update_manager.cpp:207] Recovering task status update manager
3: I1201 21:21:56.394045 17393 containerizer.cpp:672] Recovering containerizer
3: I1201 21:21:56.394234 17407 master.cpp:3049] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT, SHARED_RESOURCES ]
3: I1201 21:21:56.395267 17403 sched.cpp:751] Framework registered with 3430238b-59ef-4944-af8b-133f24d85c2d-0000
3: I1201 21:21:56.395401 17403 sched.cpp:765] Scheduler::registered took 100926ns
3: I1201 21:21:56.395436 17397 hierarchical.cpp:293] Added framework 3430238b-59ef-4944-af8b-133f24d85c2d-0000
3: I1201 21:21:56.395722 17397 hierarchical.cpp:1431] Performed allocation for 0 agents in 98961ns
3: I1201 21:21:56.396293 17412 provisioner.cpp:493] Provisioner recovery complete
3: I1201 21:21:56.396813 17411 slave.cpp:6513] Finished recovery
3: I1201 21:21:56.398144 17402 slave.cpp:999] New master detected at master@172.17.0.3:33575
3: I1201 21:21:56.398176 17393 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1201 21:21:56.398308 17402 slave.cpp:1034] Detecting new master
3: I1201 21:21:56.405771 17404 slave.cpp:1061] Authenticating with master master@172.17.0.3:33575
3: I1201 21:21:56.405879 17404 slave.cpp:1070] Using default CRAM-MD5 authenticatee
3: I1201 21:21:56.406261 17399 authenticatee.cpp:121] Creating new client SASL connection
3: I1201 21:21:56.406693 17406 master.cpp:8589] Authenticating slave(884)@172.17.0.3:33575
3: I1201 21:21:56.406901 17398 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1526)@172.17.0.3:33575
3: I1201 21:21:56.407214 17392 authenticator.cpp:98] Creating new server SASL connection
3: I1201 21:21:56.407505 17403 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1201 21:21:56.407538 17403 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1201 21:21:56.407665 17403 authenticator.cpp:204] Received SASL authentication start
3: I1201 21:21:56.407726 17403 authenticator.cpp:326] Authentication requires more steps
3: I1201 21:21:56.407868 17395 authenticatee.cpp:259] Received SASL authentication step
3: I1201 21:21:56.408020 17395 authenticator.cpp:232] Received SASL authentication step
3: I1201 21:21:56.408056 17395 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '3e08591a7e82' server FQDN: '3e08591a7e82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
3: I1201 21:21:56.408071 17395 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1201 21:21:56.408110 17395 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1201 21:21:56.408136 17395 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '3e08591a7e82' server FQDN: '3e08591a7e82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
3: I1201 21:21:56.408146 17395 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1201 21:21:56.408155 17395 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1201 21:21:56.408171 17395 authenticator.cpp:318] Authentication success
3: I1201 21:21:56.408298 17410 authenticatee.cpp:299] Authentication success
3: I1201 21:21:56.408361 17397 master.cpp:8619] Successfully authenticated principal 'test-principal' at slave(884)@172.17.0.3:33575
3: I1201 21:21:56.408408 17408 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1526)@172.17.0.3:33575
3: I1201 21:21:56.408622 17395 slave.cpp:1153] Successfully authenticated with master master@172.17.0.3:33575
3: I1201 21:21:56.408897 17395 slave.cpp:1696] Will retry registration in 18.401128ms if necessary
3: I1201 21:21:56.409339 17389 master.cpp:6042] Received register agent message from slave(884)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:56.409546 17389 master.cpp:3878] Authorizing agent with principal 'test-principal'
3: I1201 21:21:56.410162 17391 master.cpp:6104] Authorized registration of agent at slave(884)@172.17.0.3:33575 (3e08591a7e82)
3: I1201 21:21:56.410315 17391 master.cpp:6197] Registering agent at slave(884)@172.17.0.3:33575 (3e08591a7e82) with id 3430238b-59ef-4944-af8b-133f24d85c2d-S0
Build step 'Execute shell' marked build as failure