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=centos%3A7,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4494/display/redirect>
------------------------------------------ [...truncated 30.05 MB...] 3: I1123 08:02:37.301524 16008 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1512)@172.17.0.7:45624 3: I1123 08:02:37.301753 16000 authenticator.cpp:98] Creating new server SASL connection 3: I1123 08:02:37.301939 15995 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1123 08:02:37.301959 15995 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1123 08:02:37.302052 16010 authenticator.cpp:204] Received SASL authentication start 3: I1123 08:02:37.302091 16010 authenticator.cpp:326] Authentication requires more steps 3: I1123 08:02:37.302193 16014 authenticatee.cpp:259] Received SASL authentication step 3: I1123 08:02:37.302317 16013 authenticator.cpp:232] Received SASL authentication step 3: I1123 08:02:37.302350 16013 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c4ef77bbab88' server FQDN: 'c4ef77bbab88' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1123 08:02:37.302363 16013 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1123 08:02:37.302392 16013 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1123 08:02:37.302414 16013 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c4ef77bbab88' server FQDN: 'c4ef77bbab88' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1123 08:02:37.302428 16013 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1123 08:02:37.302435 16013 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1123 08:02:37.302451 16013 authenticator.cpp:318] Authentication success 3: I1123 08:02:37.302532 16015 authenticatee.cpp:299] Authentication success 3: I1123 08:02:37.302593 16005 master.cpp:8342] Successfully authenticated principal 'test-principal' at [email protected]:45624 3: I1123 08:02:37.302666 16012 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1512)@172.17.0.7:45624 3: I1123 08:02:37.302789 15992 sched.cpp:502] Successfully authenticated with master [email protected]:45624 3: I1123 08:02:37.302808 15992 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:45624 3: I1123 08:02:37.302913 15992 sched.cpp:857] Will retry registration in 1.994549692secs if necessary 3: I1123 08:02:37.303082 16009 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:45624 3: I1123 08:02:37.303159 16009 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ default-role }' 3: I1123 08:02:37.303567 15993 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT, SHARED_RESOURCES ] 3: I1123 08:02:37.304131 16006 sched.cpp:751] Framework registered with 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.304188 16006 sched.cpp:765] Scheduler::registered took 35373ns 3: I1123 08:02:37.304293 16011 hierarchical.cpp:306] Added framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.305974 16011 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.564333ms 3: I1123 08:02:37.306684 16007 master.cpp:8142] Sending 1 offers to framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 3: I1123 08:02:37.307216 15998 sched.cpp:921] Scheduler::resourceOffers took 102008ns 3: I1123 08:02:37.308933 16000 hierarchical.cpp:1457] Performed allocation for 1 agents in 127689ns 3: I1123 08:02:37.311372 16010 master.cpp:10063] Removing offer 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-O0 3: I1123 08:02:37.311564 16010 master.cpp:4230] Processing ACCEPT call for offers: [ 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-O0 ] on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) for framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 3: I1123 08:02:37.311722 16010 master.cpp:3792] 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_Aao6Fr\/disk1"},"type":"PATH"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]' 3: I1123 08:02:37.312255 16010 master.cpp:3599] Authorizing framework principal 'test-principal' to launch task 71647f3a-e15c-4d00-8a0b-787c40438f52 3: I1123 08:02:37.313681 15997 master.cpp:4706] 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_Aao6Fr\/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 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 to agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.314512 15997 master.cpp:9945] Sending offer operation '' (uuid: 52b5b374-3fca-4fee-b36f-03ec3afdb9cf) to agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.316128 16002 slave.cpp:3594] Updated checkpointed resources from {} to disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1,id1:path1]:2048 3: I1123 08:02:37.316231 16002 slave.cpp:6989] Updating the state of offer operation '' (uuid: 52b5b374-3fca-4fee-b36f-03ec3afdb9cf) of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED) 3: I1123 08:02:37.316270 15997 master.cpp:10814] Adding task 71647f3a-e15c-4d00-8a0b-787c40438f52 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_Aao6Fr/disk1,id1:path1]:2048 on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.316687 15997 master.cpp:4978] Launching task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 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_Aao6Fr\/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 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.317454 15997 master.cpp:9731] Updating the state of offer operation '' (uuid: 52b5b374-3fca-4fee-b36f-03ec3afdb9cf) of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED) 3: I1123 08:02:37.317726 16012 slave.cpp:1806] Got assigned task '71647f3a-e15c-4d00-8a0b-787c40438f52' for framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.318377 16012 slave.cpp:2074] Authorizing task '71647f3a-e15c-4d00-8a0b-787c40438f52' for framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.318435 16012 slave.cpp:7349] Authorizing framework principal 'test-principal' to launch task 71647f3a-e15c-4d00-8a0b-787c40438f52 3: I1123 08:02:37.319180 15993 slave.cpp:2242] Launching task '71647f3a-e15c-4d00-8a0b-787c40438f52' for framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.319834 15993 paths.cpp:621] Trying to chown '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9' to user 'mesos' 3: I1123 08:02:37.320080 15993 slave.cpp:7823] Launching executor '71647f3a-e15c-4d00-8a0b-787c40438f52' of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-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_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9' 3: I1123 08:02:37.320581 15992 hierarchical.cpp:856] Updated allocation of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-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_Aao6Fr/disk1]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/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_Aao6Fr/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1,id1:path1]:2048 3: I1123 08:02:37.320870 15993 slave.cpp:2933] Launching container e58f7941-7b71-4f8b-8292-944bd06b19b9 for executor '71647f3a-e15c-4d00-8a0b-787c40438f52' of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.321233 15996 containerizer.cpp:1195] Starting container e58f7941-7b71-4f8b-8292-944bd06b19b9 3: I1123 08:02:37.321254 15993 slave.cpp:2470] Queued task '71647f3a-e15c-4d00-8a0b-787c40438f52' for executor '71647f3a-e15c-4d00-8a0b-787c40438f52' of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.321359 15993 slave.cpp:958] Successfully attached '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9' to virtual path '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/latest' 3: I1123 08:02:37.321413 15993 slave.cpp:958] Successfully attached '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9' to virtual path '/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/latest' 3: I1123 08:02:37.321462 15993 slave.cpp:958] Successfully attached '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9' to virtual path '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9' 3: I1123 08:02:37.321728 15992 hierarchical.cpp:1132] 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_Aao6Fr/disk2]:2048 (total: cpus:2; mem:2048; ports:[31000-32000]; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk2]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/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_Aao6Fr/disk1,id1:path1]:2048) on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 from framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.321821 15992 hierarchical.cpp:1178] Framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 filtered agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 for 5secs 3: I1123 08:02:37.322320 15996 containerizer.cpp:1367] Checkpointed ContainerConfig at '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_uCpgMH/containers/e58f7941-7b71-4f8b-8292-944bd06b19b9/config' 3: I1123 08:02:37.322353 15996 containerizer.cpp:2919] Transitioning the state of container e58f7941-7b71-4f8b-8292-944bd06b19b9 from PROVISIONING to PREPARING 3: I1123 08:02:37.322965 16007 posix.cpp:204] Changing the ownership of the persistent volume at '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1/volumes/roles/default-role/id1' with uid 1000 and gid 1000 3: I1123 08:02:37.323038 16007 posix.cpp:250] Adding symlink from '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1/volumes/roles/default-role/id1' to '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9/path1' for persistent volume disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1,id1:path1]:2048 of container e58f7941-7b71-4f8b-8292-944bd06b19b9 3: I1123 08:02:37.326474 16005 containerizer.cpp:1836] 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.7:45624"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4\/slaves\/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0\/frameworks\/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000\/executors\/71647f3a-e15c-4d00-8a0b-787c40438f52\/runs\/e58f7941-7b71-4f8b-8292-944bd06b19b9"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"71647f3a-e15c-4d00-8a0b-787c40438f52"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(850)@172.17.0.7:45624"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4\/slaves\/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0\/frameworks\/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000\/executors\/71647f3a-e15c-4d00-8a0b-787c40438f52\/runs\/e58f7941-7b71-4f8b-8292-944bd06b19b9"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4\/slaves\/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0\/frameworks\/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000\/executors\/71647f3a-e15c-4d00-8a0b-787c40438f52\/runs\/e58f7941-7b71-4f8b-8292-944bd06b19b9"}" --pipe_read="15" --pipe_write="16" --runtime_directory="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_uCpgMH/containers/e58f7941-7b71-4f8b-8292-944bd06b19b9" --unshare_namespace_mnt="false"' 3: I1123 08:02:37.330117 16005 launcher.cpp:140] Forked child with pid '24640' for container 'e58f7941-7b71-4f8b-8292-944bd06b19b9' 3: I1123 08:02:37.330699 16005 containerizer.cpp:2919] Transitioning the state of container e58f7941-7b71-4f8b-8292-944bd06b19b9 from PREPARING to ISOLATING 3: I1123 08:02:37.332409 16011 containerizer.cpp:2919] Transitioning the state of container e58f7941-7b71-4f8b-8292-944bd06b19b9 from ISOLATING to FETCHING 3: I1123 08:02:37.332648 15992 fetcher.cpp:379] Starting to fetch URIs for container: e58f7941-7b71-4f8b-8292-944bd06b19b9, directory: /tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9 3: I1123 08:02:37.333628 15996 containerizer.cpp:2919] Transitioning the state of container e58f7941-7b71-4f8b-8292-944bd06b19b9 from FETCHING to RUNNING 3: I1123 08:02:37.584663 24641 exec.cpp:162] Version: 1.5.0 3: I1123 08:02:37.593709 16000 slave.cpp:4110] Got registration for executor '71647f3a-e15c-4d00-8a0b-787c40438f52' of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 from executor(1)@172.17.0.7:40375 3: I1123 08:02:37.596292 16009 slave.cpp:2672] Sending queued task '71647f3a-e15c-4d00-8a0b-787c40438f52' to executor '71647f3a-e15c-4d00-8a0b-787c40438f52' of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 at executor(1)@172.17.0.7:40375 3: I1123 08:02:37.599004 24662 exec.cpp:237] Executor registered on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 3: I1123 08:02:37.605306 24643 executor.cpp:171] Received SUBSCRIBED event 3: I1123 08:02:37.607174 24643 executor.cpp:175] Subscribed executor on c4ef77bbab88 3: I1123 08:02:37.607576 24643 executor.cpp:171] Received LAUNCH event 3: I1123 08:02:37.610472 24643 executor.cpp:637] Starting task 71647f3a-e15c-4d00-8a0b-787c40438f52 3: I1123 08:02:37.614110 15999 slave.cpp:4564] Handling status update TASK_STARTING (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 from executor(1)@172.17.0.7:40375 3: I1123 08:02:37.616152 16000 task_status_update_manager.cpp:328] Received task status update TASK_STARTING (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.616219 16000 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.617044 16000 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 to the agent 3: I1123 08:02:37.617341 16001 slave.cpp:5047] Forwarding the update TASK_STARTING (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 to [email protected]:45624 3: I1123 08:02:37.617657 16001 slave.cpp:4940] Task status update manager successfully handled status update TASK_STARTING (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.617710 16001 slave.cpp:4956] Sending acknowledgement for status update TASK_STARTING (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 to executor(1)@172.17.0.7:40375 3: I1123 08:02:37.617833 15994 master.cpp:7274] Status update TASK_STARTING (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 from agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.617894 15994 master.cpp:7336] Forwarding status update TASK_STARTING (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.618139 15994 master.cpp:9529] Updating the state of task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (latest state: TASK_STARTING, status update state: TASK_STARTING) 3: I1123 08:02:37.618496 16010 sched.cpp:1029] Scheduler::statusUpdate took 91747ns 3: I1123 08:02:37.618857 16002 master.cpp:5793] Processing ACKNOWLEDGE call 2fb76f0e-3d08-4ac5-8dca-eab506913bdd for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 3: I1123 08:02:37.619276 16014 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.619568 16013 slave.cpp:3848] Task status update manager successfully handled status update acknowledgement (UUID: 2fb76f0e-3d08-4ac5-8dca-eab506913bdd) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.627012 24643 executor.cpp:477] Running '/mesos/build/src/mesos-containerizer launch <POSSIBLY-SENSITIVE-DATA>' 3: I1123 08:02:37.629820 24643 executor.cpp:650] Forked command at 24667 3: I1123 08:02:37.632881 15997 slave.cpp:4564] Handling status update TASK_RUNNING (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 from executor(1)@172.17.0.7:40375 3: I1123 08:02:37.634718 16008 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.634927 16008 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 to the agent 3: I1123 08:02:37.635203 16015 slave.cpp:5047] Forwarding the update TASK_RUNNING (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 to [email protected]:45624 3: I1123 08:02:37.635442 16015 slave.cpp:4940] Task status update manager successfully handled status update TASK_RUNNING (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.635488 16015 slave.cpp:4956] Sending acknowledgement for status update TASK_RUNNING (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 to executor(1)@172.17.0.7:40375 3: I1123 08:02:37.635607 15995 master.cpp:7274] Status update TASK_RUNNING (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 from agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.635659 15995 master.cpp:7336] Forwarding status update TASK_RUNNING (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.635838 15995 master.cpp:9529] Updating the state of task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING) 3: I1123 08:02:37.636093 16000 sched.cpp:1029] Scheduler::statusUpdate took 73804ns 3: I1123 08:02:37.636384 16001 master.cpp:5793] Processing ACKNOWLEDGE call 1987bfc9-c4ae-46d8-ba5c-3942fed26875 for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 3: I1123 08:02:37.636762 16010 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.637038 16002 slave.cpp:3848] Task status update manager successfully handled status update acknowledgement (UUID: 1987bfc9-c4ae-46d8-ba5c-3942fed26875) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.784693 24650 executor.cpp:929] Command exited with status 0 (pid: 24667) 3: I1123 08:02:37.792351 16004 slave.cpp:4564] Handling status update TASK_FINISHED (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 from executor(1)@172.17.0.7:40375 3: I1123 08:02:37.795953 16005 posix.cpp:142] Removing symlink '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9/path1' for persistent volume disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1,id1:path1]:2048 of container e58f7941-7b71-4f8b-8292-944bd06b19b9 3: I1123 08:02:37.796957 16010 task_status_update_manager.cpp:328] Received task status update TASK_FINISHED (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.797224 16010 task_status_update_manager.cpp:383] Forwarding task status update TASK_FINISHED (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 to the agent 3: I1123 08:02:37.797499 16014 slave.cpp:5047] Forwarding the update TASK_FINISHED (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 to [email protected]:45624 3: I1123 08:02:37.797849 16014 slave.cpp:4940] Task status update manager successfully handled status update TASK_FINISHED (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.797917 16014 slave.cpp:4956] Sending acknowledgement for status update TASK_FINISHED (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 to executor(1)@172.17.0.7:40375 3: I1123 08:02:37.798102 16004 master.cpp:7274] Status update TASK_FINISHED (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 from agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.798195 16004 master.cpp:7336] Forwarding status update TASK_FINISHED (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.798481 16004 master.cpp:9529] Updating the state of task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED) 3: I1123 08:02:37.798702 15997 sched.cpp:1029] Scheduler::statusUpdate took 71311ns 3: I1123 08:02:37.799229 16004 master.cpp:5793] Processing ACKNOWLEDGE call 4f471a20-bab0-4eb3-833a-a818329adfac for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 3: I1123 08:02:37.799377 16004 master.cpp:9629] Removing task 71647f3a-e15c-4d00-8a0b-787c40438f52 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_Aao6Fr/disk1,id1:path1]:2048 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.799988 16003 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.799948 15993 hierarchical.cpp:1132] 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_Aao6Fr/disk1,id1:path1]:2048 (total: cpus:2; mem:2048; ports:[31000-32000]; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk2]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1,id1:path1]:2048, allocated: {}) on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 from framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.800130 16003 task_status_update_manager.cpp:538] Cleaning up status update stream for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.800809 15999 slave.cpp:3848] Task status update manager successfully handled status update acknowledgement (UUID: 4f471a20-bab0-4eb3-833a-a818329adfac) for task 71647f3a-e15c-4d00-8a0b-787c40438f52 of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.800889 15999 slave.cpp:8428] Completing task 71647f3a-e15c-4d00-8a0b-787c40438f52 3: I1123 08:02:37.814313 16013 hierarchical.cpp:1457] Performed allocation for 1 agents in 3.858689ms 3: I1123 08:02:37.815086 15996 master.cpp:8142] Sending 1 offers to framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 3: I1123 08:02:37.815778 16011 sched.cpp:921] Scheduler::resourceOffers took 116940ns 3: I1123 08:02:37.818300 16012 master.cpp:10063] Removing offer 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-O1 3: I1123 08:02:37.818442 16012 master.cpp:4230] Processing ACCEPT call for offers: [ 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-O1 ] on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) for framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 3: I1123 08:02:37.818624 16012 master.cpp:3844] 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_Aao6Fr\/disk1"},"type":"PATH"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]' 3: I1123 08:02:37.820747 15998 master.cpp:4799] 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_Aao6Fr\/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 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 to agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.821830 15998 master.cpp:9945] Sending offer operation '' (uuid: 631abb46-d8be-44cd-8912-508061681ff9) to agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.823933 16015 slave.cpp:3666] Deleting persistent volume 'id1' at '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1/volumes/roles/default-role/id1' 3: I1123 08:02:37.824331 16015 slave.cpp:3594] Updated checkpointed resources from disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1,id1:path1]:2048 to {} 3: I1123 08:02:37.824443 16015 slave.cpp:6989] Updating the state of offer operation '' (uuid: 631abb46-d8be-44cd-8912-508061681ff9) of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED) 3: I1123 08:02:37.824744 15994 master.cpp:9731] Updating the state of offer operation '' (uuid: 631abb46-d8be-44cd-8912-508061681ff9) of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED) 3: I1123 08:02:37.826442 16002 hierarchical.cpp:856] Updated allocation of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-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_Aao6Fr/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/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_Aao6Fr/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1]:2048 3: I1123 08:02:37.827919 16002 hierarchical.cpp:1132] 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_Aao6Fr/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1]:2048 (total: cpus:2; mem:2048; ports:[31000-32000]; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk2]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_Aao6Fr/disk1]:2048, allocated: {}) on agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 from framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.828009 16002 hierarchical.cpp:1178] Framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 filtered agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 for 5secs 3: I1123 08:02:37.828351 15991 sched.cpp:2009] Asked to stop the driver 3: I1123 08:02:37.828438 16010 sched.cpp:1191] Stopping framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.828666 16014 master.cpp:8819] Processing TEARDOWN call for framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 3: I1123 08:02:37.828696 16014 master.cpp:8831] Removing framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 3: I1123 08:02:37.828707 16014 master.cpp:3333] Deactivating framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 (default) at [email protected]:45624 3: I1123 08:02:37.828824 15997 hierarchical.cpp:419] Deactivated framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.828919 15993 slave.cpp:3270] Asked to shut down framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 by [email protected]:45624 3: I1123 08:02:37.828964 15993 slave.cpp:3295] Shutting down framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.829026 15993 slave.cpp:5923] Shutting down executor '71647f3a-e15c-4d00-8a0b-787c40438f52' of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 at executor(1)@172.17.0.7:40375 3: I1123 08:02:37.829355 15992 hierarchical.cpp:358] Removed framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.829754 16001 containerizer.cpp:2322] Destroying container e58f7941-7b71-4f8b-8292-944bd06b19b9 in RUNNING state 3: I1123 08:02:37.829777 16001 containerizer.cpp:2919] Transitioning the state of container e58f7941-7b71-4f8b-8292-944bd06b19b9 from RUNNING to DESTROYING 3: I1123 08:02:37.830067 16001 launcher.cpp:156] Asked to destroy container e58f7941-7b71-4f8b-8292-944bd06b19b9 3: I1123 08:02:37.830080 24659 exec.cpp:435] Executor asked to shutdown 3: I1123 08:02:37.830428 24665 executor.cpp:171] Received SHUTDOWN event 3: I1123 08:02:37.830453 24665 executor.cpp:747] Shutting down 3: I1123 08:02:37.839386 15999 slave.cpp:5179] Got exited event for executor(1)@172.17.0.7:40375 3: I1123 08:02:37.931794 16014 containerizer.cpp:2773] Container e58f7941-7b71-4f8b-8292-944bd06b19b9 has exited 3: I1123 08:02:37.934448 15999 provisioner.cpp:557] Ignoring destroy request for unknown container e58f7941-7b71-4f8b-8292-944bd06b19b9 3: I1123 08:02:37.935684 16013 slave.cpp:5588] Executor '71647f3a-e15c-4d00-8a0b-787c40438f52' of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 terminated with signal Killed 3: I1123 08:02:37.935752 16013 slave.cpp:5692] Cleaning up executor '71647f3a-e15c-4d00-8a0b-787c40438f52' of framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 at executor(1)@172.17.0.7:40375 3: I1123 08:02:37.936059 15996 gc.cpp:90] Scheduling '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52/runs/e58f7941-7b71-4f8b-8292-944bd06b19b9' for gc 6.99998916732741days in the future 3: I1123 08:02:37.936213 16013 slave.cpp:5799] Cleaning up framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.936295 15996 gc.cpp:90] Scheduling '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000/executors/71647f3a-e15c-4d00-8a0b-787c40438f52' for gc 6.99998916531259days in the future 3: I1123 08:02:37.936403 16005 task_status_update_manager.cpp:289] Closing task status update streams for framework 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000 3: I1123 08:02:37.936480 15996 gc.cpp:90] Scheduling '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_xASaJ4/slaves/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0/frameworks/9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-0000' for gc 6.99998916242963days in the future 3: I1123 08:02:37.936761 16002 slave.cpp:883] Agent terminating 3: I1123 08:02:37.937014 16004 master.cpp:1311] Agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) disconnected 3: I1123 08:02:37.937037 16004 master.cpp:3370] Disconnecting agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.937098 16004 master.cpp:3389] Deactivating agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 at slave(850)@172.17.0.7:45624 (c4ef77bbab88) 3: I1123 08:02:37.937283 16003 hierarchical.cpp:697] Agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 deactivated 3: I1123 08:02:37.944648 16007 master.cpp:1153] Master terminating 3: I1123 08:02:37.946084 16013 hierarchical.cpp:633] Removed agent 9ca0dafe-06b9-4dbf-be65-e8f3a4e3b194-S0 3: [ OK ] DiskResource/PersistentVolumeTest.AccessPersistentVolume/3 (693 ms) 3: [ RUN ] DiskResource/PersistentVolumeTest.SharedPersistentVolumeMultipleTasks/0 3: I1123 08:02:37.953012 15991 cluster.cpp:162] Creating default 'local' authorizer 3: I1123 08:02:37.955756 16013 master.cpp:448] Master 0d6ccad5-b5f7-4516-9d45-da83f7bab3fc (c4ef77bbab88) started on 172.17.0.7:45624 3: I1123 08:02:37.955776 16013 master.cpp:450] 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/EbnZJN/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/EbnZJN/master" --zk_session_timeout="10secs" 3: I1123 08:02:37.956051 16013 master.cpp:499] Master only allowing authenticated frameworks to register 3: I1123 08:02:37.956058 16013 master.cpp:505] Master only allowing authenticated agents to register 3: I1123 08:02:37.956063 16013 master.cpp:511] Master only allowing authenticated HTTP frameworks to register 3: I1123 08:02:37.956068 16013 credentials.hpp:37] Loading credentials for authentication from '/tmp/EbnZJN/credentials' 3: I1123 08:02:37.956347 16013 master.cpp:555] Using default 'crammd5' authenticator 3: I1123 08:02:37.956504 16013 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I1123 08:02:37.956681 16013 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I1123 08:02:37.956828 16013 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I1123 08:02:37.956933 16013 master.cpp:634] Authorization enabled 3: I1123 08:02:37.957090 16002 hierarchical.cpp:173] Initialized hierarchical allocator process 3: I1123 08:02:37.957132 15994 whitelist_watcher.cpp:77] No whitelist given 3: I1123 08:02:37.960849 16014 master.cpp:2215] Elected as the leading master! 3: I1123 08:02:37.960876 16014 master.cpp:1695] Recovering from registrar 3: I1123 08:02:37.961024 16012 registrar.cpp:347] Recovering registrar 3: I1123 08:02:37.961616 16012 registrar.cpp:391] Successfully fetched the registry (0B) in 553984ns 3: I1123 08:02:37.961735 16012 registrar.cpp:495] Applied 1 operations in 30262ns; attempting to update the registry 3: I1123 08:02:37.962272 16012 registrar.cpp:552] Successfully updated the registry in 483072ns 3: I1123 08:02:37.962391 16012 registrar.cpp:424] Successfully recovered registrar 3: I1123 08:02:37.962777 16011 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register 3: I1123 08:02:37.962849 16000 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover 3: W1123 08:02:37.967388 15991 process.cpp:2756] Attempted to spawn already running process [email protected]:45624 3: I1123 08:02:37.968250 15991 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1123 08:02:37.968753 15991 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1123 08:02:37.968863 15991 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1123 08:02:37.968894 15991 provisioner.cpp:259] Using default backend 'copy' 3: I1123 08:02:37.970659 15991 cluster.cpp:448] Creating default 'local' authorizer 3: I1123 08:02:37.972599 16000 slave.cpp:262] Mesos agent started on (851)@172.17.0.7:45624 3: I1123 08:02:37.972620 16000 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_5aoYQL/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_5aoYQL/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_5aoYQL/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_5aoYQL/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_5aoYQL/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_5aoYQL" --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_uwoC86" --zk_session_timeout="10secs" 3: I1123 08:02:37.972986 16000 credentials.hpp:86] Loading credential for authentication from '/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_5aoYQL/credential' 3: I1123 08:02:37.973209 16000 slave.cpp:295] Agent using credential for: test-principal 3: I1123 08:02:37.973229 16000 credentials.hpp:37] Loading credentials for authentication from '/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_5aoYQL/http_credentials' 3: W1123 08:02:37.973235 15991 process.cpp:2756] Attempted to spawn already running process [email protected]:45624 3: I1123 08:02:37.973459 16000 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1123 08:02:37.973608 16000 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1123 08:02:37.974108 15991 sched.cpp:232] Version: 1.5.0 3: I1123 08:02:37.974647 16009 sched.cpp:336] New master detected at [email protected]:45624 3: I1123 08:02:37.974740 16009 sched.cpp:396] Authenticating with master [email protected]:45624 3: I1123 08:02:37.974755 16009 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1123 08:02:37.974997 16012 authenticatee.cpp:121] Creating new client SASL connection 3: I1123 08:02:37.974983 16000 slave.cpp:593] 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: I1123 08:02:37.975266 15999 master.cpp:8312] Authenticating [email protected]:45624 3: I1123 08:02:37.975272 16000 slave.cpp:601] Agent attributes: [ ] 3: I1123 08:02:37.975288 16000 slave.cpp:610] Agent hostname: c4ef77bbab88 3: I1123 08:02:37.975370 16010 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1513)@172.17.0.7:45624 3: I1123 08:02:37.975420 15995 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1123 08:02:37.975623 15998 authenticator.cpp:98] Creating new server SASL connection 3: I1123 08:02:37.975842 16008 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1123 08:02:37.975865 16008 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1123 08:02:37.975980 15994 authenticator.cpp:204] Received SASL authentication start 3: I1123 08:02:37.976037 15994 authenticator.cpp:326] Authentication requires more steps 3: I1123 08:02:37.976142 16002 authenticatee.cpp:259] Received SASL authentication step 3: I1123 08:02:37.976267 16015 authenticator.cpp:232] Received SASL authentication step 3: I1123 08:02:37.976299 16015 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c4ef77bbab88' server FQDN: 'c4ef77bbab88' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1123 08:02:37.976313 16015 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1123 08:02:37.976366 16015 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1123 08:02:37.976398 16015 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c4ef77bbab88' server FQDN: 'c4ef77bbab88' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1123 08:02:37.976415 16015 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1123 08:02:37.976424 16015 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1123 08:02:37.976442 16015 authenticator.cpp:318] Authentication success 3: I1123 08:02:37.976531 16005 authenticatee.cpp:299] Authentication success 3: I1123 08:02:37.976600 15993 master.cpp:8342] Successfully authenticated principal 'test-principal' at [email protected]:45624 3: I1123 08:02:37.976689 15997 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1513)@172.17.0.7:45624 3: I1123 08:02:37.976830 16014 sched.cpp:502] Successfully authenticated with master [email protected]:45624 3: I1123 08:02:37.976853 16014 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:45624 3: I1123 08:02:37.976981 16014 sched.cpp:857] Will retry registration in 1.21038226secs if necessary 3: I1123 08:02:37.977179 16004 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:45624 3: I1123 08:02:37.977257 16004 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ default-role }' 3: I1123 08:02:37.977290 16006 state.cpp:64] Recovering state from '/tmp/DiskResource_PersistentVolumeTest_SharedPersistentVolumeMultipleTasks_0_uwoC86/meta' 3: I1123 08:02:37.977543 16006 task_status_update_manager.cpp:207] Recovering task status update manager write /dev/stdout: resource temporarily unavailable + docker rmi mesos-1511422012-31752 Build step 'Execute shell' marked build as failure Not sending mail to unregistered user [email protected]
