See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/73/>
------------------------------------------ [...truncated 13055 lines...] I0505 00:23:09.478384 24455 master.cpp:2838] Successfully authenticated slave(51)@67.195.138.9:37909 I0505 00:23:09.478520 24449 slave.cpp:644] Successfully authenticated with master [email protected]:37909 I0505 00:23:09.478582 24449 slave.cpp:873] Will retry registration in 6.185133022secs if necessary I0505 00:23:09.478658 24453 master.cpp:2134] Registering slave at slave(51)@67.195.138.9:37909 (vesta.apache.org) with id 20140505-002308-160088899-37909-24266-1 I0505 00:23:09.478857 24454 registrar.cpp:422] Attempting to update the 'registry' I0505 00:23:09.480067 24455 log.cpp:680] Attempting to append 515 bytes to the log I0505 00:23:09.480121 24449 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 5 I0505 00:23:09.480514 24455 replica.cpp:508] Replica received write request for position 5 I0505 00:23:09.492759 24455 leveldb.cpp:341] Persisting action (534 bytes) to leveldb took 12.229994ms I0505 00:23:09.492796 24455 replica.cpp:676] Persisted action at 5 I0505 00:23:09.493127 24453 replica.cpp:655] Replica received learned notice for position 5 I0505 00:23:09.572561 24453 leveldb.cpp:341] Persisting action (536 bytes) to leveldb took 79.381257ms I0505 00:23:09.572619 24453 replica.cpp:676] Persisted action at 5 I0505 00:23:09.572631 24453 replica.cpp:661] Replica learned APPEND action at position 5 I0505 00:23:09.573096 24453 registrar.cpp:479] Successfully updated 'registry' I0505 00:23:09.573251 24452 log.cpp:699] Attempting to truncate the log to 5 I0505 00:23:09.573354 24449 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 6 I0505 00:23:09.573360 24456 master.cpp:2174] Registered slave 20140505-002308-160088899-37909-24266-1 at slave(51)@67.195.138.9:37909 (vesta.apache.org) I0505 00:23:09.573384 24456 master.cpp:3283] Adding slave 20140505-002308-160088899-37909-24266-1 at slave(51)@67.195.138.9:37909 (vesta.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0505 00:23:09.573531 24452 slave.cpp:677] Registered with master [email protected]:37909; given slave ID 20140505-002308-160088899-37909-24266-1 I0505 00:23:09.573710 24456 replica.cpp:508] Replica received write request for position 6 I0505 00:23:09.573719 24452 slave.cpp:690] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/meta/slaves/20140505-002308-160088899-37909-24266-1/slave.info' I0505 00:23:09.573739 24453 hierarchical_allocator_process.hpp:444] Added slave 20140505-002308-160088899-37909-24266-1 (vesta.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I0505 00:23:09.573809 24453 hierarchical_allocator_process.hpp:751] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140505-002308-160088899-37909-24266-1 to framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:09.573995 24453 hierarchical_allocator_process.hpp:707] Performed allocation for slave 20140505-002308-160088899-37909-24266-1 in 224450ns I0505 00:23:09.574116 24452 master.hpp:612] Adding offer 20140505-002308-160088899-37909-24266-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140505-002308-160088899-37909-24266-1 (vesta.apache.org) I0505 00:23:09.574167 24452 master.cpp:2747] Sending 1 offers to framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:09.574404 24454 sched.cpp:529] Scheduler::resourceOffers took 31038ns I0505 00:23:09.575747 24453 master.hpp:622] Removing offer 20140505-002308-160088899-37909-24266-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140505-002308-160088899-37909-24266-1 (vesta.apache.org) I0505 00:23:09.575811 24453 master.cpp:1812] Processing reply for offers: [ 20140505-002308-160088899-37909-24266-1 ] on slave 20140505-002308-160088899-37909-24266-1 at slave(51)@67.195.138.9:37909 (vesta.apache.org) for framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:09.575906 24453 master.hpp:584] Adding task db857d58-97a8-4cd8-a42a-9eb62f4583fa with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140505-002308-160088899-37909-24266-1 (vesta.apache.org) I0505 00:23:09.575959 24453 master.cpp:2922] Launching task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140505-002308-160088899-37909-24266-1 at slave(51)@67.195.138.9:37909 (vesta.apache.org) I0505 00:23:09.576086 24449 slave.cpp:907] Got assigned task db857d58-97a8-4cd8-a42a-9eb62f4583fa for framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:09.576190 24449 slave.cpp:3085] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/meta/slaves/20140505-002308-160088899-37909-24266-1/frameworks/20140505-002308-160088899-37909-24266-0000/framework.info' I0505 00:23:09.576302 24449 slave.cpp:3092] Checkpointing framework pid 'scheduler(39)@67.195.138.9:37909' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/meta/slaves/20140505-002308-160088899-37909-24266-1/frameworks/20140505-002308-160088899-37909-24266-0000/framework.pid' I0505 00:23:09.576511 24449 slave.cpp:1017] Launching task db857d58-97a8-4cd8-a42a-9eb62f4583fa for framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:09.577499 24449 slave.cpp:3399] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/meta/slaves/20140505-002308-160088899-37909-24266-1/frameworks/20140505-002308-160088899-37909-24266-0000/executors/db857d58-97a8-4cd8-a42a-9eb62f4583fa/executor.info' I0505 00:23:09.577883 24449 slave.cpp:3496] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/meta/slaves/20140505-002308-160088899-37909-24266-1/frameworks/20140505-002308-160088899-37909-24266-0000/executors/db857d58-97a8-4cd8-a42a-9eb62f4583fa/runs/775df9b1-72da-44de-92f2-f87291e20cb7/tasks/db857d58-97a8-4cd8-a42a-9eb62f4583fa/task.info' I0505 00:23:09.577905 24450 mesos_containerizer.cpp:523] Starting container '775df9b1-72da-44de-92f2-f87291e20cb7' for executor 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' of framework '20140505-002308-160088899-37909-24266-0000' I0505 00:23:09.578043 24449 slave.cpp:1127] Queuing task 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' for executor db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework '20140505-002308-160088899-37909-24266-0000 I0505 00:23:09.578121 24449 slave.cpp:488] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/slaves/20140505-002308-160088899-37909-24266-1/frameworks/20140505-002308-160088899-37909-24266-0000/executors/db857d58-97a8-4cd8-a42a-9eb62f4583fa/runs/775df9b1-72da-44de-92f2-f87291e20cb7' I0505 00:23:09.579169 24450 launcher.cpp:117] Forked child with pid '25462' for container '775df9b1-72da-44de-92f2-f87291e20cb7' I0505 00:23:09.579269 24450 mesos_containerizer.cpp:746] Checkpointing executor's forked pid 25462 to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/meta/slaves/20140505-002308-160088899-37909-24266-1/frameworks/20140505-002308-160088899-37909-24266-0000/executors/db857d58-97a8-4cd8-a42a-9eb62f4583fa/runs/775df9b1-72da-44de-92f2-f87291e20cb7/pids/forked.pid' I0505 00:23:09.580445 24449 mesos_containerizer.cpp:623] Fetching URIs for container '775df9b1-72da-44de-92f2-f87291e20cb7' using command '/home/hudson/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src/mesos-fetcher' I0505 00:23:09.592635 24456 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 18.785108ms I0505 00:23:09.592696 24456 replica.cpp:676] Persisted action at 6 I0505 00:23:09.593547 24451 replica.cpp:655] Replica received learned notice for position 6 I0505 00:23:09.600426 24451 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 6.841373ms I0505 00:23:09.600484 24451 leveldb.cpp:399] Deleting ~2 keys from leveldb took 18966ns I0505 00:23:09.600498 24451 replica.cpp:676] Persisted action at 6 I0505 00:23:09.600510 24451 replica.cpp:661] Replica learned TRUNCATE action at position 6 I0505 00:23:09.973253 24456 slave.cpp:2284] Monitoring executor 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' of framework '20140505-002308-160088899-37909-24266-0000' in container '775df9b1-72da-44de-92f2-f87291e20cb7' WARNING: Logging before InitGoogleLogging() is written to STDERR I0505 00:23:10.005146 25484 process.cpp:1611] libprocess is initialized on 67.195.138.9:35102 for 8 cpus I0505 00:23:10.006180 25484 exec.cpp:131] Version: 0.19.0 I0505 00:23:10.007604 25499 exec.cpp:181] Executor started at: executor(1)@67.195.138.9:35102 with pid 25484 I0505 00:23:10.008164 24456 slave.cpp:1600] Got registration for executor 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.008224 24456 slave.cpp:1685] Checkpointing executor pid 'executor(1)@67.195.138.9:35102' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/meta/slaves/20140505-002308-160088899-37909-24266-1/frameworks/20140505-002308-160088899-37909-24266-0000/executors/db857d58-97a8-4cd8-a42a-9eb62f4583fa/runs/775df9b1-72da-44de-92f2-f87291e20cb7/pids/libprocess.pid' I0505 00:23:10.008625 24456 slave.cpp:1719] Flushing queued task db857d58-97a8-4cd8-a42a-9eb62f4583fa for executor 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.008990 25506 process.cpp:1023] Socket closed while receiving I0505 00:23:10.009049 25505 exec.cpp:205] Executor registered on slave 20140505-002308-160088899-37909-24266-1 I0505 00:23:10.009913 25505 exec.cpp:217] Executor::registered took 83098ns Registered executor on vesta.apache.org I0505 00:23:10.010023 25505 exec.cpp:292] Executor asked to run task 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' I0505 00:23:10.010076 25505 exec.cpp:301] Executor::launchTask took 34587ns Starting task db857d58-97a8-4cd8-a42a-9eb62f4583fa Forked command at 25507 sh -c 'sleep 1000' I0505 00:23:10.011773 25503 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.012099 24454 slave.cpp:1955] Handling status update TASK_RUNNING (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 from executor(1)@67.195.138.9:35102 I0505 00:23:10.012217 24454 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.012229 24454 status_update_manager.cpp:499] Creating StatusUpdate stream for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.012406 24454 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.271118 24454 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 to [email protected]:37909 I0505 00:23:10.271327 24454 slave.cpp:2072] Status update manager successfully handled status update TASK_RUNNING (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.271338 24454 slave.cpp:2078] Sending acknowledgement for status update TASK_RUNNING (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 to executor(1)@67.195.138.9:35102 I0505 00:23:10.271390 24453 master.cpp:2450] Status update TASK_RUNNING (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 from slave 20140505-002308-160088899-37909-24266-1 at slave(51)@67.195.138.9:37909 (vesta.apache.org) I0505 00:23:10.271458 24453 sched.cpp:620] Scheduler::statusUpdate took 14432ns I0505 00:23:10.271669 25506 process.cpp:1023] Socket closed while receiving I0505 00:23:10.271704 25498 exec.cpp:338] Executor received status update acknowledgement 1ac72be6-b0db-4d58-9d1a-7bf13de11a35 for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.271924 24454 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.271945 24454 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.298812 24453 hierarchical_allocator_process.hpp:687] Performed allocation for 2 slaves in 43928ns I0505 00:23:10.422714 24450 slave.cpp:1540] Status update manager successfully handled status update acknowledgement (UUID: 1ac72be6-b0db-4d58-9d1a-7bf13de11a35) for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.422968 24266 slave.cpp:416] Slave terminating I0505 00:23:10.423104 24450 master.cpp:690] Slave 20140505-002308-160088899-37909-24266-0 at slave(50)@67.195.138.9:37909 (vesta.apache.org) disconnected I0505 00:23:10.423132 24450 master.cpp:1262] Disconnecting slave 20140505-002308-160088899-37909-24266-0 I0505 00:23:10.423249 24454 hierarchical_allocator_process.hpp:483] Slave 20140505-002308-160088899-37909-24266-0 disconnected I0505 00:23:10.423838 24266 slave.cpp:416] Slave terminating I0505 00:23:10.423907 24453 master.cpp:690] Slave 20140505-002308-160088899-37909-24266-1 at slave(51)@67.195.138.9:37909 (vesta.apache.org) disconnected I0505 00:23:10.423933 24453 master.cpp:1262] Disconnecting slave 20140505-002308-160088899-37909-24266-1 I0505 00:23:10.424024 24456 hierarchical_allocator_process.hpp:483] Slave 20140505-002308-160088899-37909-24266-1 disconnected I0505 00:23:10.424453 24266 mesos_containerizer.cpp:122] Using isolation: posix/cpu,posix/mem I0505 00:23:10.425937 24455 slave.cpp:140] Slave started on 52)@67.195.138.9:37909 I0505 00:23:10.425968 24455 credentials.hpp:35] Loading credentials for authentication W0505 00:23:10.426074 24455 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveRecoveryTest_0_MultipleSlaves_wg2szi/credential': No such file or directory I0505 00:23:10.426100 24455 slave.cpp:231] Slave using credential for: test-principal I0505 00:23:10.426239 24266 mesos_containerizer.cpp:122] Using isolation: posix/cpu,posix/mem I0505 00:23:10.426228 24455 slave.cpp:244] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0505 00:23:10.426309 24455 slave.cpp:272] Slave hostname: vesta.apache.org I0505 00:23:10.426326 24455 slave.cpp:273] Slave checkpoint: true I0505 00:23:10.426879 24456 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_wg2szi/meta' I0505 00:23:10.428024 24456 slave.cpp:140] Slave started on 53)@67.195.138.9:37909 I0505 00:23:10.428035 24456 credentials.hpp:35] Loading credentials for authentication W0505 00:23:10.428078 24456 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/credential': No such file or directory I0505 00:23:10.428098 24456 slave.cpp:231] Slave using credential for: test-principal I0505 00:23:10.428185 24456 slave.cpp:244] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0505 00:23:10.428226 24456 slave.cpp:272] Slave hostname: vesta.apache.org I0505 00:23:10.428233 24456 slave.cpp:273] Slave checkpoint: true I0505 00:23:10.428561 24451 slave.cpp:3014] Recovering framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.428632 24451 slave.cpp:3249] Recovering executor 'b67093e7-ce45-41d1-9ad3-b664594f6ff1' of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.428848 24452 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/meta' I0505 00:23:10.429111 24453 status_update_manager.cpp:193] Recovering status update manager I0505 00:23:10.429124 24453 status_update_manager.cpp:201] Recovering executor 'b67093e7-ce45-41d1-9ad3-b664594f6ff1' of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.429155 24453 status_update_manager.cpp:499] Creating StatusUpdate stream for task b67093e7-ce45-41d1-9ad3-b664594f6ff1 of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.429311 24453 status_update_manager.hpp:306] Replaying status update stream for task b67093e7-ce45-41d1-9ad3-b664594f6ff1 I0505 00:23:10.429317 24451 slave.cpp:488] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleSlaves_wg2szi/slaves/20140505-002308-160088899-37909-24266-0/frameworks/20140505-002308-160088899-37909-24266-0000/executors/b67093e7-ce45-41d1-9ad3-b664594f6ff1/runs/67fa4eaa-e143-4f9f-8230-79ebf19d461b' I0505 00:23:10.429713 24454 mesos_containerizer.cpp:279] Recovering containerizer I0505 00:23:10.429741 24454 mesos_containerizer.cpp:321] Recovering container '67fa4eaa-e143-4f9f-8230-79ebf19d461b' for executor 'b67093e7-ce45-41d1-9ad3-b664594f6ff1' of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.430104 24453 slave.cpp:3014] Recovering framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.430132 24453 slave.cpp:3249] Recovering executor 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.430522 24456 slave.cpp:2887] Sending reconnect request to executor b67093e7-ce45-41d1-9ad3-b664594f6ff1 of framework 20140505-002308-160088899-37909-24266-0000 at executor(1)@67.195.138.9:56161 I0505 00:23:10.430590 24454 status_update_manager.cpp:193] Recovering status update manager I0505 00:23:10.430614 24454 status_update_manager.cpp:201] Recovering executor 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.430642 24454 status_update_manager.cpp:499] Creating StatusUpdate stream for task db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.430778 24453 slave.cpp:488] Successfully attached file '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/slaves/20140505-002308-160088899-37909-24266-1/frameworks/20140505-002308-160088899-37909-24266-0000/executors/db857d58-97a8-4cd8-a42a-9eb62f4583fa/runs/775df9b1-72da-44de-92f2-f87291e20cb7' I0505 00:23:10.430785 24454 status_update_manager.hpp:306] Replaying status update stream for task db857d58-97a8-4cd8-a42a-9eb62f4583fa I0505 00:23:10.430934 25459 process.cpp:1023] Socket closed while receiving I0505 00:23:10.430989 25451 exec.cpp:251] Received reconnect request from slave 20140505-002308-160088899-37909-24266-0 I0505 00:23:10.431207 24455 mesos_containerizer.cpp:279] Recovering containerizer I0505 00:23:10.431246 24455 mesos_containerizer.cpp:321] Recovering container '775df9b1-72da-44de-92f2-f87291e20cb7' for executor 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.431288 24452 slave.cpp:1779] Re-registering executor b67093e7-ce45-41d1-9ad3-b664594f6ff1 of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.431591 25459 process.cpp:1023] Socket closed while receiving I0505 00:23:10.431643 25455 exec.cpp:228] Executor re-registered on slave 20140505-002308-160088899-37909-24266-0 I0505 00:23:10.432095 24456 slave.cpp:2887] Sending reconnect request to executor db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 at executor(1)@67.195.138.9:35102 I0505 00:23:10.432313 25506 process.cpp:1023] Socket closed while receiving I0505 00:23:10.432359 25500 exec.cpp:251] Received reconnect request from slave 20140505-002308-160088899-37909-24266-1 I0505 00:23:10.432539 25455 exec.cpp:240] Executor::reregistered took 49858ns Re-registered executor on vesta.apache.org I0505 00:23:10.432643 24454 slave.cpp:1779] Re-registering executor db857d58-97a8-4cd8-a42a-9eb62f4583fa of framework 20140505-002308-160088899-37909-24266-0000 I0505 00:23:10.432834 25506 process.cpp:1023] Socket closed while receiving I0505 00:23:10.432868 25500 exec.cpp:228] Executor re-registered on slave 20140505-002308-160088899-37909-24266-1 Re-registered executor on vesta.apache.org I0505 00:23:10.433661 25500 exec.cpp:240] Executor::reregistered took 34289ns I0505 00:23:10.458559 24456 slave.cpp:1904] Cleaning up un-reregistered executors I0505 00:23:10.458588 24449 slave.cpp:1904] Cleaning up un-reregistered executors I0505 00:23:10.458596 24450 hierarchical_allocator_process.hpp:687] Performed allocation for 2 slaves in 38569ns I0505 00:23:10.458606 24456 slave.cpp:2946] Finished recovery I0505 00:23:10.458823 24455 monitor.cpp:140] Failed to collect resource usage for container '775df9b1-72da-44de-92f2-f87291e20cb7' for executor 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' of framework '20140505-002308-160088899-37909-24266-0000': Unknown container: 775df9b1-72da-44de-92f2-f87291e20cb7 I0505 00:23:10.458905 24456 slave.cpp:527] New master detected at [email protected]:37909 I0505 00:23:10.458927 24456 slave.cpp:587] Authenticating with master [email protected]:37909 I0505 00:23:10.458974 24456 slave.cpp:560] Detecting new master I0505 00:23:10.458997 24455 status_update_manager.cpp:167] New master detected at [email protected]:37909 I0505 00:23:10.459035 24456 authenticatee.hpp:128] Creating new client SASL connection I0505 00:23:10.458734 24449 slave.cpp:2946] Finished recovery I0505 00:23:10.459127 24453 monitor.cpp:140] Failed to collect resource usage for container '775df9b1-72da-44de-92f2-f87291e20cb7' for executor 'db857d58-97a8-4cd8-a42a-9eb62f4583fa' of framework '20140505-002308-160088899-37909-24266-0000': Unknown container: 775df9b1-72da-44de-92f2-f87291e20cb7 I0505 00:23:10.459245 24454 master.cpp:2798] Authenticating slave(52)@67.195.138.9:37909 I0505 00:23:10.459270 24449 slave.cpp:527] New master detected at [email protected]:37909 I0505 00:23:10.459310 24449 slave.cpp:587] Authenticating with master [email protected]:37909 I0505 00:23:10.459344 24454 status_update_manager.cpp:167] New master detected at [email protected]:37909 I0505 00:23:10.459383 24453 authenticator.hpp:148] Creating new server SASL connection I0505 00:23:10.459398 24454 authenticatee.hpp:128] Creating new client SASL connection I0505 00:23:10.459388 24449 slave.cpp:560] Detecting new master I0505 00:23:10.459461 24455 master.cpp:2798] Authenticating slave(53)@67.195.138.9:37909 I0505 00:23:10.459481 24454 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0505 00:23:10.459498 24454 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0505 00:23:10.459537 24454 authenticator.hpp:148] Creating new server SASL connection I0505 00:23:10.459552 24455 authenticator.hpp:254] Received SASL authentication start I0505 00:23:10.459594 24455 authenticator.hpp:342] Authentication requires more steps I0505 00:23:10.460095 24449 authenticatee.hpp:265] Received SASL authentication step I0505 00:23:10.460119 24454 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0505 00:23:10.460134 24454 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0505 00:23:10.461935 24449 authenticator.hpp:282] Received SASL authentication step I0505 00:23:10.461978 24456 authenticator.hpp:254] Received SASL authentication start I0505 00:23:10.461993 24449 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0505 00:23:10.462005 24449 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0505 00:23:10.462008 24456 authenticator.hpp:342] Authentication requires more steps I0505 00:23:10.462018 24449 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0505 00:23:10.462030 24449 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0505 00:23:10.462036 24456 authenticatee.hpp:265] Received SASL authentication step I0505 00:23:10.462038 24449 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0505 00:23:10.462082 24449 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0505 00:23:10.462087 24456 authenticator.hpp:282] Received SASL authentication step I0505 00:23:10.462097 24449 authenticator.hpp:334] Authentication success I0505 00:23:10.462103 24456 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0505 00:23:10.462116 24456 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0505 00:23:10.462126 24456 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0505 00:23:10.462138 24456 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'vesta.apache.org' server FQDN: 'vesta.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0505 00:23:10.462138 24454 authenticatee.hpp:305] Authentication success I0505 00:23:10.462151 24456 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0505 00:23:10.462165 24456 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0505 00:23:10.462179 24456 authenticator.hpp:334] Authentication success I0505 00:23:10.462218 24454 slave.cpp:644] Successfully authenticated with master [email protected]:37909 I0505 00:23:10.462229 24456 authenticatee.hpp:305] Authentication success I0505 00:23:10.462257 24456 master.cpp:2838] Successfully authenticated slave(53)@67.195.138.9:37909 I0505 00:23:10.462281 24454 slave.cpp:873] Will retry registration in 7.817449361secs if necessary I0505 00:23:10.462399 24456 master.cpp:2192] Queuing up re-registration request from slave(52)@67.195.138.9:37909 because authentication is still in progress I0505 00:23:10.462404 24454 slave.cpp:644] Successfully authenticated with master [email protected]:37909 I0505 00:23:10.462461 24454 slave.cpp:873] Will retry registration in 8.220002736secs if necessary I0505 00:23:10.462551 24456 master.cpp:2838] Successfully authenticated slave(52)@67.195.138.9:37909 W0505 00:23:10.462718 24456 master.cpp:2248] Slave at slave(53)@67.195.138.9:37909 (vesta.apache.org) is being allowed to re-register with an already in use id (20140505-002308-160088899-37909-24266-1) I0505 00:23:10.462771 24455 slave.cpp:727] Re-registered with master [email protected]:37909 I0505 00:23:10.462811 24455 slave.cpp:1481] Updating framework 20140505-002308-160088899-37909-24266-0000 pid to scheduler(39)@67.195.138.9:37909 W0505 00:23:10.462827 24456 master.cpp:2248] Slave at slave(52)@67.195.138.9:37909 (vesta.apache.org) is being allowed to re-register with an already in use id (20140505-002308-160088899-37909-24266-0) I0505 00:23:10.462848 24455 slave.cpp:1489] Checkpointing framework pid 'scheduler(39)@67.195.138.9:37909' to '/tmp/SlaveRecoveryTest_0_MultipleSlaves_YXcdrN/meta/slaves/20140505-002308-160088899-37909-24266-1/frameworks/20140505-002308-160088899-37909-24266-0000/framework.pid' I0505 00:23:10.462892 24453 hierarchical_allocator_process.hpp:497] Slave 20140505-002308-160088899-37909-24266-1 reconnected F0505 00:23:10.462848 24456 protobuf.hpp:110] Check failed: from Attempting to reply without a sender *** Check failure stack trace: *** @ 0x2afb9d0cbb6d google::LogMessage::Fail() @ 0x2afb9d0cdbff google::LogMessage::SendToLog() @ 0x2afb9d0cb75c google::LogMessage::Flush() @ 0x2afb9d0ce46d google::LogMessageFatal::~LogMessageFatal() @ 0x2afb9cc1fbc2 ProtobufProcess<>::reply() @ 0x2afb9cc042c9 mesos::internal::master::Master::reregisterSlave() @ 0x2afb9cc0e9e5 std::tr1::_Function_handler<>::_M_invoke() @ 0x4d15e5 std::tr1::_Function_handler<>::_M_invoke() @ 0x2afb9cfff34c process::ProcessManager::resume() @ 0x2afb9cffff5c process::schedule() @ 0x2afb9e2e1e9a start_thread @ 0x2afb9e5ec3fd (unknown) I0505 00:23:10.541995 25459 process.cpp:1023] Socket closed while receiving I0505 00:23:10.542057 25506 process.cpp:1023] Socket closed while receiving Imake[4]: 0505 00:23:10.542064 25455 exec.cpp:449] Slave exited, but framework has checkpointing enabled. Waiting 15mins to reconnect with slave 20140505-002308-160088899-37909-24266-0 *** [check-local] Aborted I0505 00:23:10.542162 25455 exec.cpp:458] Slave exited ... shutting down I0505 00:23:10.542146 25501 exec.cpp:449] Slave exited, but framework has checkpointing enabled. Waiting 15mins to reconnect with slave 20140505-002308-160088899-37909-24266-1 II0505 00:23:10.542242 25501 exec.cpp:458] Slave exited ... shutting down 0505 00:23:10.542242 25455 exec.cpp:475] Executor::shutdown took 25710ns I0505 00:23:10.542246 25451 exec.cpp:77] Scheduling shutdown of the executor Shutting down Sending SIGTERM to process tree at pid 25460 I0505 00:23:10.542292 25501 exec.cpp:475] Executor::shutdown took 7377ns Shutting down I0505 00:23:10.542317 25500 exec.cpp:77] Scheduling shutdown of the executor Sending SIGTERM to process tree at pid 25507 make[4]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src' make[3]: *** [check-am] Error 2 make[3]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src' make[2]: *** [check] Error 2 make[2]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build/src' make[1]: *** [check-recursive] Error 1 make[1]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.19.0/_build' make: *** [distcheck] Error 1 Killing the following process trees: [ -+- 25507 sh -c sleep 1000 \--- 25508 sleep 1000 ] Build step 'Execute shell' marked build as failure
