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/11/22 22:04:12 UTC
Build failed in Jenkins: Mesos-Buildbot » cmake,gcc,--verbose --disable-libtool-wrappers --enable-libevent --enable-ssl,GLOG_v=1 MESOS_VERBOSE=1,ubuntu:14.04,(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23) #4492
See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4492/display/redirect?page=changes>
Changes:
[bmahler] Optimized resources logging in master.
------------------------------------------
[...truncated 7.27 MB...]
3: I1122 22:04:01.680599 20043 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1122 22:04:01.680635 20043 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1122 22:04:01.680655 20043 auxprop.cpp:109] Request to lookup properties for user: 'test-principal-2' realm: '987dffa45d9c' server FQDN: '987dffa45d9c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I1122 22:04:01.680665 20043 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1122 22:04:01.680671 20043 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1122 22:04:01.680685 20043 authenticator.cpp:318] Authentication success
3: I1122 22:04:01.680800 20044 authenticatee.cpp:299] Authentication success
3: I1122 22:04:01.680860 20046 master.cpp:8342] Successfully authenticated principal 'test-principal-2' at scheduler-f5c003e2-3ef2-4671-ae3c-456fe45318c7@172.17.0.2:35264
3: I1122 22:04:01.680910 20037 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(347)@172.17.0.2:35264
3: I1122 22:04:01.681049 20042 sched.cpp:502] Successfully authenticated with master master@172.17.0.2:35264
3: I1122 22:04:01.681074 20042 sched.cpp:824] Sending SUBSCRIBE call to master@172.17.0.2:35264
3: I1122 22:04:01.681176 20042 sched.cpp:857] Will retry registration in 585.236252ms if necessary
3: I1122 22:04:01.681437 20047 master.cpp:2963] Received SUBSCRIBE call for framework 'framework-muggle' at scheduler-f5c003e2-3ef2-4671-ae3c-456fe45318c7@172.17.0.2:35264
3: I1122 22:04:01.681563 20047 master.cpp:2280] Authorizing framework principal 'test-principal-2' to receive offers for roles '{ muggle }'
3: I1122 22:04:01.682106 20040 master.cpp:3043] Subscribing framework framework-muggle with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
3: I1122 22:04:01.682896 20050 sched.cpp:751] Framework registered with 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.683037 20050 sched.cpp:765] Scheduler::registered took 97982ns
3: I1122 22:04:01.683230 20038 hierarchical.cpp:306] Added framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.685714 20038 hierarchical.cpp:1457] Performed allocation for 1 agents in 2.239995ms
3: I1122 22:04:01.686143 20052 master.cpp:8142] Sending 1 offers to framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 (framework-muggle) at scheduler-f5c003e2-3ef2-4671-ae3c-456fe45318c7@172.17.0.2:35264
3: I1122 22:04:01.686646 20043 sched.cpp:921] Scheduler::resourceOffers took 103630ns
3: I1122 22:04:01.688982 20042 master.cpp:10057] Removing offer 1a5b1511-a9f5-49cb-8824-470a109f5b8b-O1
3: I1122 22:04:01.689254 20042 master.cpp:4230] Processing ACCEPT call for offers: [ 1a5b1511-a9f5-49cb-8824-470a109f5b8b-O1 ] on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c) for framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 (framework-muggle) at scheduler-f5c003e2-3ef2-4671-ae3c-456fe45318c7@172.17.0.2:35264
3: I1122 22:04:01.689452 20042 master.cpp:3599] Authorizing framework principal 'test-principal-2' to launch task 2
3: W1122 22:04:01.691474 20040 validation.cpp:1391] Executor 'test-executor-muggle' for task '2' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
3: W1122 22:04:01.691514 20040 validation.cpp:1403] Executor 'test-executor-muggle' for task '2' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
3: I1122 22:04:01.692132 20040 master.cpp:10808] Adding task 2 with resources mem(allocated: muggle)(reservations: [(STATIC,muggle)]):1024; cpus(allocated: muggle)(reservations: [(STATIC,muggle)]):3 on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.692472 20040 master.cpp:4978] Launching task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 (framework-muggle) at scheduler-f5c003e2-3ef2-4671-ae3c-456fe45318c7@172.17.0.2:35264 with resources [{"allocation_info":{"role":"muggle"},"name":"mem","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"allocation_info":{"role":"muggle"},"name":"cpus","reservations":[{"role":"muggle","type":"STATIC"}],"scalar":{"value":3.0},"type":"SCALAR"}] on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.693156 20045 slave.cpp:1806] Got assigned task '2' for framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.693817 20045 slave.cpp:2074] Authorizing task '2' for framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.693881 20045 slave.cpp:7270] Authorizing framework principal 'test-principal-2' to launch task 2
3: I1122 22:04:01.695022 20053 slave.cpp:2242] Launching task '2' for framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.695809 20053 paths.cpp:621] Trying to chown '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/23df3b2f-27ae-46bc-b0de-e51d78a2406c' to user 'foo'
3: W1122 22:04:01.695936 20053 paths.cpp:629] Failed to chown executor directory '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/23df3b2f-27ae-46bc-b0de-e51d78a2406c'. This may be due to attempting to run the executor as a nonexistent user on the agent; see the description for the `--switch_user` flag for more information: Failed to get user information for 'foo': Success
3: I1122 22:04:01.696086 20053 slave.cpp:7744] Launching executor 'test-executor-muggle' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 with resources [] in work directory '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/23df3b2f-27ae-46bc-b0de-e51d78a2406c'
3: I1122 22:04:01.697371 20053 slave.cpp:2470] Queued task '2' for executor 'test-executor-muggle' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.697484 20053 slave.cpp:958] Successfully attached '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/23df3b2f-27ae-46bc-b0de-e51d78a2406c' to virtual path '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/latest'
3: I1122 22:04:01.697536 20053 slave.cpp:958] Successfully attached '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/23df3b2f-27ae-46bc-b0de-e51d78a2406c' to virtual path '/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/latest'
3: I1122 22:04:01.697579 20053 slave.cpp:958] Successfully attached '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/23df3b2f-27ae-46bc-b0de-e51d78a2406c' to virtual path '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/23df3b2f-27ae-46bc-b0de-e51d78a2406c'
3: I1122 22:04:01.697963 20053 slave.cpp:2933] Launching container 23df3b2f-27ae-46bc-b0de-e51d78a2406c for executor 'test-executor-muggle' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: W1122 22:04:01.701584 20057 process.cpp:2756] Attempted to spawn already running process version@172.17.0.2:35264
3: I1122 22:04:01.701843 20057 exec.cpp:162] Version: 1.5.0
3: I1122 22:04:01.702199 20038 exec.cpp:212] Executor started at: executor(42)@172.17.0.2:35264 with pid 20035
3: I1122 22:04:01.702453 20052 slave.cpp:4066] Got registration for executor 'test-executor-muggle' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 from executor(42)@172.17.0.2:35264
3: I1122 22:04:01.702927 20043 exec.cpp:237] Executor registered on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0
3: I1122 22:04:01.702975 20043 exec.cpp:249] Executor::registered took 22363ns
3: I1122 22:04:01.703369 20052 slave.cpp:2672] Sending queued task '2' to executor 'test-executor-muggle' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 at executor(42)@172.17.0.2:35264
3: I1122 22:04:01.703861 20044 exec.cpp:331] Executor asked to run task '2'
3: I1122 22:04:01.703990 20044 exec.cpp:340] Executor::launchTask took 88373ns
3: I1122 22:04:01.704128 20044 exec.cpp:571] Executor sending status update TASK_RUNNING (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.704511 20044 slave.cpp:4520] Handling status update TASK_RUNNING (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 from executor(42)@172.17.0.2:35264
3: I1122 22:04:01.705251 20039 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.705301 20039 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.705816 20039 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 to the agent
3: I1122 22:04:01.706118 20059 slave.cpp:5003] Forwarding the update TASK_RUNNING (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 to master@172.17.0.2:35264
3: I1122 22:04:01.706424 20059 slave.cpp:4896] Task status update manager successfully handled status update TASK_RUNNING (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.706490 20059 slave.cpp:4912] Sending acknowledgement for status update TASK_RUNNING (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 to executor(42)@172.17.0.2:35264
3: I1122 22:04:01.706656 20047 master.cpp:7274] Status update TASK_RUNNING (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 from agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.706717 20042 exec.cpp:388] Executor received status update acknowledgement ac65aa56-73ff-40c1-9b52-ce8396b1a6b9 for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.706732 20047 master.cpp:7336] Forwarding status update TASK_RUNNING (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.706996 20047 master.cpp:9529] Updating the state of task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
3: I1122 22:04:01.707346 20051 sched.cpp:1029] Scheduler::statusUpdate took 114320ns
3: I1122 22:04:01.707759 20051 master.cpp:5793] Processing ACKNOWLEDGE call ac65aa56-73ff-40c1-9b52-ce8396b1a6b9 for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 (framework-muggle) at scheduler-f5c003e2-3ef2-4671-ae3c-456fe45318c7@172.17.0.2:35264 on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0
3: I1122 22:04:01.708210 20056 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.708566 20049 slave.cpp:3804] Task status update manager successfully handled status update acknowledgement (UUID: ac65aa56-73ff-40c1-9b52-ce8396b1a6b9) for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.710278 20043 process.cpp:3503] Handling HTTP event for process 'slave(146)' with path: '/slave(146)/state'
3: I1122 22:04:01.712779 20047 http.cpp:1185] HTTP GET for /slave(146)/state from 172.17.0.2:57064
3: I1122 22:04:01.730600 20042 process.cpp:3503] Handling HTTP event for process 'slave(146)' with path: '/slave(146)/state'
3: I1122 22:04:01.732993 20036 http.cpp:1185] HTTP GET for /slave(146)/state from 172.17.0.2:57066
3: I1122 22:04:01.740792 20035 sched.cpp:2009] Asked to stop the driver
3: I1122 22:04:01.740924 20037 sched.cpp:1191] Stopping framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000
3: I1122 22:04:01.741214 20035 sched.cpp:2009] Asked to stop the driver
3: I1122 22:04:01.741204 20042 master.cpp:8819] Processing TEARDOWN call for framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 (framework-superhero) at scheduler-8549778b-5956-4ffe-8e0e-bcdf067bb7cc@172.17.0.2:35264
3: I1122 22:04:01.741247 20042 master.cpp:8831] Removing framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 (framework-superhero) at scheduler-8549778b-5956-4ffe-8e0e-bcdf067bb7cc@172.17.0.2:35264
3: I1122 22:04:01.741266 20042 master.cpp:3333] Deactivating framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 (framework-superhero) at scheduler-8549778b-5956-4ffe-8e0e-bcdf067bb7cc@172.17.0.2:35264
3: I1122 22:04:01.741413 20040 sched.cpp:1191] Stopping framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.741542 20047 hierarchical.cpp:419] Deactivated framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000
3: I1122 22:04:01.741638 20048 slave.cpp:3270] Asked to shut down framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 by master@172.17.0.2:35264
3: I1122 22:04:01.741653 20042 master.cpp:9529] Updating the state of task 1 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
3: I1122 22:04:01.741701 20048 slave.cpp:3295] Shutting down framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000
3: I1122 22:04:01.741770 20048 slave.cpp:5879] Shutting down executor 'test-executor-superhero' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 at executor(41)@172.17.0.2:35264
3: I1122 22:04:01.741961 20036 exec.cpp:435] Executor asked to shutdown
3: I1122 22:04:01.742020 20036 exec.cpp:450] Executor::shutdown took 29883ns
3: I1122 22:04:01.742316 20051 slave.cpp:5135] Got exited event for executor(41)@172.17.0.2:35264
3: I1122 22:04:01.743155 20042 master.cpp:9629] Removing task 1 with resources cpus(allocated: superhero)(reservations: [(STATIC,superhero)]):2; mem(allocated: superhero)(reservations: [(STATIC,superhero)]):512; disk(allocated: superhero):367463; ports(allocated: superhero):[31000-32000] of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.743644 20042 master.cpp:9658] Removing executor 'test-executor-superhero' with resources [] of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.743654 20041 hierarchical.cpp:1132] Recovered cpus(allocated: superhero)(reservations: [(STATIC,superhero)]):2; mem(allocated: superhero)(reservations: [(STATIC,superhero)]):512; disk(allocated: superhero):367463; ports(allocated: superhero):[31000-32000] (total: cpus(reservations: [(STATIC,superhero)]):2; cpus(reservations: [(STATIC,muggle)]):3; mem(reservations: [(STATIC,superhero)]):512; mem(reservations: [(STATIC,muggle)]):1024; disk:367463; ports:[31000-32000], allocated: cpus(allocated: muggle)(reservations: [(STATIC,muggle)]):3; mem(allocated: muggle)(reservations: [(STATIC,muggle)]):1024) on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 from framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000
3: I1122 22:04:01.744751 20042 master.cpp:8819] Processing TEARDOWN call for framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 (framework-muggle) at scheduler-f5c003e2-3ef2-4671-ae3c-456fe45318c7@172.17.0.2:35264
3: I1122 22:04:01.744777 20053 hierarchical.cpp:358] Removed framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000
3: I1122 22:04:01.744794 20042 master.cpp:8831] Removing framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 (framework-muggle) at scheduler-f5c003e2-3ef2-4671-ae3c-456fe45318c7@172.17.0.2:35264
3: I1122 22:04:01.744814 20042 master.cpp:3333] Deactivating framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 (framework-muggle) at scheduler-f5c003e2-3ef2-4671-ae3c-456fe45318c7@172.17.0.2:35264
3: I1122 22:04:01.744961 20045 slave.cpp:5544] Executor 'test-executor-superhero' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 exited with status 0
3: I1122 22:04:01.745028 20042 master.cpp:9529] Updating the state of task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 (latest state: TASK_KILLED, status update state: TASK_KILLED)
3: I1122 22:04:01.745126 20043 hierarchical.cpp:419] Deactivated framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.745112 20045 slave.cpp:5648] Cleaning up executor 'test-executor-superhero' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 at executor(41)@172.17.0.2:35264
3: I1122 22:04:01.745643 20040 gc.cpp:90] Scheduling '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000/executors/test-executor-superhero/runs/0a961748-aeb5-41b7-aeef-641cdbb34022' for gc 6.99999137191111days in the future
3: I1122 22:04:01.745832 20045 slave.cpp:5755] Cleaning up framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000
3: I1122 22:04:01.745839 20042 master.cpp:9629] Removing task 2 with resources mem(allocated: muggle)(reservations: [(STATIC,muggle)]):1024; cpus(allocated: muggle)(reservations: [(STATIC,muggle)]):3 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.745879 20040 gc.cpp:90] Scheduling '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000/executors/test-executor-superhero' for gc 6.99999136895704days in the future
3: I1122 22:04:01.746035 20057 task_status_update_manager.cpp:289] Closing task status update streams for framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000
3: I1122 22:04:01.746110 20057 task_status_update_manager.cpp:538] Cleaning up status update stream for task 1 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000
3: I1122 22:04:01.746150 20040 gc.cpp:90] Scheduling '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000' for gc 6.99999136548741days in the future
3: I1122 22:04:01.746204 20042 master.cpp:9658] Removing executor 'test-executor-muggle' with resources [] of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.746274 20045 slave.cpp:3270] Asked to shut down framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 by master@172.17.0.2:35264
3: I1122 22:04:01.746335 20045 slave.cpp:3295] Shutting down framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.746388 20045 slave.cpp:5879] Shutting down executor 'test-executor-muggle' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 at executor(42)@172.17.0.2:35264
3: I1122 22:04:01.746385 20048 hierarchical.cpp:1132] Recovered mem(allocated: muggle)(reservations: [(STATIC,muggle)]):1024; cpus(allocated: muggle)(reservations: [(STATIC,muggle)]):3 (total: cpus(reservations: [(STATIC,superhero)]):2; cpus(reservations: [(STATIC,muggle)]):3; mem(reservations: [(STATIC,superhero)]):512; mem(reservations: [(STATIC,muggle)]):1024; disk:367463; ports:[31000-32000], allocated: {}) on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 from framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.746613 20045 slave.cpp:5135] Got exited event for executor(42)@172.17.0.2:35264
3: I1122 22:04:01.746726 20045 slave.cpp:5544] Executor 'test-executor-muggle' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 exited with status 0
3: I1122 22:04:01.746836 20045 slave.cpp:5648] Cleaning up executor 'test-executor-muggle' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 at executor(42)@172.17.0.2:35264
3: I1122 22:04:01.747208 20050 gc.cpp:90] Scheduling '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle/runs/23df3b2f-27ae-46bc-b0de-e51d78a2406c' for gc 6.99999135381926days in the future
3: W1122 22:04:01.747257 20042 master.cpp:7480] Ignoring unknown exited executor 'test-executor-superhero' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0000 on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.747368 20045 slave.cpp:5755] Cleaning up framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.747398 20050 gc.cpp:90] Scheduling '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001/executors/test-executor-muggle' for gc 6.99999135101926days in the future
3: W1122 22:04:01.747409 20042 master.cpp:7480] Ignoring unknown exited executor 'test-executor-muggle' of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001 on agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.747473 20036 hierarchical.cpp:358] Removed framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.747579 20054 task_status_update_manager.cpp:289] Closing task status update streams for framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.747640 20054 task_status_update_manager.cpp:538] Cleaning up status update stream for task 2 of framework 1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001
3: I1122 22:04:01.747684 20046 gc.cpp:90] Scheduling '/tmp/SlaveAuthorizerTest_0_FilterStateEndpoint_vnHdq0/slaves/1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0/frameworks/1a5b1511-a9f5-49cb-8824-470a109f5b8b-0001' for gc 6.99999134785778days in the future
3: I1122 22:04:01.747704 20045 slave.cpp:883] Agent terminating
3: I1122 22:04:01.747967 20040 master.cpp:1311] Agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c) disconnected
3: I1122 22:04:01.747997 20040 master.cpp:3370] Disconnecting agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.748060 20040 master.cpp:3389] Deactivating agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 at slave(146)@172.17.0.2:35264 (987dffa45d9c)
3: I1122 22:04:01.748212 20052 hierarchical.cpp:697] Agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0 deactivated
3: I1122 22:04:01.752887 20041 master.cpp:1153] Master terminating
3: I1122 22:04:01.754263 20037 hierarchical.cpp:633] Removed agent 1a5b1511-a9f5-49cb-8824-470a109f5b8b-S0
3: [ OK ] SlaveAuthorizerTest/0.FilterStateEndpoint (152 ms)
3: [ RUN ] SlaveAuthorizerTest/0.ViewFlags
3: I1122 22:04:01.768858 20035 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W1122 22:04:01.769572 20035 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W1122 22:04:01.769727 20035 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I1122 22:04:01.769768 20035 provisioner.cpp:259] Using default backend 'copy'
3: I1122 22:04:01.774929 20043 slave.cpp:262] Mesos agent started on (147)@172.17.0.2:35264
3: I1122 22:04:01.774957 20043 slave.cpp:263] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/SlaveAuthorizerTest_0_ViewFlags_sYhgZo/store/appc" --authenticate_http_executors="true" --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/SlaveAuthorizerTest_0_ViewFlags_sYhgZo/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/SlaveAuthorizerTest_0_ViewFlags_sYhgZo/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_secret_key="/tmp/SlaveAuthorizerTest_0_ViewFlags_sYhgZo/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveAuthorizerTest_0_ViewFlags_sYhgZo/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/SlaveAuthorizerTest_0_ViewFlags_sYhgZo/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/SlaveAuthorizerTest_0_ViewFlags_sYhgZo" --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/SlaveAuthorizerTest_0_ViewFlags_89YpKP" --zk_session_timeout="10secs"
3: I1122 22:04:01.775563 20043 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveAuthorizerTest_0_ViewFlags_sYhgZo/credential'
3: I1122 22:04:01.775807 20043 slave.cpp:295] Agent using credential for: test-principal
3: I1122 22:04:01.775833 20043 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveAuthorizerTest_0_ViewFlags_sYhgZo/http_credentials'
3: I1122 22:04:01.776240 20043 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
3: I1122 22:04:01.776432 20043 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
3: I1122 22:04:01.776732 20043 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1122 22:04:01.776868 20043 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1122 22:04:01.777113 20043 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1122 22:04:01.777246 20043 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1122 22:04:01.779431 20043 slave.cpp:593] 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: I1122 22:04:01.779765 20043 slave.cpp:601] Agent attributes: [ ]
3: I1122 22:04:01.779778 20043 slave.cpp:610] Agent hostname: 987dffa45d9c
3: I1122 22:04:01.780023 20048 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1122 22:04:01.782361 20051 state.cpp:64] Recovering state from '/tmp/SlaveAuthorizerTest_0_ViewFlags_89YpKP/meta'
3: I1122 22:04:01.782852 20053 task_status_update_manager.cpp:207] Recovering task status update manager
3: I1122 22:04:01.783140 20042 containerizer.cpp:668] Recovering containerizer
3: I1122 22:04:01.785105 20044 provisioner.cpp:455] Provisioner recovery complete
3: I1122 22:04:01.785637 20048 slave.cpp:6449] Finished recovery
3: I1122 22:04:01.789158 20041 process.cpp:3503] Handling HTTP event for process 'slave(147)' with path: '/slave(147)/flags'
3: I1122 22:04:01.791847 20044 http.cpp:1185] HTTP GET for /slave(147)/flags from 172.17.0.2:57070
3: I1122 22:04:01.797747 20036 process.cpp:3503] Handling HTTP event for process 'slave(147)' with path: '/slave(147)/state'
3: I1122 22:04:01.799968 20047 http.cpp:1185] HTTP GET for /slave(147)/state from 172.17.0.2:57074
3: I1122 22:04:01.808104 20036 process.cpp:3503] Handling HTTP event for process 'slave(147)' with path: '/slave(147)/flags'
3: I1122 22:04:01.810194 20049 http.cpp:1185] HTTP GET for /slave(147)/flags from 172.17.0.2:57080
3: I1122 22:04:01.813923 20055 process.cpp:3503] Handling HTTP event for process 'slave(147)' with path: '/slave(147)/state'
3: I1122 22:04:01.816609 20047 http.cpp:1185] HTTP GET for /slave(147)/state from 172.17.0.2:57082
3: I1122 22:04:01.821602 20048 slave.cpp:883] Agent terminating
3: [ OK ] SlaveAuthorizerTest/0.ViewFlags (71 ms)
3: [ RUN ] SlaveAuthorizerTest/0.AuthorizeRunTaskOnAgent
3: I1122 22:04:01.835062 20035 cluster.cpp:162] Creating default 'local' authorizer
3: I1122 22:04:01.839287 20038 master.cpp:448] Master 981fdab6-e821-4209-9386-3e530021d411 (987dffa45d9c) started on 172.17.0.2:35264
3: I1122 22:04:01.839316 20038 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/dIluFx/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/dIluFx/master" --zk_session_timeout="10secs"
3: I1122 22:04:01.839694 20038 master.cpp:499] Master only allowing authenticated frameworks to register
3: I1122 22:04:01.839705 20038 master.cpp:505] Master only allowing authenticated agents to register
3: I1122 22:04:01.839712 20038 master.cpp:511] Master only allowing authenticated HTTP frameworks to register
3: I1122 22:04:01.839720 20038 credentials.hpp:37] Loading credentials for authentication from '/tmp/dIluFx/credentials'
3: I1122 22:04:01.840078 20038 master.cpp:555] Using default 'crammd5' authenticator
3: I1122 22:04:01.840289 20038 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
3: I1122 22:04:01.840474 20038 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
3: I1122 22:04:01.840652 20038 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
3: I1122 22:04:01.840816 20038 master.cpp:634] Authorization enabled
3: I1122 22:04:01.841027 20048 hierarchical.cpp:173] Initialized hierarchical allocator process
3: I1122 22:04:01.841035 20037 whitelist_watcher.cpp:77] No whitelist given
3: I1122 22:04:01.845016 20043 master.cpp:2215] Elected as the leading master!
3: I1122 22:04:01.845064 20043 master.cpp:1695] Recovering from registrar
3: I1122 22:04:01.845254 20040 registrar.cpp:347] Recovering registrar
3: I1122 22:04:01.846112 20040 registrar.cpp:391] Successfully fetched the registry (0B) in 801024ns
3: I1122 22:04:01.846261 20040 registrar.cpp:495] Applied 1 operations in 43908ns; attempting to update the registry
3: I1122 22:04:01.847060 20040 registrar.cpp:552] Successfully updated the registry in 724224ns
3: I1122 22:04:01.847223 20040 registrar.cpp:424] Successfully recovered registrar
3: I1122 22:04:01.847756 20059 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
3: I1122 22:04:01.847841 20039 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover
3: W1122 22:04:01.853865 20035 process.cpp:2756] Attempted to spawn already running process files@172.17.0.2:35264
3: I1122 22:04:01.854928 20035 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W1122 22:04:01.855526 20035 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W1122 22:04:01.855656 20035 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I1122 22:04:01.855691 20035 provisioner.cpp:259] Using default backend 'copy'
3: I1122 22:04:01.858007 20035 cluster.cpp:448] Creating default 'local' authorizer
3: I1122 22:04:01.860788 20039 slave.cpp:262] Mesos agent started on (148)@172.17.0.2:35264
3: I1122 22:04:01.860816 20039 slave.cpp:263] Flags at startup: --acls="permissive: false
3: run_tasks {
3: principals {
3: type: ANY
3: }
3: users {
3: values: "bar"
3: values: "mesos"
3: }
3: }
3: " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_t51yxG/store/appc" --authenticate_http_executors="true" --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/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_t51yxG/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/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_t51yxG/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_secret_key="/tmp/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_t51yxG/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_t51yxG/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/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_t51yxG/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/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_t51yxG" --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/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_qsUv66" --zk_session_timeout="10secs"
3: I1122 22:04:01.861531 20039 credentials.hpp:86] Loading credential for authentication from '/tmp/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_t51yxG/credential'
3: W1122 22:04:01.861563 20035 process.cpp:2756] Attempted to spawn already running process version@172.17.0.2:35264
3: I1122 22:04:01.861717 20039 slave.cpp:295] Agent using credential for: test-principal
3: I1122 22:04:01.861744 20039 credentials.hpp:37] Loading credentials for authentication from '/tmp/SlaveAuthorizerTest_0_AuthorizeRunTaskOnAgent_t51yxG/http_credentials'
3: I1122 22:04:01.862084 20039 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
3: I1122 22:04:01.862223 20039 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
3: I1122 22:04:01.862464 20039 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1122 22:04:01.862584 20039 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1122 22:04:01.862679 20035 sched.cpp:232] Version: 1.5.0
3: I1122 22:04:01.862807 20039 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1122 22:04:01.862924 20039 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1122 22:04:01.863360 20051 sched.cpp:336] New master detected at master@172.17.0.2:35264
3: I1122 22:04:01.863474 20051 sched.cpp:396] Authenticating with master master@172.17.0.2:35264
3: I1122 22:04:01.863492 20051 sched.cpp:403] Using default CRAM-MD5 authenticatee
3: I1122 22:04:01.863790 20059 authenticatee.cpp:121] Creating new client SASL connection
3: I1122 22:04:01.864130 20047 master.cpp:8312] Authenticating scheduler-69852cda-d54b-4c1c-ac89-8763e8717312@172.17.0.2:35264
3: I1122 22:04:01.864279 20048 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(348)@172.17.0.2:35264
3: I1122 22:04:01.864575 20050 authenticator.cpp:98] Creating new server SASL connection
3: I1122 22:04:01.864914 20038 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1122 22:04:01.864953 20038 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1122 22:04:01.864783 20039 slave.cpp:593] 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: I1122 22:04:01.865077 20039 slave.cpp:601] Agent attributes: [ ]
3: I1122 22:04:01.865083 20043 authenticator.cpp:204] Received SASL authentication start
3: I1122 22:04:01.865092 20039 slave.cpp:610] Agent hostname: 987dffa45d9c
3: I1122 22:04:01.865147 20043 authenticator.cpp:326] Authentication requires more steps
3: I1122 22:04:01.865278 20042 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1122 22:04:01.865346 20045 authenticatee.cpp:259] Received SASL authentication step
3: I1122 22:04:01.865516 20055 authenticator.cpp:232] Received SASL authentication step
3: I1122 22:04:01.865556 20055 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '987dffa45d9c' server FQDN: '987dffa45d9c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I1122 22:04:01.865569 20055 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1122 22:04:01.865607 20055 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1122 22:04:01.865631 20055 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '987dffa45d9c' server FQDN: '987dffa45d9c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I1122 22:04:01.865640 20055 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1122 22:04:01.865648 20055 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1122 22:04:01.865665 20055 authenticator.cpp:318] Authentication success
3: I1122 22:04:01.865777 20036 authenticatee.cpp:299] Authentication success
3: I1122 22:04:01.865854 20054 master.cpp:8342] Successfully authenticated principal 'test-principal' at scheduler-69852cda-d54b-4c1c-ac89-8763e8717312@172.17.0.2:35264
3: I1122 22:04:01.865918 20041 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(348)@172.17.0.2:35264
3: I1122 22:04:01.866268 20057 sched.cpp:502] Successfully authenticated with master master@172.17.0.2:35264
3: I1122 22:04:01.866295 20057 sched.cpp:824] Sending SUBSCRIBE call to master@172.17.0.2:35264
3: I1122 22:04:01.866452 20057 sched.cpp:857] Will retry registration in 1.782519472secs if necessary
3: I1122 22:04:01.866654 20049 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at scheduler-69852cda-d54b-4c1c-ac89-8763e8717312@172.17.0.2:35264
write /dev/stdout: resource temporarily unavailable
+ docker rmi mesos-1511385564-13051
Build step 'Execute shell' marked build as failure
Jenkins build is back to normal : Mesos-Buildbot » cmake,gcc,--verbose --disable-libtool-wrappers --enable-libevent --enable-ssl,GLOG_v=1 MESOS_VERBOSE=1,ubuntu:14.04,(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23) #4495
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%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4495/display/redirect?page=changes>
Build failed in Jenkins: Mesos-Buildbot » cmake,gcc,--verbose --disable-libtool-wrappers --enable-libevent --enable-ssl,GLOG_v=1 MESOS_VERBOSE=1,ubuntu:14.04,(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23) #4494
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%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4494/display/redirect>
------------------------------------------
[...truncated 34.86 MB...]
3: I1123 08:07:02.086238 29061 hierarchical.cpp:1457] Performed allocation for 0 agents in 36401ns
3: I1123 08:07:02.086483 29062 authenticatee.cpp:121] Creating new client SASL connection
3: I1123 08:07:02.086899 29045 master.cpp:8312] Authenticating slave(951)@172.17.0.2:33553
3: I1123 08:07:02.087051 29041 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1701)@172.17.0.2:33553
3: I1123 08:07:02.087285 29043 authenticator.cpp:98] Creating new server SASL connection
3: I1123 08:07:02.087599 29053 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1123 08:07:02.087630 29053 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1123 08:07:02.087726 29053 authenticator.cpp:204] Received SASL authentication start
3: I1123 08:07:02.087776 29053 authenticator.cpp:326] Authentication requires more steps
3: I1123 08:07:02.087870 29053 authenticatee.cpp:259] Received SASL authentication step
3: I1123 08:07:02.087963 29053 authenticator.cpp:232] Received SASL authentication step
3: I1123 08:07:02.087986 29053 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'dce3e4c418cb' server FQDN: 'dce3e4c418cb' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I1123 08:07:02.088006 29053 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1123 08:07:02.088032 29053 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1123 08:07:02.088048 29053 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'dce3e4c418cb' server FQDN: 'dce3e4c418cb' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I1123 08:07:02.088057 29053 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1123 08:07:02.088063 29053 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1123 08:07:02.088075 29053 authenticator.cpp:318] Authentication success
3: I1123 08:07:02.088181 29063 authenticatee.cpp:299] Authentication success
3: I1123 08:07:02.088214 29050 master.cpp:8342] Successfully authenticated principal 'test-principal' at slave(951)@172.17.0.2:33553
3: I1123 08:07:02.088246 29064 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1701)@172.17.0.2:33553
3: I1123 08:07:02.088433 29063 slave.cpp:1161] Successfully authenticated with master master@172.17.0.2:33553
3: I1123 08:07:02.088634 29063 slave.cpp:1685] Will retry registration in 9.979907ms if necessary
3: I1123 08:07:02.088858 29052 master.cpp:6036] Received register agent message from slave(951)@172.17.0.2:33553 (dce3e4c418cb)
3: I1123 08:07:02.089020 29052 master.cpp:3872] Authorizing agent with principal 'test-principal'
3: I1123 08:07:02.089542 29055 master.cpp:6098] Authorized registration of agent at slave(951)@172.17.0.2:33553 (dce3e4c418cb)
3: I1123 08:07:02.089643 29055 master.cpp:6191] Registering agent at slave(951)@172.17.0.2:33553 (dce3e4c418cb) with id 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0
3: I1123 08:07:02.090153 29059 registrar.cpp:495] Applied 1 operations in 69881ns; attempting to update the registry
3: I1123 08:07:02.090759 29059 registrar.cpp:552] Successfully updated the registry in 542976ns
3: I1123 08:07:02.091032 29061 master.cpp:6240] Admitted agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb)
3: I1123 08:07:02.092270 29061 master.cpp:6276] Registered agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb) with cpus:1; mem:512; disk:367489; ports:[31000-32000]
3: I1123 08:07:02.092344 29046 slave.cpp:1207] Registered with master master@172.17.0.2:33553; given agent ID 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0
3: I1123 08:07:02.092448 29054 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I1123 08:07:02.092473 29045 hierarchical.cpp:600] Added agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 (dce3e4c418cb) with cpus:1; mem:512; disk:367489; ports:[31000-32000] (allocated: {})
3: I1123 08:07:02.092697 29046 slave.cpp:1227] Checkpointing SlaveInfo to '/tmp/ResourceProviderCapability_ReservationTest_PreventUnreservingAlienResources_1_GRVqo8/meta/slaves/04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0/slave.info'
3: I1123 08:07:02.092749 29045 hierarchical.cpp:1457] Performed allocation for 1 agents in 122523ns
3: I1123 08:07:02.093232 29046 slave.cpp:1288] Forwarding total resources cpus:1; mem:512; disk:367489; ports:[31000-32000]
3: I1123 08:07:02.093317 29046 slave.cpp:1298] Forwarding total oversubscribed resources {}
3: I1123 08:07:02.093912 29053 master.cpp:7078] Received update of agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb) with total resources cpus:1; mem:512; disk:367489; ports:[31000-32000]
3: I1123 08:07:02.093973 29053 master.cpp:7091] Received update of agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb) with total oversubscribed resources {}
3: I1123 08:07:02.094030 29056 hierarchical.cpp:1457] Performed allocation for 1 agents in 112853ns
3: I1123 08:07:02.094146 29053 master.cpp:7109] Ignoring update on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb) as it reports no changes
3: W1123 08:07:02.094509 20036 process.cpp:2756] Attempted to spawn already running process version@172.17.0.2:33553
3: W1123 08:07:02.094951 20036 process.cpp:2756] Attempted to spawn already running process version@172.17.0.2:33553
3: I1123 08:07:02.095805 20036 sched.cpp:232] Version: 1.5.0
3: I1123 08:07:02.096349 29060 sched.cpp:336] New master detected at master@172.17.0.2:33553
3: I1123 08:07:02.096437 29060 sched.cpp:396] Authenticating with master master@172.17.0.2:33553
3: I1123 08:07:02.096451 29060 sched.cpp:403] Using default CRAM-MD5 authenticatee
3: I1123 08:07:02.096842 29059 authenticatee.cpp:121] Creating new client SASL connection
3: I1123 08:07:02.097152 29041 master.cpp:8312] Authenticating scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.097272 29043 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1702)@172.17.0.2:33553
3: I1123 08:07:02.097611 29061 authenticator.cpp:98] Creating new server SASL connection
3: I1123 08:07:02.097946 29054 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1123 08:07:02.097997 29054 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1123 08:07:02.098146 29054 authenticator.cpp:204] Received SASL authentication start
3: I1123 08:07:02.098249 29054 authenticator.cpp:326] Authentication requires more steps
3: I1123 08:07:02.098387 29044 authenticatee.cpp:259] Received SASL authentication step
3: I1123 08:07:02.098512 29046 authenticator.cpp:232] Received SASL authentication step
3: I1123 08:07:02.098549 29046 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'dce3e4c418cb' server FQDN: 'dce3e4c418cb' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I1123 08:07:02.098567 29046 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1123 08:07:02.098599 29046 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1123 08:07:02.098618 29046 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'dce3e4c418cb' server FQDN: 'dce3e4c418cb' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I1123 08:07:02.098626 29046 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1123 08:07:02.098631 29046 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1123 08:07:02.098644 29046 authenticator.cpp:318] Authentication success
3: I1123 08:07:02.098724 29050 authenticatee.cpp:299] Authentication success
3: I1123 08:07:02.098786 29042 master.cpp:8342] Successfully authenticated principal 'test-principal' at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.098876 29051 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1702)@172.17.0.2:33553
3: I1123 08:07:02.098983 29050 sched.cpp:502] Successfully authenticated with master master@172.17.0.2:33553
3: I1123 08:07:02.099000 29050 sched.cpp:824] Sending SUBSCRIBE call to master@172.17.0.2:33553
3: I1123 08:07:02.099112 29050 sched.cpp:857] Will retry registration in 353.471407ms if necessary
3: I1123 08:07:02.099325 29052 master.cpp:2963] Received SUBSCRIBE call for framework 'framework1' at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.099400 29052 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ role1 }'
3: I1123 08:07:02.099865 29057 master.cpp:3043] Subscribing framework framework1 with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
3: I1123 08:07:02.100549 29057 sched.cpp:751] Framework registered with 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.100591 29057 sched.cpp:765] Scheduler::registered took 16255ns
3: I1123 08:07:02.100668 29049 hierarchical.cpp:306] Added framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.101745 29049 hierarchical.cpp:1457] Performed allocation for 1 agents in 957973ns
3: I1123 08:07:02.102000 29049 hierarchical.cpp:1457] Performed allocation for 1 agents in 112278ns
3: I1123 08:07:02.102156 29060 master.cpp:8142] Sending 1 offers to framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.102614 29060 sched.cpp:921] Scheduler::resourceOffers took 95753ns
3: I1123 08:07:02.104498 29046 master.cpp:10063] Removing offer 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O0
3: I1123 08:07:02.104629 29046 master.cpp:4230] Processing ACCEPT call for offers: [ 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O0 ] on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb) for framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.104811 29046 master.cpp:3657] Authorizing principal 'test-principal' to reserve resources '[{"allocation_info":{"role":"role1"},"name":"mem","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":256.0},"type":"SCALAR"}]'
3: I1123 08:07:02.106252 29051 master.cpp:4563] Applying RESERVE operation for resources [{"allocation_info":{"role":"role1"},"name":"mem","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":256.0},"type":"SCALAR"}] from framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553 to agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb)
3: I1123 08:07:02.107183 29051 master.cpp:9945] Sending offer operation '' (uuid: e4bbf33a-edd0-4b43-9807-6fb69ef35fd9) to agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb)
3: I1123 08:07:02.108247 29050 slave.cpp:3594] Updated checkpointed resources from {} to mem(reservations: [(DYNAMIC,role1,test-principal)]):256
3: I1123 08:07:02.108335 29050 slave.cpp:6989] Updating the state of offer operation '' (uuid: e4bbf33a-edd0-4b43-9807-6fb69ef35fd9) of framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
3: I1123 08:07:02.108585 29047 master.cpp:9731] Updating the state of offer operation '' (uuid: e4bbf33a-edd0-4b43-9807-6fb69ef35fd9) of framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
3: I1123 08:07:02.110074 29052 hierarchical.cpp:856] Updated allocation of framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 from cpus(allocated: role1):1; mem(allocated: role1):512; disk(allocated: role1):367489; ports(allocated: role1):[31000-32000] to cpus(allocated: role1):1; mem(allocated: role1):256; disk(allocated: role1):367489; ports(allocated: role1):[31000-32000]; mem(allocated: role1)(reservations: [(DYNAMIC,role1,test-principal)]):256
3: I1123 08:07:02.111292 29052 hierarchical.cpp:1132] Recovered cpus(allocated: role1):1; mem(allocated: role1):256; disk(allocated: role1):367489; ports(allocated: role1):[31000-32000]; mem(allocated: role1)(reservations: [(DYNAMIC,role1,test-principal)]):256 (total: cpus:1; mem:256; disk:367489; ports:[31000-32000]; mem(reservations: [(DYNAMIC,role1,test-principal)]):256, allocated: {}) on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 from framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.112908 29052 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.3771ms
3: I1123 08:07:02.113917 29055 master.cpp:8142] Sending 1 offers to framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.114468 29058 sched.cpp:921] Scheduler::resourceOffers took 107483ns
3: I1123 08:07:02.115414 29060 master.cpp:5434] Processing DECLINE call for offers: [ 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O1 ] for framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.115634 20036 sched.cpp:232] Version: 1.5.0
3: I1123 08:07:02.116161 29042 sched.cpp:336] New master detected at master@172.17.0.2:33553
3: I1123 08:07:02.116248 29042 sched.cpp:396] Authenticating with master master@172.17.0.2:33553
3: I1123 08:07:02.116262 29042 sched.cpp:403] Using default CRAM-MD5 authenticatee
3: I1123 08:07:02.116283 29060 master.cpp:10063] Removing offer 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O1
3: I1123 08:07:02.116464 29064 authenticatee.cpp:121] Creating new client SASL connection
3: I1123 08:07:02.116739 29046 master.cpp:8312] Authenticating scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: I1123 08:07:02.116834 29063 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1703)@172.17.0.2:33553
3: I1123 08:07:02.116961 29061 hierarchical.cpp:1132] Recovered cpus(allocated: role1):1; mem(allocated: role1):256; disk(allocated: role1):367489; ports(allocated: role1):[31000-32000]; mem(allocated: role1)(reservations: [(DYNAMIC,role1,test-principal)]):256 (total: cpus:1; mem:256; disk:367489; ports:[31000-32000]; mem(reservations: [(DYNAMIC,role1,test-principal)]):256, allocated: {}) on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 from framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: W1123 08:07:02.117055 29061 hierarchical.cpp:1153] Using 365 days to create the refused resources offer filter because the input value is too big
3: I1123 08:07:02.117070 29061 hierarchical.cpp:1178] Framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 filtered agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 for 365days
3: I1123 08:07:02.117110 29053 authenticator.cpp:98] Creating new server SASL connection
3: I1123 08:07:02.117400 29051 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1123 08:07:02.117424 29051 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1123 08:07:02.117506 29051 authenticator.cpp:204] Received SASL authentication start
3: I1123 08:07:02.117547 29051 authenticator.cpp:326] Authentication requires more steps
3: I1123 08:07:02.117677 29047 authenticatee.cpp:259] Received SASL authentication step
3: I1123 08:07:02.117825 29052 authenticator.cpp:232] Received SASL authentication step
3: I1123 08:07:02.117854 29052 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'dce3e4c418cb' server FQDN: 'dce3e4c418cb' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I1123 08:07:02.117864 29052 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1123 08:07:02.117887 29052 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1123 08:07:02.117909 29052 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'dce3e4c418cb' server FQDN: 'dce3e4c418cb' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I1123 08:07:02.117924 29052 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1123 08:07:02.117938 29052 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1123 08:07:02.117956 29052 authenticator.cpp:318] Authentication success
3: I1123 08:07:02.118129 29055 authenticatee.cpp:299] Authentication success
3: I1123 08:07:02.118171 29058 master.cpp:8342] Successfully authenticated principal 'test-principal' at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: I1123 08:07:02.118221 29052 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1703)@172.17.0.2:33553
3: I1123 08:07:02.118366 29062 sched.cpp:502] Successfully authenticated with master master@172.17.0.2:33553
3: I1123 08:07:02.118389 29062 sched.cpp:824] Sending SUBSCRIBE call to master@172.17.0.2:33553
3: I1123 08:07:02.118492 29062 sched.cpp:857] Will retry registration in 867.237435ms if necessary
3: I1123 08:07:02.118654 29052 master.cpp:2963] Received SUBSCRIBE call for framework 'framework2' at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: I1123 08:07:02.118731 29052 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ role2 }'
3: I1123 08:07:02.119114 29054 master.cpp:3043] Subscribing framework framework2 with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
3: I1123 08:07:02.119624 29060 sched.cpp:751] Framework registered with 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001
3: I1123 08:07:02.119663 29060 sched.cpp:765] Scheduler::registered took 17193ns
3: I1123 08:07:02.119796 29045 hierarchical.cpp:306] Added framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001
3: I1123 08:07:02.121027 29045 hierarchical.cpp:2175] Filtered offer with mem(reservations: [(DYNAMIC,role1,test-principal)]):256 on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 for role role1 of framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.121280 29045 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.342782ms
3: I1123 08:07:02.121671 29056 master.cpp:8142] Sending 1 offers to framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001 (framework2) at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: I1123 08:07:02.121984 29064 hierarchical.cpp:2175] Filtered offer with mem(reservations: [(DYNAMIC,role1,test-principal)]):256 on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 for role role1 of framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.122136 29056 sched.cpp:921] Scheduler::resourceOffers took 112277ns
3: I1123 08:07:02.122268 29064 hierarchical.cpp:1457] Performed allocation for 1 agents in 642408ns
3: I1123 08:07:02.123710 29055 master.cpp:10063] Removing offer 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O2
3: I1123 08:07:02.123853 29055 master.cpp:4230] Processing ACCEPT call for offers: [ 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O2 ] on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb) for framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001 (framework2) at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: I1123 08:07:02.123989 29055 master.cpp:3725] Authorizing principal 'test-principal' to unreserve resources '[{"allocation_info":{"role":"role2"},"name":"mem","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":256.0},"type":"SCALAR"}]'
3: W1123 08:07:02.125120 29043 master.cpp:2365] Dropping UNRESERVE offer operation from framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001 (framework2) at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553: cpus(allocated: role2):1; mem(allocated: role2):256; disk(allocated: role2):367489; ports(allocated: role2):[31000-32000] does not contain mem(allocated: role2)(reservations: [(DYNAMIC,role1,test-principal)]):256
3: I1123 08:07:02.126170 29062 hierarchical.cpp:1132] Recovered cpus(allocated: role2):1; mem(allocated: role2):256; disk(allocated: role2):367489; ports(allocated: role2):[31000-32000] (total: cpus:1; mem:256; disk:367489; ports:[31000-32000]; mem(reservations: [(DYNAMIC,role1,test-principal)]):256, allocated: {}) on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 from framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001
3: I1123 08:07:02.131615 29048 hierarchical.cpp:2175] Filtered offer with mem(reservations: [(DYNAMIC,role1,test-principal)]):256 on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 for role role1 of framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.131799 29048 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.342168ms
3: I1123 08:07:02.132169 29054 master.cpp:8142] Sending 1 offers to framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001 (framework2) at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: I1123 08:07:02.132602 29054 sched.cpp:921] Scheduler::resourceOffers took 90686ns
3: I1123 08:07:02.133033 20036 sched.cpp:2009] Asked to stop the driver
3: W1123 08:07:02.133100 29063 sched.cpp:1402] Attempting to decline an unknown offer 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O2
3: I1123 08:07:02.133225 29063 sched.cpp:1191] Stopping framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001
3: I1123 08:07:02.133363 29061 master.cpp:5434] Processing DECLINE call for offers: [ 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O2 ] for framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001 (framework2) at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: W1123 08:07:02.133399 29061 master.cpp:5455] Ignoring decline of offer 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O2 since it is no longer valid
3: I1123 08:07:02.133502 29061 master.cpp:8819] Processing TEARDOWN call for framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001 (framework2) at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: I1123 08:07:02.133525 29061 master.cpp:8831] Removing framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001 (framework2) at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: I1123 08:07:02.133535 29061 master.cpp:3333] Deactivating framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001 (framework2) at scheduler-8717cad6-6f3e-44d5-8b11-4ab9727c4a66@172.17.0.2:33553
3: I1123 08:07:02.133678 29047 hierarchical.cpp:419] Deactivated framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001
3: I1123 08:07:02.134030 29061 master.cpp:10063] Removing offer 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O3
3: I1123 08:07:02.134238 29058 slave.cpp:3270] Asked to shut down framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001 by master@172.17.0.2:33553
3: I1123 08:07:02.134268 29058 slave.cpp:3285] Cannot shut down unknown framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001
3: I1123 08:07:02.134407 29061 master.cpp:5539] Processing REVIVE call for framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.134552 29047 hierarchical.cpp:1132] Recovered cpus(allocated: role2):1; mem(allocated: role2):256; disk(allocated: role2):367489; ports(allocated: role2):[31000-32000] (total: cpus:1; mem:256; disk:367489; ports:[31000-32000]; mem(reservations: [(DYNAMIC,role1,test-principal)]):256, allocated: {}) on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 from framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001
3: I1123 08:07:02.134795 29047 hierarchical.cpp:358] Removed framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0001
3: I1123 08:07:02.134925 29047 hierarchical.cpp:1279] Revived offers for roles { role1 } of framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.136319 29047 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.2184ms
3: I1123 08:07:02.136835 29059 master.cpp:8142] Sending 1 offers to framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.137380 29044 sched.cpp:921] Scheduler::resourceOffers took 113313ns
3: I1123 08:07:02.137900 20036 sched.cpp:2009] Asked to stop the driver
3: I1123 08:07:02.138056 29060 sched.cpp:1191] Stopping framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.138278 29046 master.cpp:8819] Processing TEARDOWN call for framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.138303 29046 master.cpp:8831] Removing framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.138314 29046 master.cpp:3333] Deactivating framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 (framework1) at scheduler-45420782-bd4d-4881-9009-bad29a7608c1@172.17.0.2:33553
3: I1123 08:07:02.138567 29056 hierarchical.cpp:1457] Performed allocation for 1 agents in 177046ns
3: I1123 08:07:02.138788 29056 hierarchical.cpp:419] Deactivated framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.139029 29046 master.cpp:10063] Removing offer 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-O4
3: I1123 08:07:02.139225 29041 slave.cpp:3270] Asked to shut down framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000 by master@172.17.0.2:33553
3: I1123 08:07:02.139256 29041 slave.cpp:3285] Cannot shut down unknown framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.139953 29049 slave.cpp:883] Agent terminating
3: I1123 08:07:02.139956 29056 hierarchical.cpp:1132] Recovered cpus(allocated: role1):1; mem(allocated: role1):256; disk(allocated: role1):367489; ports(allocated: role1):[31000-32000]; mem(allocated: role1)(reservations: [(DYNAMIC,role1,test-principal)]):256 (total: cpus:1; mem:256; disk:367489; ports:[31000-32000]; mem(reservations: [(DYNAMIC,role1,test-principal)]):256, allocated: {}) on agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 from framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.140123 29049 master.cpp:1311] Agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb) disconnected
3: I1123 08:07:02.140142 29049 master.cpp:3370] Disconnecting agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb)
3: I1123 08:07:02.140182 29049 master.cpp:3389] Deactivating agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 at slave(951)@172.17.0.2:33553 (dce3e4c418cb)
3: I1123 08:07:02.140198 29056 hierarchical.cpp:358] Removed framework 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-0000
3: I1123 08:07:02.140272 29061 hierarchical.cpp:697] Agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0 deactivated
3: I1123 08:07:02.146389 29048 hierarchical.cpp:1457] Performed allocation for 1 agents in 109560ns
3: I1123 08:07:02.147698 20036 master.cpp:1153] Master terminating
3: I1123 08:07:02.148469 29057 hierarchical.cpp:633] Removed agent 04f5bbc4-23d1-47d2-9b15-53bf3a9f73f5-S0
3: [ OK ] ResourceProviderCapability/ReservationTest.PreventUnreservingAlienResources/1 (110 ms)
3: [----------] 36 tests from ResourceProviderCapability/ReservationTest (3311 ms total)
3:
3: [----------] Global test environment tear-down
3: [==========] 1771 tests from 183 test cases ran. (407524 ms total)
3: [ PASSED ] 1770 tests.
3: [ FAILED ] 1 test, listed below:
3: [ FAILED ] ContentType/ResourceProviderManagerHttpApiTest.ConvertResources/1, where GetParam() = application/json
3:
3: 1 FAILED TEST
3: YOU HAVE 23 DISABLED TESTS
3:
3: I1123 08:07:02.220273 29065 process.cpp:887] Failed to accept socket: future discarded
3/3 Test #3: MesosTests .......................***Failed 412.23 sec
67% tests passed, 1 tests failed out of 3
Total Test time (real) = 454.15 sec
The following tests FAILED:
3 - MesosTests (Failed)
Errors while running CTest
make[3]: Leaving directory `/mesos/build'
make[3]: *** [CMakeFiles/check] Error 8
make[2]: Leaving directory `/mesos/build'
make[2]: *** [CMakeFiles/check.dir/all] Error 2
make[1]: *** [CMakeFiles/check.dir/rule] Error 2
make[1]: Leaving directory `/mesos/build'
make: *** [check] Error 2
+ docker rmi mesos-1511422017-20779
Untagged: mesos-1511422017-20779:latest
Deleted: sha256:a03f326d4bd6e30445f031592a0a3a115f850dec5a129bf78429558815757041
Deleted: sha256:99aa98f1b6e504ceb5a16c1e9d4ed59ae8273d216993b135e068e34f381ef20f
Deleted: sha256:a0659202af38d5b5d6885fb4ed15b4bcb8037af224ec6b99dc7c9e4842465cc1
Deleted: sha256:158df3189762705337a9a1cd4177020d8faab70fd3efc67584f8792f4e2c585a
Deleted: sha256:b4e03aed4ff1e775d016b4f5b92f9a84da3c97516331a3860cf14b6930cb378c
Deleted: sha256:30cdb8102943738fd9ada3fb97822e831d512a65160c75c263d6cb95503f8b3d
Deleted: sha256:66a0936d110116a2f168edf299beb672f2f161d8188e60b04a881008b63f6dee
Deleted: sha256:3c3ebcfee1905e338a459e053ea2d7bf9f4b3a3841566ccd7ad80ce398c3c1ae
Deleted: sha256:9275246a1ffb26746e31eaf3fd37d97a7e6242730ddc281f5ae6c5bcf72e3d64
Deleted: sha256:c403f43049a6037dfc1e3a1416557947c1890c1c6f70bd8999a2d70697b48e83
Deleted: sha256:35e64c7dccd60d41310b29fe5e1028f20852f646718e81420a6ecd5fb5740fdc
Deleted: sha256:4bbdc7368c309c4472e14c597834f48490378fcecb076813e9d00cd0f68c3d58
Deleted: sha256:8b6c33e30f06dbdce773268801ae050cc38b5378f0c4f95400cd2ce5e04e9ef0
Deleted: sha256:09e5a5da43baf101902faf6b9911a37209edc3e83c0d17c4f07c7cb4715bf487
Deleted: sha256:08a6330969dbc8b1cccc1ec4eed0fa9618706a7ee7b912754ff58e71f92ea82d
Deleted: sha256:f5c885ccbfb6655360abbe32bcba09c8a26bc29865baf18ee80039d8ad28f278
Deleted: sha256:85b50e54d15457cdd7aa2b32393a82c22ff21e319eb212d00c3f97bb7ff45148
Deleted: sha256:83ebb265284185df7fe88a5045698cae8c612d5c57b171c17eab0f9f4cc2a40a
Deleted: sha256:c889ec87218364cb167f92f396c4c585fc05ddd91fb7dede4fb22b80ecb9b182
Deleted: sha256:aed0510006b375f3560d5af3ad69941af4ba58c84d5f10cd5ae56fb0089d4133
Deleted: sha256:451dce9e3fe6c6b09500b7339dd060c756cda5aebc7c84db005f85107548deaf
Deleted: sha256:fc2e41300fff10a27747f126fc5e64e13fe9c386e3876f935c431aec9c7373a3
Deleted: sha256:15ea5177333d5393df362ce0c9a07a51a77a34ebe290463a202953b17ac64214
Deleted: sha256:002eb808b55312ac4f221641719b78ede9dc39050e298b5ad36f20ba861ff4b6
Deleted: sha256:5cf86d035d3f3d76a6cb85a1546cd3201011194b9884966989ca07d0149e0613
Deleted: sha256:3a91e09586af8071d2223845b258b9d78a6a564c1ff5ca1b073cdb490ac26c16
Deleted: sha256:e11b81a64f4477f7e26d0d0a7bf338c9e159a55b65b76e705689df87f39e61c0
Deleted: sha256:d4b589e1e2a0cd202c8a2182bc3afe15bed7581ef1d6ccc90c8377ccfa6e0206
Deleted: sha256:a8dcce72326d3d7479ac88bd3acd4365aac22df15dc26b23660d823d49688297
Deleted: sha256:3016362fdb0946fcefbb4233eade6ffe6b0325129afbda726d8445444a556c18
Build step 'Execute shell' marked build as failure
Not sending mail to unregistered user yujie.jay@gmail.com
Build failed in Jenkins: Mesos-Buildbot » cmake,gcc,--verbose --disable-libtool-wrappers --enable-libevent --enable-ssl,GLOG_v=1 MESOS_VERBOSE=1,ubuntu:14.04,(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23) #4493
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%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4493/display/redirect?page=changes>
Changes:
[yujie.jay] Triggered 'ApplyOfferOperationMessage' for agent local resources.
[yujie.jay] Refactored 'MockResourceProvider' to include default functions.
[yujie.jay] Added resource provider support for all offer operations.
[yujie.jay] Improved log messages of offer operations.
------------------------------------------
[...truncated 31.07 MB...]
3: I1123 03:04:39.479714 29046 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_2_pVt1BM\/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 03:04:39.485232 29039 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_2_pVt1BM\/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 a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 (default) at scheduler-9503e3c6-7c0d-4799-a5df-78a0e99d13e0@172.17.0.2:36343 to agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0 at slave(858)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.486980 29039 master.cpp:10008] Sending updated checkpointed resources {} to agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0 at slave(858)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.489603 29052 slave.cpp:3666] Deleting persistent volume 'id1' at '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_pVt1BM/disk1/volumes/roles/default-role/id1'
3: I1123 03:04:39.490151 29052 slave.cpp:3594] Updated checkpointed resources from disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_pVt1BM/disk1,id1:path1]:2048 to {}
3: I1123 03:04:39.495167 29034 hierarchical.cpp:856] Updated allocation of framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 on agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-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_2_pVt1BM/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_pVt1BM/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_2_pVt1BM/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_pVt1BM/disk1]:2048
3: I1123 03:04:39.497594 29034 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_2_pVt1BM/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_pVt1BM/disk1]:2048 (total: cpus:2; mem:2048; ports:[31000-32000]; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_pVt1BM/disk2]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_pVt1BM/disk1]:2048, allocated: {}) on agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0 from framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000
3: I1123 03:04:39.497740 29034 hierarchical.cpp:1178] Framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 filtered agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0 for 5secs
3: I1123 03:04:39.498448 20035 sched.cpp:2009] Asked to stop the driver
3: I1123 03:04:39.498750 29056 sched.cpp:1191] Stopping framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000
3: I1123 03:04:39.499819 29050 master.cpp:8819] Processing TEARDOWN call for framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 (default) at scheduler-9503e3c6-7c0d-4799-a5df-78a0e99d13e0@172.17.0.2:36343
3: I1123 03:04:39.499863 29050 master.cpp:8831] Removing framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 (default) at scheduler-9503e3c6-7c0d-4799-a5df-78a0e99d13e0@172.17.0.2:36343
3: I1123 03:04:39.499881 29050 master.cpp:3333] Deactivating framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 (default) at scheduler-9503e3c6-7c0d-4799-a5df-78a0e99d13e0@172.17.0.2:36343
3: I1123 03:04:39.500274 29051 hierarchical.cpp:419] Deactivated framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000
3: I1123 03:04:39.500470 29037 slave.cpp:3270] Asked to shut down framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 by master@172.17.0.2:36343
3: I1123 03:04:39.500536 29037 slave.cpp:3295] Shutting down framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000
3: I1123 03:04:39.500622 29037 slave.cpp:5923] Shutting down executor '12e69d23-e0eb-4ce1-89b2-64e213d6355c' of framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 at executor(1)@172.17.0.2:37111
3: I1123 03:04:39.501335 29054 hierarchical.cpp:358] Removed framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000
3: I1123 03:04:39.502049 29193 exec.cpp:435] Executor asked to shutdown
3: I1123 03:04:39.502619 29198 executor.cpp:171] Received SHUTDOWN event
3: I1123 03:04:39.502655 29198 executor.cpp:747] Shutting down
3: I1123 03:04:39.502781 29056 containerizer.cpp:2322] Destroying container 94a7011e-85e9-48e4-844b-1d3a2deb132a in RUNNING state
3: I1123 03:04:39.502820 29056 containerizer.cpp:2919] Transitioning the state of container 94a7011e-85e9-48e4-844b-1d3a2deb132a from RUNNING to DESTROYING
3: I1123 03:04:39.503590 29056 launcher.cpp:156] Asked to destroy container 94a7011e-85e9-48e4-844b-1d3a2deb132a
3: I1123 03:04:39.522104 29033 slave.cpp:5179] Got exited event for executor(1)@172.17.0.2:37111
3: I1123 03:04:39.603098 29046 containerizer.cpp:2773] Container 94a7011e-85e9-48e4-844b-1d3a2deb132a has exited
3: I1123 03:04:39.606890 29039 provisioner.cpp:557] Ignoring destroy request for unknown container 94a7011e-85e9-48e4-844b-1d3a2deb132a
3: I1123 03:04:39.608317 29048 slave.cpp:5588] Executor '12e69d23-e0eb-4ce1-89b2-64e213d6355c' of framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 terminated with signal Killed
3: I1123 03:04:39.608398 29048 slave.cpp:5692] Cleaning up executor '12e69d23-e0eb-4ce1-89b2-64e213d6355c' of framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000 at executor(1)@172.17.0.2:37111
3: I1123 03:04:39.608808 29051 gc.cpp:90] Scheduling '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_sTyUIm/slaves/a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0/frameworks/a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000/executors/12e69d23-e0eb-4ce1-89b2-64e213d6355c/runs/94a7011e-85e9-48e4-844b-1d3a2deb132a' for gc 6.99999295567111days in the future
3: I1123 03:04:39.609133 29048 slave.cpp:5799] Cleaning up framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000
3: I1123 03:04:39.609375 29053 task_status_update_manager.cpp:289] Closing task status update streams for framework a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000
3: I1123 03:04:39.609405 29051 gc.cpp:90] Scheduling '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_sTyUIm/slaves/a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0/frameworks/a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000/executors/12e69d23-e0eb-4ce1-89b2-64e213d6355c' for gc 6.99999295193185days in the future
3: I1123 03:04:39.609782 29051 gc.cpp:90] Scheduling '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_2_sTyUIm/slaves/a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0/frameworks/a3368380-d4fd-4992-89e8-4e4372ff6ea2-0000' for gc 6.99999294748741days in the future
3: I1123 03:04:39.610149 20035 slave.cpp:883] Agent terminating
3: I1123 03:04:39.610579 29041 master.cpp:1311] Agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0 at slave(858)@172.17.0.2:36343 (ba1bfb1c6543) disconnected
3: I1123 03:04:39.610628 29041 master.cpp:3370] Disconnecting agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0 at slave(858)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.610723 29041 master.cpp:3389] Deactivating agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0 at slave(858)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.611008 29039 hierarchical.cpp:697] Agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0 deactivated
3: I1123 03:04:39.621697 20035 master.cpp:1153] Master terminating
3: I1123 03:04:39.623267 29054 hierarchical.cpp:633] Removed agent a3368380-d4fd-4992-89e8-4e4372ff6ea2-S0
3: [ OK ] DiskResource/PersistentVolumeTest.AccessPersistentVolume/2 (892 ms)
3: [ RUN ] DiskResource/PersistentVolumeTest.AccessPersistentVolume/3
3: I1123 03:04:39.636013 20035 cluster.cpp:162] Creating default 'local' authorizer
3: I1123 03:04:39.640893 29054 master.cpp:448] Master d142776f-7477-45ae-9f75-f29a441d43ef (ba1bfb1c6543) started on 172.17.0.2:36343
3: I1123 03:04:39.640924 29054 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/rAMOsG/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/rAMOsG/master" --zk_session_timeout="10secs"
3: I1123 03:04:39.641469 29054 master.cpp:499] Master only allowing authenticated frameworks to register
3: I1123 03:04:39.641480 29054 master.cpp:505] Master only allowing authenticated agents to register
3: I1123 03:04:39.641486 29054 master.cpp:511] Master only allowing authenticated HTTP frameworks to register
3: I1123 03:04:39.641494 29054 credentials.hpp:37] Loading credentials for authentication from '/tmp/rAMOsG/credentials'
3: I1123 03:04:39.642019 29054 master.cpp:555] Using default 'crammd5' authenticator
3: I1123 03:04:39.642307 29054 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
3: I1123 03:04:39.642613 29054 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
3: I1123 03:04:39.642819 29054 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
3: I1123 03:04:39.643046 29054 master.cpp:634] Authorization enabled
3: I1123 03:04:39.643373 29046 hierarchical.cpp:173] Initialized hierarchical allocator process
3: I1123 03:04:39.643448 29052 whitelist_watcher.cpp:77] No whitelist given
3: I1123 03:04:39.648133 29038 master.cpp:2215] Elected as the leading master!
3: I1123 03:04:39.648188 29038 master.cpp:1695] Recovering from registrar
3: I1123 03:04:39.648448 29053 registrar.cpp:347] Recovering registrar
3: I1123 03:04:39.649387 29053 registrar.cpp:391] Successfully fetched the registry (0B) in 0ns
3: I1123 03:04:39.649538 29053 registrar.cpp:495] Applied 1 operations in 46514ns; attempting to update the registry
3: I1123 03:04:39.650339 29053 registrar.cpp:552] Successfully updated the registry in 0ns
3: I1123 03:04:39.650506 29053 registrar.cpp:424] Successfully recovered registrar
3: I1123 03:04:39.651118 29043 master.cpp:1808] Recovered 0 agents from the registry (129B); allowing 10mins for agents to re-register
3: I1123 03:04:39.651238 29055 hierarchical.cpp:211] Skipping recovery of hierarchical allocator: nothing to recover
3: W1123 03:04:39.659313 20035 process.cpp:2756] Attempted to spawn already running process files@172.17.0.2:36343
3: I1123 03:04:39.660724 20035 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W1123 03:04:39.661496 20035 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W1123 03:04:39.661686 20035 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I1123 03:04:39.661736 20035 provisioner.cpp:259] Using default backend 'copy'
3: I1123 03:04:39.664733 20035 cluster.cpp:448] Creating default 'local' authorizer
3: I1123 03:04:39.668217 29055 slave.cpp:262] Mesos agent started on (859)@172.17.0.2:36343
3: I1123 03:04:39.668251 29055 slave.cpp:263] Flags at startup: --acls="" --agent_features="capabilities {
3: type: MULTI_ROLE
3: }
3: capabilities {
3: type: HIERARCHICAL_ROLE
3: }
3: capabilities {
3: type: RESERVATION_REFINEMENT
3: }
3: capabilities {
3: type: RESOURCE_PROVIDER
3: }
3: " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bGaZbx/store/appc" --authenticate_http_executors="true" --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_AccessPersistentVolume_3_bGaZbx/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_AccessPersistentVolume_3_bGaZbx/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_secret_key="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bGaZbx/executor_secret_key" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bGaZbx/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_AccessPersistentVolume_3_bGaZbx/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="[{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":2048.0},"type":"SCALAR"},{"disk":{"source":{"path":{"root":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi\/disk1"},"type":"PATH"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"},{"disk":{"source":{"path":{"root":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi\/disk2"},"type":"PATH"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bGaZbx" --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_AccessPersistentVolume_3_ULYOVU" --zk_session_timeout="10secs"
3: I1123 03:04:39.669162 29055 credentials.hpp:86] Loading credential for authentication from '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bGaZbx/credential'
3: I1123 03:04:39.669520 29055 slave.cpp:295] Agent using credential for: test-principal
3: I1123 03:04:39.669556 29055 credentials.hpp:37] Loading credentials for authentication from '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bGaZbx/http_credentials'
3: I1123 03:04:39.670097 29055 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
3: I1123 03:04:39.670389 29055 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
3: I1123 03:04:39.670821 29055 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1123 03:04:39.671048 29055 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
3: I1123 03:04:39.671458 29055 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1123 03:04:39.671670 29055 http.cpp:1066] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
3: I1123 03:04:39.678011 29055 slave.cpp:593] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":2048.0},"type":"SCALAR"},{"disk":{"source":{"path":{"root":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi\/disk1"},"type":"PATH"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"},{"disk":{"source":{"path":{"root":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi\/disk2"},"type":"PATH"}},"name":"disk","reservations":[{"role":"default-role","type":"STATIC"}],"scalar":{"value":2048.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
3: I1123 03:04:39.678791 29055 slave.cpp:601] Agent attributes: [ ]
3: I1123 03:04:39.678813 29055 slave.cpp:610] Agent hostname: ba1bfb1c6543
3: I1123 03:04:39.679077 29037 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1123 03:04:39.682008 29043 state.cpp:64] Recovering state from '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/meta'
3: I1123 03:04:39.682607 29043 task_status_update_manager.cpp:207] Recovering task status update manager
3: I1123 03:04:39.682940 29041 containerizer.cpp:668] Recovering containerizer
3: I1123 03:04:39.685137 29034 provisioner.cpp:455] Provisioner recovery complete
3: I1123 03:04:39.685724 29033 slave.cpp:6493] Finished recovery
3: I1123 03:04:39.686784 29055 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I1123 03:04:39.686794 29042 slave.cpp:1007] New master detected at master@172.17.0.2:36343
3: I1123 03:04:39.686934 29042 slave.cpp:1042] Detecting new master
3: I1123 03:04:39.687269 29042 slave.cpp:1069] Authenticating with master master@172.17.0.2:36343
3: I1123 03:04:39.687391 29042 slave.cpp:1078] Using default CRAM-MD5 authenticatee
3: I1123 03:04:39.687799 29053 authenticatee.cpp:121] Creating new client SASL connection
3: I1123 03:04:39.688275 29039 master.cpp:8312] Authenticating slave(859)@172.17.0.2:36343
3: I1123 03:04:39.688504 29043 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1528)@172.17.0.2:36343
3: I1123 03:04:39.689095 29049 authenticator.cpp:98] Creating new server SASL connection
3: I1123 03:04:39.689563 29045 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1123 03:04:39.689602 29045 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1123 03:04:39.689751 29045 authenticator.cpp:204] Received SASL authentication start
3: I1123 03:04:39.689816 29045 authenticator.cpp:326] Authentication requires more steps
3: I1123 03:04:39.689960 29045 authenticatee.cpp:259] Received SASL authentication step
3: I1123 03:04:39.690105 29045 authenticator.cpp:232] Received SASL authentication step
3: I1123 03:04:39.690138 29045 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ba1bfb1c6543' server FQDN: 'ba1bfb1c6543' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I1123 03:04:39.690155 29045 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1123 03:04:39.690198 29045 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1123 03:04:39.690232 29045 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ba1bfb1c6543' server FQDN: 'ba1bfb1c6543' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I1123 03:04:39.690243 29045 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1123 03:04:39.690253 29045 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1123 03:04:39.690269 29045 authenticator.cpp:318] Authentication success
3: I1123 03:04:39.690434 29035 authenticatee.cpp:299] Authentication success
3: I1123 03:04:39.690506 29046 master.cpp:8342] Successfully authenticated principal 'test-principal' at slave(859)@172.17.0.2:36343
3: I1123 03:04:39.690583 29041 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1528)@172.17.0.2:36343
3: I1123 03:04:39.690830 29045 slave.cpp:1161] Successfully authenticated with master master@172.17.0.2:36343
3: I1123 03:04:39.691166 29045 slave.cpp:1685] Will retry registration in 10.405863ms if necessary
3: I1123 03:04:39.691597 29037 master.cpp:6036] Received register agent message from slave(859)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.691787 29037 master.cpp:3872] Authorizing agent with principal 'test-principal'
3: I1123 03:04:39.692452 29033 master.cpp:6098] Authorized registration of agent at slave(859)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.692600 29033 master.cpp:6191] Registering agent at slave(859)@172.17.0.2:36343 (ba1bfb1c6543) with id d142776f-7477-45ae-9f75-f29a441d43ef-S0
3: I1123 03:04:39.693208 29056 registrar.cpp:495] Applied 1 operations in 88767ns; attempting to update the registry
3: I1123 03:04:39.694126 29044 registrar.cpp:552] Successfully updated the registry in 0ns
3: I1123 03:04:39.694600 29039 master.cpp:6240] Admitted agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.696038 29049 slave.cpp:1207] Registered with master master@172.17.0.2:36343; given agent ID d142776f-7477-45ae-9f75-f29a441d43ef-S0
3: I1123 03:04:39.696053 29039 master.cpp:6276] Registered agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543) with cpus:2; mem:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk1]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk2]:2048; ports:[31000-32000]
3: I1123 03:04:39.696183 29054 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I1123 03:04:39.696506 29049 slave.cpp:1227] Checkpointing SlaveInfo to '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/meta/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/slave.info'
3: I1123 03:04:39.696776 29040 hierarchical.cpp:600] Added agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 (ba1bfb1c6543) with cpus:2; mem:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk1]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk2]:2048; ports:[31000-32000] (allocated: {})
3: I1123 03:04:39.697298 29040 hierarchical.cpp:1457] Performed allocation for 1 agents in 199680ns
3: I1123 03:04:39.697268 29049 slave.cpp:1288] Forwarding total resources cpus:2; mem:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk1]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk2]:2048; ports:[31000-32000]
3: I1123 03:04:39.697441 29049 slave.cpp:1298] Forwarding total oversubscribed resources {}
3: I1123 03:04:39.698487 29038 master.cpp:7078] Received update of agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543) with total resources cpus:2; mem:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk1]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk2]:2048; ports:[31000-32000]
3: I1123 03:04:39.698627 29038 master.cpp:7091] Received update of agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543) with total oversubscribed resources {}
3: I1123 03:04:39.698952 29038 master.cpp:7109] Ignoring update on agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543) as it reports no changes
3: W1123 03:04:39.699591 20035 process.cpp:2756] Attempted to spawn already running process version@172.17.0.2:36343
3: I1123 03:04:39.700669 20035 sched.cpp:232] Version: 1.5.0
3: I1123 03:04:39.701436 29047 sched.cpp:336] New master detected at master@172.17.0.2:36343
3: I1123 03:04:39.701550 29047 sched.cpp:396] Authenticating with master master@172.17.0.2:36343
3: I1123 03:04:39.701568 29047 sched.cpp:403] Using default CRAM-MD5 authenticatee
3: I1123 03:04:39.701867 29045 authenticatee.cpp:121] Creating new client SASL connection
3: I1123 03:04:39.702172 29037 master.cpp:8312] Authenticating scheduler-3148f977-1a39-4f6c-b6d9-b8bed663ed92@172.17.0.2:36343
3: I1123 03:04:39.702337 29033 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1529)@172.17.0.2:36343
3: I1123 03:04:39.702706 29055 authenticator.cpp:98] Creating new server SASL connection
3: I1123 03:04:39.703033 29056 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I1123 03:04:39.703060 29056 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I1123 03:04:39.703181 29056 authenticator.cpp:204] Received SASL authentication start
3: I1123 03:04:39.703229 29056 authenticator.cpp:326] Authentication requires more steps
3: I1123 03:04:39.703336 29056 authenticatee.cpp:259] Received SASL authentication step
3: I1123 03:04:39.703449 29056 authenticator.cpp:232] Received SASL authentication step
3: I1123 03:04:39.703481 29056 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ba1bfb1c6543' server FQDN: 'ba1bfb1c6543' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I1123 03:04:39.703492 29056 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I1123 03:04:39.703517 29056 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I1123 03:04:39.703536 29056 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ba1bfb1c6543' server FQDN: 'ba1bfb1c6543' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I1123 03:04:39.703543 29056 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I1123 03:04:39.703549 29056 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I1123 03:04:39.703562 29056 authenticator.cpp:318] Authentication success
3: I1123 03:04:39.703740 29044 authenticatee.cpp:299] Authentication success
3: I1123 03:04:39.703812 29043 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1529)@172.17.0.2:36343
3: I1123 03:04:39.703840 29052 master.cpp:8342] Successfully authenticated principal 'test-principal' at scheduler-3148f977-1a39-4f6c-b6d9-b8bed663ed92@172.17.0.2:36343
3: I1123 03:04:39.704231 29044 sched.cpp:502] Successfully authenticated with master master@172.17.0.2:36343
3: I1123 03:04:39.704260 29044 sched.cpp:824] Sending SUBSCRIBE call to master@172.17.0.2:36343
3: I1123 03:04:39.704433 29044 sched.cpp:857] Will retry registration in 1.436915156secs if necessary
3: I1123 03:04:39.704715 29038 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at scheduler-3148f977-1a39-4f6c-b6d9-b8bed663ed92@172.17.0.2:36343
3: I1123 03:04:39.704810 29038 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ default-role }'
3: I1123 03:04:39.705447 29050 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT, SHARED_RESOURCES ]
3: I1123 03:04:39.706348 29034 sched.cpp:751] Framework registered with d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:39.706429 29034 sched.cpp:765] Scheduler::registered took 50660ns
3: I1123 03:04:39.706490 29048 hierarchical.cpp:306] Added framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:39.708407 29048 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.762913ms
3: I1123 03:04:39.709328 29051 master.cpp:8142] Sending 1 offers to framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 (default) at scheduler-3148f977-1a39-4f6c-b6d9-b8bed663ed92@172.17.0.2:36343
3: I1123 03:04:39.709996 29037 sched.cpp:921] Scheduler::resourceOffers took 121352ns
3: I1123 03:04:39.711091 29055 hierarchical.cpp:1457] Performed allocation for 1 agents in 201809ns
3: I1123 03:04:39.713958 29053 master.cpp:10063] Removing offer d142776f-7477-45ae-9f75-f29a441d43ef-O0
3: I1123 03:04:39.714159 29053 master.cpp:4230] Processing ACCEPT call for offers: [ d142776f-7477-45ae-9f75-f29a441d43ef-O0 ] on agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543) for framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 (default) at scheduler-3148f977-1a39-4f6c-b6d9-b8bed663ed92@172.17.0.2:36343
3: I1123 03:04:39.714313 29053 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_09VFFi\/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 03:04:39.714855 29053 master.cpp:3599] Authorizing framework principal 'test-principal' to launch task 03e36ce1-0fba-41bd-a201-b651feabe6b0
3: I1123 03:04:39.716341 29054 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_09VFFi\/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 d142776f-7477-45ae-9f75-f29a441d43ef-0000 (default) at scheduler-3148f977-1a39-4f6c-b6d9-b8bed663ed92@172.17.0.2:36343 to agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.717254 29054 master.cpp:9945] Sending offer operation '' (uuid: 274774eb-5792-468e-8b88-40fde4081f60) to agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.719156 29054 master.cpp:10814] Adding task 03e36ce1-0fba-41bd-a201-b651feabe6b0 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_09VFFi/disk1,id1:path1]:2048 on agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.719642 29049 slave.cpp:3594] Updated checkpointed resources from {} to disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk1,id1:path1]:2048
3: I1123 03:04:39.719794 29049 slave.cpp:6989] Updating the state of offer operation '' (uuid: 274774eb-5792-468e-8b88-40fde4081f60) of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
3: I1123 03:04:39.719599 29054 master.cpp:4978] Launching task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 (default) at scheduler-3148f977-1a39-4f6c-b6d9-b8bed663ed92@172.17.0.2:36343 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_09VFFi\/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 d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:39.720402 29054 master.cpp:9731] Updating the state of offer operation '' (uuid: 274774eb-5792-468e-8b88-40fde4081f60) of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 (latest state: OFFER_OPERATION_FINISHED, status update state: OFFER_OPERATION_FINISHED)
3: I1123 03:04:39.721125 29043 slave.cpp:1806] Got assigned task '03e36ce1-0fba-41bd-a201-b651feabe6b0' for framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:39.722223 29043 slave.cpp:2074] Authorizing task '03e36ce1-0fba-41bd-a201-b651feabe6b0' for framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:39.722337 29043 slave.cpp:7349] Authorizing framework principal 'test-principal' to launch task 03e36ce1-0fba-41bd-a201-b651feabe6b0
3: I1123 03:04:39.723567 29041 slave.cpp:2242] Launching task '03e36ce1-0fba-41bd-a201-b651feabe6b0' for framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:39.724306 29041 paths.cpp:621] Trying to chown '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/fb67e335-d17f-414b-82c9-f9f7b725303c' to user 'mesos'
3: I1123 03:04:39.724613 29041 slave.cpp:7823] Launching executor '03e36ce1-0fba-41bd-a201-b651feabe6b0' of framework d142776f-7477-45ae-9f75-f29a441d43ef-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_ULYOVU/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/fb67e335-d17f-414b-82c9-f9f7b725303c'
3: I1123 03:04:39.725795 29041 slave.cpp:2470] Queued task '03e36ce1-0fba-41bd-a201-b651feabe6b0' for executor '03e36ce1-0fba-41bd-a201-b651feabe6b0' of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:39.725924 29041 slave.cpp:958] Successfully attached '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/fb67e335-d17f-414b-82c9-f9f7b725303c' to virtual path '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/latest'
3: I1123 03:04:39.725967 29041 slave.cpp:958] Successfully attached '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/fb67e335-d17f-414b-82c9-f9f7b725303c' to virtual path '/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/latest'
3: I1123 03:04:39.726016 29041 slave.cpp:958] Successfully attached '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/fb67e335-d17f-414b-82c9-f9f7b725303c' to virtual path '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/fb67e335-d17f-414b-82c9-f9f7b725303c'
3: I1123 03:04:39.726428 29041 slave.cpp:2933] Launching container fb67e335-d17f-414b-82c9-f9f7b725303c for executor '03e36ce1-0fba-41bd-a201-b651feabe6b0' of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:39.726828 29045 containerizer.cpp:1195] Starting container fb67e335-d17f-414b-82c9-f9f7b725303c
3: I1123 03:04:39.726794 29044 hierarchical.cpp:856] Updated allocation of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 on agent d142776f-7477-45ae-9f75-f29a441d43ef-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_09VFFi/disk1]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/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_09VFFi/disk2]:2048; disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk1,id1:path1]:2048
3: I1123 03:04:39.727749 29045 containerizer.cpp:1367] Checkpointed ContainerConfig at '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bGaZbx/containers/fb67e335-d17f-414b-82c9-f9f7b725303c/config'
3: I1123 03:04:39.727778 29045 containerizer.cpp:2919] Transitioning the state of container fb67e335-d17f-414b-82c9-f9f7b725303c from PROVISIONING to PREPARING
3: I1123 03:04:39.728379 29051 posix.cpp:204] Changing the ownership of the persistent volume at '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk1/volumes/roles/default-role/id1' with uid 1000 and gid 1000
3: I1123 03:04:39.728598 29051 posix.cpp:250] Adding symlink from '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk1/volumes/roles/default-role/id1' to '/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/fb67e335-d17f-414b-82c9-f9f7b725303c/path1' for persistent volume disk(allocated: default-role)(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk1,id1:path1]:2048 of container fb67e335-d17f-414b-82c9-f9f7b725303c
3: I1123 03:04:39.728989 29044 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_09VFFi/disk2]:2048 (total: cpus:2; mem:2048; ports:[31000-32000]; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/disk2]:2048; disk(reservations: [(STATIC,default-role)])[PATH:/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_09VFFi/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_09VFFi/disk1,id1:path1]:2048) on agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 from framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:39.729221 29044 hierarchical.cpp:1178] Framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 filtered agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 for 5secs
3: I1123 03:04:39.734570 29039 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.2:36343"},{"name":"MESOS_CHECKPOINT","type":"VALUE","value":"0"},{"name":"MESOS_DIRECTORY","type":"VALUE","value":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU\/slaves\/d142776f-7477-45ae-9f75-f29a441d43ef-S0\/frameworks\/d142776f-7477-45ae-9f75-f29a441d43ef-0000\/executors\/03e36ce1-0fba-41bd-a201-b651feabe6b0\/runs\/fb67e335-d17f-414b-82c9-f9f7b725303c"},{"name":"MESOS_EXECUTOR_AUTHENTICATION_TOKEN","type":"VALUE","value":"eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJjaWQiOiJmYjY3ZTMzNS1kMTdmLTQxNGItODJjOS1mOWY3YjcyNTMwM2MiLCJlaWQiOiIwM2UzNmNlMS0wZmJhLTQxYmQtYTIwMS1iNjUxZmVhYmU2YjAiLCJmaWQiOiJkMTQyNzc2Zi03NDc3LTQ1YWUtOWY3NS1mMjlhNDQxZDQzZWYtMDAwMCJ9.4Xo5pMqTCUZFufGmYqgwLsfX1Qph9_G-Si3jswhY-m4"},{"name":"MESOS_EXECUTOR_ID","type":"VALUE","value":"03e36ce1-0fba-41bd-a201-b651feabe6b0"},{"name":"MESOS_EXECUTOR_SHUTDOWN_GRACE_PERIOD","type":"VALUE","value":"5secs"},{"name":"MESOS_FRAMEWORK_ID","type":"VALUE","value":"d142776f-7477-45ae-9f75-f29a441d43ef-0000"},{"name":"MESOS_HTTP_COMMAND_EXECUTOR","type":"VALUE","value":"0"},{"name":"MESOS_SLAVE_ID","type":"VALUE","value":"d142776f-7477-45ae-9f75-f29a441d43ef-S0"},{"name":"MESOS_SLAVE_PID","type":"VALUE","value":"slave(859)@172.17.0.2:36343"},{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU\/slaves\/d142776f-7477-45ae-9f75-f29a441d43ef-S0\/frameworks\/d142776f-7477-45ae-9f75-f29a441d43ef-0000\/executors\/03e36ce1-0fba-41bd-a201-b651feabe6b0\/runs\/fb67e335-d17f-414b-82c9-f9f7b725303c"}]},"task_environment":{},"user":"mesos","working_directory":"\/tmp\/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU\/slaves\/d142776f-7477-45ae-9f75-f29a441d43ef-S0\/frameworks\/d142776f-7477-45ae-9f75-f29a441d43ef-0000\/executors\/03e36ce1-0fba-41bd-a201-b651feabe6b0\/runs\/fb67e335-d17f-414b-82c9-f9f7b725303c"}" --pipe_read="14" --pipe_write="15" --runtime_directory="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_bGaZbx/containers/fb67e335-d17f-414b-82c9-f9f7b725303c" --unshare_namespace_mnt="false"'
3: I1123 03:04:39.739647 29039 launcher.cpp:140] Forked child with pid '29202' for container 'fb67e335-d17f-414b-82c9-f9f7b725303c'
3: I1123 03:04:39.740623 29039 containerizer.cpp:2919] Transitioning the state of container fb67e335-d17f-414b-82c9-f9f7b725303c from PREPARING to ISOLATING
3: I1123 03:04:39.743010 29048 containerizer.cpp:2919] Transitioning the state of container fb67e335-d17f-414b-82c9-f9f7b725303c from ISOLATING to FETCHING
3: I1123 03:04:39.743211 29045 fetcher.cpp:379] Starting to fetch URIs for container: fb67e335-d17f-414b-82c9-f9f7b725303c, directory: /tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_3_ULYOVU/slaves/d142776f-7477-45ae-9f75-f29a441d43ef-S0/frameworks/d142776f-7477-45ae-9f75-f29a441d43ef-0000/executors/03e36ce1-0fba-41bd-a201-b651feabe6b0/runs/fb67e335-d17f-414b-82c9-f9f7b725303c
3: I1123 03:04:39.744189 29051 containerizer.cpp:2919] Transitioning the state of container fb67e335-d17f-414b-82c9-f9f7b725303c from FETCHING to RUNNING
3: I1123 03:04:39.997985 29215 exec.cpp:162] Version: 1.5.0
3: I1123 03:04:40.013751 29055 slave.cpp:4110] Got registration for executor '03e36ce1-0fba-41bd-a201-b651feabe6b0' of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 from executor(1)@172.17.0.2:34312
3: I1123 03:04:40.017022 29050 slave.cpp:2672] Sending queued task '03e36ce1-0fba-41bd-a201-b651feabe6b0' to executor '03e36ce1-0fba-41bd-a201-b651feabe6b0' of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 at executor(1)@172.17.0.2:34312
3: I1123 03:04:40.019840 29222 exec.cpp:237] Executor registered on agent d142776f-7477-45ae-9f75-f29a441d43ef-S0
3: I1123 03:04:40.023890 29227 executor.cpp:171] Received SUBSCRIBED event
3: I1123 03:04:40.024857 29227 executor.cpp:175] Subscribed executor on ba1bfb1c6543
3: I1123 03:04:40.025274 29227 executor.cpp:171] Received LAUNCH event
3: I1123 03:04:40.028502 29227 executor.cpp:637] Starting task 03e36ce1-0fba-41bd-a201-b651feabe6b0
3: I1123 03:04:40.032583 29038 slave.cpp:4564] Handling status update TASK_STARTING (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 from executor(1)@172.17.0.2:34312
3: I1123 03:04:40.035193 29055 task_status_update_manager.cpp:328] Received task status update TASK_STARTING (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:40.035248 29055 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:40.035962 29055 task_status_update_manager.cpp:383] Forwarding task status update TASK_STARTING (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 to the agent
3: I1123 03:04:40.036239 29046 slave.cpp:5047] Forwarding the update TASK_STARTING (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 to master@172.17.0.2:36343
3: I1123 03:04:40.036667 29046 slave.cpp:4940] Task status update manager successfully handled status update TASK_STARTING (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:40.036747 29046 slave.cpp:4956] Sending acknowledgement for status update TASK_STARTING (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 to executor(1)@172.17.0.2:34312
3: I1123 03:04:40.037156 29040 master.cpp:7274] Status update TASK_STARTING (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 from agent d142776f-7477-45ae-9f75-f29a441d43ef-S0 at slave(859)@172.17.0.2:36343 (ba1bfb1c6543)
3: I1123 03:04:40.037221 29040 master.cpp:7336] Forwarding status update TASK_STARTING (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:40.037463 29040 master.cpp:9529] Updating the state of task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 (latest state: TASK_STARTING, status update state: TASK_STARTING)
3: I1123 03:04:40.037770 29034 sched.cpp:1029] Scheduler::statusUpdate took 70830ns
3: I1123 03:04:40.038112 29053 master.cpp:5793] Processing ACKNOWLEDGE call 91b094d5-7366-4325-b859-d2cb18bd427b for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000 (default) at scheduler-3148f977-1a39-4f6c-b6d9-b8bed663ed92@172.17.0.2:36343 on agent d142776f-7477-45ae-9f75-f29a441d43ef-S0
3: I1123 03:04:40.038529 29047 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
3: I1123 03:04:40.038950 29054 slave.cpp:3848] Task status update manager successfully handled status update acknowledgement (UUID: 91b094d5-7366-4325-b859-d2cb18bd427b) for task 03e36ce1-0fba-41bd-a201-b651feabe6b0 of framework d142776f-7477-45ae-9f75-f29a441d43ef-0000
write /dev/stdout: resource temporarily unavailable
+ docker rmi mesos-1511403733-16951
Build step 'Execute shell' marked build as failure
Not sending mail to unregistered user yujie.jay@gmail.com