See <https://builds.apache.org/job/Mesos-Buildbot/BUILDTOOL=cmake,COMPILER=gcc,CONFIGURATION=--verbose%20--disable-libtool-wrappers,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!qnode3)&&(!H23)/4511/display/redirect?page=changes>
Changes: [bbannier] Added generic stringification of hashmap of stringifiable types. [bbannier] Removed stringification for hashmaps of strings. ------------------------------------------ [...truncated 3.62 MB...] 3: I1129 18:46:26.774303 17384 sched.cpp:336] New master detected at [email protected]:39413 3: I1129 18:46:26.774405 17384 sched.cpp:396] Authenticating with master [email protected]:39413 3: I1129 18:46:26.774430 17384 sched.cpp:403] Using default CRAM-MD5 authenticatee 3: I1129 18:46:26.774770 17375 authenticatee.cpp:121] Creating new client SASL connection 3: I1129 18:46:26.775074 17383 master.cpp:8312] Authenticating [email protected]:39413 3: I1129 18:46:26.775204 17380 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(140)@172.17.0.2:39413 3: I1129 18:46:26.775449 17373 authenticator.cpp:98] Creating new server SASL connection 3: I1129 18:46:26.775653 17381 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1129 18:46:26.775677 17381 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1129 18:46:26.775768 17381 authenticator.cpp:204] Received SASL authentication start 3: I1129 18:46:26.775817 17381 authenticator.cpp:326] Authentication requires more steps 3: I1129 18:46:26.775905 17381 authenticatee.cpp:259] Received SASL authentication step 3: I1129 18:46:26.776012 17371 authenticator.cpp:232] Received SASL authentication step 3: I1129 18:46:26.776041 17371 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '03b8b0abfaa8' server FQDN: '03b8b0abfaa8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1129 18:46:26.776049 17371 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1129 18:46:26.776084 17371 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1129 18:46:26.776100 17371 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '03b8b0abfaa8' server FQDN: '03b8b0abfaa8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1129 18:46:26.776109 17371 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1129 18:46:26.776114 17371 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1129 18:46:26.776126 17371 authenticator.cpp:318] Authentication success 3: I1129 18:46:26.776197 17372 authenticatee.cpp:299] Authentication success 3: I1129 18:46:26.776288 17367 master.cpp:8342] Successfully authenticated principal 'test-principal' at [email protected]:39413 3: I1129 18:46:26.776331 17372 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(140)@172.17.0.2:39413 3: I1129 18:46:26.776463 17379 sched.cpp:502] Successfully authenticated with master [email protected]:39413 3: I1129 18:46:26.776485 17379 sched.cpp:824] Sending SUBSCRIBE call to [email protected]:39413 3: I1129 18:46:26.776602 17379 sched.cpp:857] Will retry registration in 207.501622ms if necessary 3: I1129 18:46:26.776756 17368 master.cpp:2963] Received SUBSCRIBE call for framework 'default' at [email protected]:39413 3: I1129 18:46:26.776834 17368 master.cpp:2280] Authorizing framework principal 'test-principal' to receive offers for roles '{ * }' 3: I1129 18:46:26.777357 17369 master.cpp:3043] Subscribing framework default with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ] 3: I1129 18:46:26.778009 17377 sched.cpp:751] Framework registered with db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.778053 17377 sched.cpp:765] Scheduler::registered took 20512ns 3: I1129 18:46:26.778229 17390 hierarchical.cpp:306] Added framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.779649 17390 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.245446ms 3: I1129 18:46:26.780095 17375 master.cpp:8142] Sending 1 offers to framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (default) at [email protected]:39413 3: I1129 18:46:26.781344 17383 sched.cpp:921] Scheduler::resourceOffers took 812497ns 3: I1129 18:46:26.782516 17380 master.cpp:10075] Removing offer db8ca395-30b2-4bf3-afe9-930b01977a7d-O0 3: I1129 18:46:26.782650 17380 master.cpp:4230] Processing ACCEPT call for offers: [ db8ca395-30b2-4bf3-afe9-930b01977a7d-O0 ] on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(61)@172.17.0.2:39413 (03b8b0abfaa8) for framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (default) at [email protected]:39413 3: I1129 18:46:26.782734 17380 master.cpp:3599] Authorizing framework principal 'test-principal' to launch task 0 3: W1129 18:46:26.784763 17376 validation.cpp:1391] Executor 'default' for task '0' uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. 3: W1129 18:46:26.784822 17376 validation.cpp:1403] Executor 'default' for task '0' uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. 3: I1129 18:46:26.785457 17376 master.cpp:10826] Adding task 0 with resources cpus(allocated: *):2; mem(allocated: *):1024 on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(61)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.785832 17376 master.cpp:4978] Launching task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (default) at [email protected]:39413 with resources [{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}] on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(61)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.786700 17387 slave.cpp:1795] Got assigned task '0' for framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.787470 17371 hierarchical.cpp:1132] Recovered ports(allocated: *):[31000-32000]; disk(allocated: *):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: cpus(allocated: *):2; mem(allocated: *):1024) on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 from framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.787575 17371 hierarchical.cpp:1178] Framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 filtered agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 for 5secs 3: I1129 18:46:26.787681 17387 slave.cpp:2063] Authorizing task '0' for framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.787792 17387 slave.cpp:7317] Authorizing framework principal 'test-principal' to launch task 0 3: I1129 18:46:26.788651 17388 slave.cpp:2231] Launching task '0' for framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.789172 17388 paths.cpp:621] Trying to chown '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default/runs/dc639fb3-d256-4804-955c-9b4f2854389b' to user 'mesos' 3: I1129 18:46:26.789402 17388 slave.cpp:7791] Launching executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 with resources [] in work directory '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default/runs/dc639fb3-d256-4804-955c-9b4f2854389b' 3: I1129 18:46:26.789866 17388 slave.cpp:2922] Launching container dc639fb3-d256-4804-955c-9b4f2854389b for executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.790194 17388 slave.cpp:2459] Queued task '0' for executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.790271 17388 slave.cpp:947] Successfully attached '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default/runs/dc639fb3-d256-4804-955c-9b4f2854389b' to virtual path '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default/runs/latest' 3: I1129 18:46:26.790308 17388 slave.cpp:947] Successfully attached '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default/runs/dc639fb3-d256-4804-955c-9b4f2854389b' to virtual path '/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default/runs/latest' 3: I1129 18:46:26.790338 17388 slave.cpp:947] Successfully attached '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default/runs/dc639fb3-d256-4804-955c-9b4f2854389b' to virtual path '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default/runs/dc639fb3-d256-4804-955c-9b4f2854389b' 3: W1129 18:46:26.792558 17372 process.cpp:2756] Attempted to spawn already running process [email protected]:39413 3: I1129 18:46:26.792721 17372 exec.cpp:162] Version: 1.5.0 3: I1129 18:46:26.793025 17368 exec.cpp:212] Executor started at: executor(12)@172.17.0.2:39413 with pid 17366 3: I1129 18:46:26.793200 17368 slave.cpp:4111] Got registration for executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 from executor(12)@172.17.0.2:39413 3: I1129 18:46:26.793680 17369 exec.cpp:237] Executor registered on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 3: I1129 18:46:26.793778 17369 exec.cpp:249] Executor::registered took 59798ns 3: I1129 18:46:26.794217 17368 slave.cpp:2661] Sending queued task '0' to executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 at executor(12)@172.17.0.2:39413 3: I1129 18:46:26.794776 17377 exec.cpp:331] Executor asked to run task '0' 3: I1129 18:46:26.794919 17377 exec.cpp:340] Executor::launchTask took 108970ns 3: I1129 18:46:26.795071 17377 exec.cpp:571] Executor sending status update TASK_RUNNING (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.795531 17377 slave.cpp:4565] Handling status update TASK_RUNNING (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 from executor(12)@172.17.0.2:39413 3: I1129 18:46:26.796427 17375 task_status_update_manager.cpp:328] Received task status update TASK_RUNNING (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.796501 17375 task_status_update_manager.cpp:507] Creating StatusUpdate stream for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.796946 17375 task_status_update_manager.cpp:383] Forwarding task status update TASK_RUNNING (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 to the agent 3: I1129 18:46:26.797147 17383 slave.cpp:5048] Forwarding the update TASK_RUNNING (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 to [email protected]:39413 3: I1129 18:46:26.797334 17383 slave.cpp:4941] Task status update manager successfully handled status update TASK_RUNNING (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.797379 17383 slave.cpp:4957] Sending acknowledgement for status update TASK_RUNNING (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 to executor(12)@172.17.0.2:39413 3: I1129 18:46:26.797525 17383 exec.cpp:388] Executor received status update acknowledgement d8abc365-8024-4fbd-880b-f49b92737945 for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.797521 17373 master.cpp:7274] Status update TASK_RUNNING (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 from agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(61)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.797574 17373 master.cpp:7336] Forwarding status update TASK_RUNNING (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.797739 17373 master.cpp:9529] Updating the state of task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING) 3: I1129 18:46:26.797941 17378 sched.cpp:1029] Scheduler::statusUpdate took 80137ns 3: I1129 18:46:26.798319 17376 master.cpp:5793] Processing ACKNOWLEDGE call d8abc365-8024-4fbd-880b-f49b92737945 for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (default) at [email protected]:39413 on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 3: I1129 18:46:26.798800 17370 task_status_update_manager.cpp:401] Received task status update acknowledgement (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.798856 17366 slave.cpp:909] Unregistering and shutting down 3: I1129 18:46:26.798960 17366 slave.cpp:3259] Asked to shut down framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 by @0.0.0.0:0 3: I1129 18:46:26.798991 17366 slave.cpp:3284] Shutting down framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.799031 17366 slave.cpp:5924] Shutting down executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 at executor(12)@172.17.0.2:39413 3: I1129 18:46:26.799075 17382 master.cpp:9195] Removing agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(61)@172.17.0.2:39413 (03b8b0abfaa8): the agent unregistered 3: I1129 18:46:26.799144 17388 exec.cpp:435] Executor asked to shutdown 3: I1129 18:46:26.799160 17366 slave.cpp:3849] Task status update manager successfully handled status update acknowledgement (UUID: d8abc365-8024-4fbd-880b-f49b92737945) for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.799182 17388 exec.cpp:450] Executor::shutdown took 17446ns 3: I1129 18:46:26.799331 17388 slave.cpp:5180] Got exited event for executor(12)@172.17.0.2:39413 3: I1129 18:46:26.799602 17372 registrar.cpp:495] Applied 1 operations in 97639ns; attempting to update the registry 3: I1129 18:46:26.800241 17377 registrar.cpp:552] Successfully updated the registry in 564992ns 3: I1129 18:46:26.800745 17384 master.cpp:9237] Removed agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(61)@172.17.0.2:39413 (03b8b0abfaa8): the agent unregistered 3: I1129 18:46:26.800966 17384 master.cpp:9529] Updating the state of task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (latest state: TASK_LOST, status update state: TASK_LOST) 3: I1129 18:46:26.801605 17390 hierarchical.cpp:633] Removed agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 3: I1129 18:46:26.801604 17384 master.cpp:9629] Removing task 0 with resources cpus(allocated: *):2; mem(allocated: *):1024 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(61)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.801842 17384 master.cpp:7331] Sending status update TASK_LOST for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 'Agent 03b8b0abfaa8 removed: the agent unregistered' 3: I1129 18:46:26.802110 17384 master.cpp:9658] Removing executor 'default' with resources [] of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(61)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.802182 17380 sched.cpp:1029] Scheduler::statusUpdate took 15177ns 3: I1129 18:46:26.802806 17384 master.cpp:2132] Notifying framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (default) at [email protected]:39413 of lost agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 (03b8b0abfaa8) 3: I1129 18:46:26.803069 17381 sched.cpp:1091] Lost agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 3: I1129 18:46:26.803133 17381 sched.cpp:1102] Scheduler::slaveLost took 25392ns 3: I1129 18:46:26.850045 17378 slave.cpp:5997] Killing executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 at executor(12)@172.17.0.2:39413 3: I1129 18:46:26.850610 17367 slave.cpp:5589] Executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 exited with status 0 3: I1129 18:46:26.850736 17367 slave.cpp:5693] Cleaning up executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 at executor(12)@172.17.0.2:39413 3: W1129 18:46:26.851001 17370 master.cpp:7461] Ignoring exited executor 'default' of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 on removed agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 3: I1129 18:46:26.851075 17379 gc.cpp:90] Scheduling '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default/runs/dc639fb3-d256-4804-955c-9b4f2854389b' for gc 6.99999015109926days in the future 3: I1129 18:46:26.851291 17367 slave.cpp:5800] Cleaning up framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.851291 17379 gc.cpp:90] Scheduling '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000/executors/default' for gc 6.9999901482637days in the future 3: I1129 18:46:26.851466 17389 task_status_update_manager.cpp:289] Closing task status update streams for framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.851536 17389 task_status_update_manager.cpp:538] Cleaning up status update stream for task 0 of framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.851626 17382 gc.cpp:90] Scheduling '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/slaves/db8ca395-30b2-4bf3-afe9-930b01977a7d-S0/frameworks/db8ca395-30b2-4bf3-afe9-930b01977a7d-0000' for gc 6.99999014493037days in the future 3: I1129 18:46:26.851668 17367 slave.cpp:872] Agent terminating 3: W1129 18:46:26.855454 17366 process.cpp:2756] Attempted to spawn already running process [email protected]:39413 3: I1129 18:46:26.856839 17366 containerizer.cpp:301] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1129 18:46:26.857604 17366 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1129 18:46:26.857790 17366 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1129 18:46:26.857836 17366 provisioner.cpp:259] Using default backend 'copy' 3: I1129 18:46:26.860891 17366 cluster.cpp:458] Creating default 'local' authorizer 3: I1129 18:46:26.864521 17368 slave.cpp:253] Mesos agent started on (62)@172.17.0.2:39413 3: I1129 18:46:26.864547 17368 slave.cpp:254] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/GarbageCollectorIntegrationTest_Restart_lHbx3p/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/GarbageCollectorIntegrationTest_Restart_lHbx3p/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/GarbageCollectorIntegrationTest_Restart_lHbx3p/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="50ms" --fetcher_cache_dir="/tmp/GarbageCollectorIntegrationTest_Restart_lHbx3p/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/GarbageCollectorIntegrationTest_Restart_lHbx3p/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/GarbageCollectorIntegrationTest_Restart_lHbx3p" --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/GarbageCollectorIntegrationTest_Restart_j0JsFe" --zk_session_timeout="10secs" 3: I1129 18:46:26.865165 17368 credentials.hpp:86] Loading credential for authentication from '/tmp/GarbageCollectorIntegrationTest_Restart_lHbx3p/credential' 3: I1129 18:46:26.865414 17368 slave.cpp:286] Agent using credential for: test-principal 3: I1129 18:46:26.865442 17368 credentials.hpp:37] Loading credentials for authentication from '/tmp/GarbageCollectorIntegrationTest_Restart_lHbx3p/http_credentials' 3: I1129 18:46:26.865795 17368 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1129 18:46:26.866065 17368 http.cpp:1045] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' 3: I1129 18:46:26.868516 17368 slave.cpp:582] 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: I1129 18:46:26.868918 17368 slave.cpp:590] Agent attributes: [ ] 3: I1129 18:46:26.868934 17368 slave.cpp:599] Agent hostname: 03b8b0abfaa8 3: I1129 18:46:26.869206 17373 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1129 18:46:26.871809 17376 state.cpp:64] Recovering state from '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/meta' 3: I1129 18:46:26.871898 17376 state.cpp:722] No committed checkpointed resources found at '/tmp/GarbageCollectorIntegrationTest_Restart_j0JsFe/meta/resources/resources.info' 3: I1129 18:46:26.873953 17388 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1129 18:46:26.874501 17372 containerizer.cpp:668] Recovering containerizer 3: I1129 18:46:26.876991 17384 provisioner.cpp:455] Provisioner recovery complete 3: I1129 18:46:26.877566 17374 slave.cpp:6494] Finished recovery 3: I1129 18:46:26.878796 17376 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1129 18:46:26.878792 17368 slave.cpp:996] New master detected at [email protected]:39413 3: I1129 18:46:26.878917 17368 slave.cpp:1031] Detecting new master 3: I1129 18:46:26.881777 17379 slave.cpp:1058] Authenticating with master [email protected]:39413 3: I1129 18:46:26.881883 17379 slave.cpp:1067] Using default CRAM-MD5 authenticatee 3: I1129 18:46:26.882283 17375 authenticatee.cpp:121] Creating new client SASL connection 3: I1129 18:46:26.882313 17367 hierarchical.cpp:1457] Performed allocation for 0 agents in 176916ns 3: I1129 18:46:26.882827 17382 master.cpp:8312] Authenticating slave(62)@172.17.0.2:39413 3: I1129 18:46:26.883008 17372 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(141)@172.17.0.2:39413 3: I1129 18:46:26.883380 17367 authenticator.cpp:98] Creating new server SASL connection 3: I1129 18:46:26.883787 17386 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1129 18:46:26.883827 17386 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1129 18:46:26.884012 17386 authenticator.cpp:204] Received SASL authentication start 3: I1129 18:46:26.883993 17389 slave.cpp:6108] Current disk usage 31.00%. Max allowed age: 4.129784641759723days 3: I1129 18:46:26.884106 17386 authenticator.cpp:326] Authentication requires more steps 3: I1129 18:46:26.884263 17389 authenticatee.cpp:259] Received SASL authentication step 3: I1129 18:46:26.884521 17378 authenticator.cpp:232] Received SASL authentication step 3: I1129 18:46:26.884526 17371 master.cpp:1883] Skipping periodic registry garbage collection: no agents qualify for removal 3: I1129 18:46:26.884578 17378 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '03b8b0abfaa8' server FQDN: '03b8b0abfaa8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1129 18:46:26.884593 17378 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1129 18:46:26.884646 17378 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1129 18:46:26.884675 17378 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '03b8b0abfaa8' server FQDN: '03b8b0abfaa8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1129 18:46:26.884692 17378 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1129 18:46:26.884701 17378 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1129 18:46:26.884724 17378 authenticator.cpp:318] Authentication success 3: I1129 18:46:26.884850 17387 authenticatee.cpp:299] Authentication success 3: I1129 18:46:26.885051 17376 master.cpp:8342] Successfully authenticated principal 'test-principal' at slave(62)@172.17.0.2:39413 3: I1129 18:46:26.885092 17387 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(141)@172.17.0.2:39413 3: I1129 18:46:26.885253 17368 slave.cpp:1150] Successfully authenticated with master [email protected]:39413 3: I1129 18:46:26.885588 17368 slave.cpp:1674] Will retry registration in 12.52457ms if necessary 3: I1129 18:46:26.885985 17369 master.cpp:6365] Received re-register agent message from agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.886246 17369 master.cpp:3872] Authorizing agent with principal 'test-principal' 3: I1129 18:46:26.886926 17390 master.cpp:6436] Authorized re-registration of agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.887064 17390 master.cpp:6618] Re-registering agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) 3: W1129 18:46:26.887845 17377 master.hpp:2277] Allowing UNKNOWN agent to reregister: hostname: "03b8b0abfaa8" 3: resources { 3: name: "cpus" 3: type: SCALAR 3: scalar { 3: value: 2 3: } 3: role: "*" 3: } 3: resources { 3: name: "mem" 3: type: SCALAR 3: scalar { 3: value: 1024 3: } 3: role: "*" 3: } 3: resources { 3: name: "disk" 3: type: SCALAR 3: scalar { 3: value: 1024 3: } 3: role: "*" 3: } 3: resources { 3: name: "ports" 3: type: RANGES 3: ranges { 3: range { 3: begin: 31000 3: end: 32000 3: } 3: } 3: role: "*" 3: } 3: id { 3: value: "db8ca395-30b2-4bf3-afe9-930b01977a7d-S0" 3: } 3: checkpoint: true 3: port: 39413 3: I1129 18:46:26.888196 17377 registrar.cpp:495] Applied 1 operations in 407576ns; attempting to update the registry 3: I1129 18:46:26.889194 17377 registrar.cpp:552] Successfully updated the registry in 0ns 3: I1129 18:46:26.889618 17367 master.cpp:6690] Re-admitted agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.890929 17367 master.cpp:6873] Re-registered agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] 3: I1129 18:46:26.891090 17374 slave.cpp:1332] Re-registered with master [email protected]:39413 3: I1129 18:46:26.891243 17389 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1129 18:46:26.891305 17374 slave.cpp:1389] Forwarding total oversubscribed resources {} 3: I1129 18:46:26.891273 17386 hierarchical.cpp:600] Added agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 (03b8b0abfaa8) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {}) 3: I1129 18:46:26.891633 17371 master.cpp:7091] Received update of agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) with total oversubscribed resources {} 3: I1129 18:46:26.891899 17371 master.cpp:7109] Ignoring update on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) as it reports no changes 3: I1129 18:46:26.893273 17386 hierarchical.cpp:1457] Performed allocation for 1 agents in 1.715896ms 3: I1129 18:46:26.894037 17385 master.cpp:8142] Sending 1 offers to framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (default) at [email protected]:39413 3: I1129 18:46:26.894888 17378 sched.cpp:921] Scheduler::resourceOffers took 37006ns 3: I1129 18:46:26.895427 17366 sched.cpp:2009] Asked to stop the driver 3: I1129 18:46:26.895604 17388 sched.cpp:1191] Stopping framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.896075 17379 master.cpp:8819] Processing TEARDOWN call for framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (default) at [email protected]:39413 3: I1129 18:46:26.896132 17379 master.cpp:8831] Removing framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (default) at [email protected]:39413 3: I1129 18:46:26.896167 17379 master.cpp:3333] Deactivating framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 (default) at [email protected]:39413 3: I1129 18:46:26.896376 17387 hierarchical.cpp:419] Deactivated framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.897014 17379 master.cpp:10075] Removing offer db8ca395-30b2-4bf3-afe9-930b01977a7d-O1 3: I1129 18:46:26.897387 17382 slave.cpp:3259] Asked to shut down framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 by [email protected]:39413 3: I1129 18:46:26.897445 17382 slave.cpp:3274] Cannot shut down unknown framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.898125 17366 slave.cpp:872] Agent terminating 3: I1129 18:46:26.898243 17387 hierarchical.cpp:1132] Recovered cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 from framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.898385 17376 master.cpp:1311] Agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) disconnected 3: I1129 18:46:26.898424 17376 master.cpp:3370] Disconnecting agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.898506 17376 master.cpp:3389] Deactivating agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 at slave(62)@172.17.0.2:39413 (03b8b0abfaa8) 3: I1129 18:46:26.898825 17387 hierarchical.cpp:358] Removed framework db8ca395-30b2-4bf3-afe9-930b01977a7d-0000 3: I1129 18:46:26.898910 17387 hierarchical.cpp:697] Agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 deactivated 3: I1129 18:46:26.907889 17366 master.cpp:1153] Master terminating 3: I1129 18:46:26.908864 17374 hierarchical.cpp:633] Removed agent db8ca395-30b2-4bf3-afe9-930b01977a7d-S0 3: [ OK ] GarbageCollectorIntegrationTest.Restart (187 ms) 3: [ RUN ] GarbageCollectorIntegrationTest.ExitedFramework 3: I1129 18:46:26.919242 17366 cluster.cpp:170] Creating default 'local' authorizer 3: I1129 18:46:26.923815 17374 master.cpp:448] Master 2d4b6f64-166e-4c42-9c45-287c4623655d (03b8b0abfaa8) started on 172.17.0.2:39413 write /dev/stdout: resource temporarily unavailable + docker rmi mesos-1511978389-19191 Error response from daemon: conflict: unable to remove repository reference "mesos-1511978389-19191" (must force) - container 03b8b0abfaa8 is using its referenced image 81a79adf59a3 Build step 'Execute shell' marked build as failure Not sending mail to unregistered user [email protected]
