See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/1642/changes>
Changes: [bmahler] Fixed a memory leak in os::read(). ------------------------------------------ [...truncated 3960 lines...] I0925 23:16:27.700311 6029 status_update_manager.cpp:471] Creating StatusUpdate stream for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.700456 6030 slave.cpp:543] New master detected at [email protected]:42794 I0925 23:16:27.700567 6029 status_update_manager.hpp:301] Replaying status update stream for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 I0925 23:16:27.700573 6030 slave.cpp:558] Postponing registration until recovery is complete I0925 23:16:27.700809 6030 slave.cpp:525] Successfully attached file '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_vcx5XN/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/b3dff7b3-6fe1-4835-92e0-3a43d119d0d1/runs/9f43240a-8952-40ff-aabd-ea251dc13d02' I0925 23:16:27.701002 6026 process_isolator.cpp:314] Recovering isolator I0925 23:16:27.701077 6029 status_update_manager.cpp:157] New master detected at [email protected]:42794 I0925 23:16:27.701205 6026 process_isolator.cpp:322] Recovering executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.701724 6030 slave.cpp:2713] Sending reconnect request to executor b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 at executor(1)@67.195.138.8:60535 I0925 23:16:27.702025 6296 exec.cpp:239] Ignoring reconnect message from slave 201309252316-143311683-42794-5995-0 because the driver is aborted! I0925 23:16:27.702101 6300 process.cpp:986] Socket closed while receiving I0925 23:16:27.711990 6025 hierarchical_allocator_process.hpp:687] No resources available to allocate! I0925 23:16:27.712074 6025 hierarchical_allocator_process.hpp:649] Performed allocation for 0 slaves in 110.385us I0925 23:16:27.712098 6032 slave.cpp:1721] Cleaning up un-reregistered executors I0925 23:16:27.712427 6032 slave.cpp:1739] Killing un-reregistered executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.712671 6032 slave.cpp:399] Finished recovery W0925 23:16:27.712941 6025 master.cpp:1130] Slave at slave(22)@67.195.138.8:42794 (minerva.apache.org) is being allowed to re-register with an already in use id (201309252316-143311683-42794-5995-0) I0925 23:16:27.713317 6026 slave.cpp:644] Re-registered with master [email protected]:42794 I0925 23:16:27.713379 6032 hierarchical_allocator_process.hpp:434] Added slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and available) I0925 23:16:27.713556 6032 hierarchical_allocator_process.hpp:669] Performed allocation for slave 201309252316-143311683-42794-5995-0 in 16.947us I0925 23:16:27.713467 6026 slave.cpp:1332] Updating framework 201309252316-143311683-42794-5995-0000 pid to scheduler(18)@67.195.138.8:42794 I0925 23:16:27.713829 6026 slave.cpp:1340] Checkpointing framework pid 'scheduler(18)@67.195.138.8:42794' to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_vcx5XN/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/framework.pid' Killed the following process trees: [ -+- 6301 sh -c sleep 1000 \--- 6302 sleep 1000 ] I0925 23:16:27.723593 6029 monitor.cpp:187] Publishing resource usage for executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:27.733746 6032 monitor.cpp:187] Publishing resource usage for executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:27.773975 6027 process_isolator.cpp:268] Killed the following process trees: [ -+- 6260 sh -c <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src/mesos-executor> \-+- 6278 <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src/.libs/lt-mesos-executor> \--- 6301 () ] I0925 23:16:27.774683 6033 process.cpp:986] Socket closed while receiving I0925 23:16:27.782383 6032 hierarchical_allocator_process.hpp:649] Performed allocation for 1 slaves in 62.257us W0925 23:16:27.782405 6028 reaper.cpp:124] Cannot get the exit status of process 6260 because it no longer exists I0925 23:16:27.782814 6032 monitor.cpp:193] Failed to collect resource usage for executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework '201309252316-143311683-42794-5995-0000': Unknown/killed executor I0925 23:16:27.783143 6032 monitor.cpp:193] Failed to collect resource usage for executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework '201309252316-143311683-42794-5995-0000': Unknown/killed executor I0925 23:16:27.783195 6030 process_isolator.cpp:479] Telling slave of terminated executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.783371 6028 slave.cpp:2148] Executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework 201309252316-143311683-42794-5995-0000 has terminated with unknown status I0925 23:16:27.784330 6028 slave.cpp:1773] Handling status update TASK_FAILED (UUID: 02cd2a01-4e3f-4e53-af93-706acbfa9095) for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 from @0.0.0.0:0 I0925 23:16:27.784435 6028 slave.cpp:3119] Terminating task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 I0925 23:16:27.784615 6025 process_isolator.cpp:298] Asked to update resources for an unknown/killed executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.784721 6026 status_update_manager.cpp:300] Received status update TASK_FAILED (UUID: 02cd2a01-4e3f-4e53-af93-706acbfa9095) for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.784832 6026 status_update_manager.hpp:337] Checkpointing UPDATE for status update TASK_FAILED (UUID: 02cd2a01-4e3f-4e53-af93-706acbfa9095) for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.785725 6026 status_update_manager.cpp:351] Forwarding status update TASK_FAILED (UUID: 02cd2a01-4e3f-4e53-af93-706acbfa9095) for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 to [email protected]:42794 I0925 23:16:27.786044 6031 slave.cpp:1892] Status update manager successfully handled status update TASK_FAILED (UUID: 02cd2a01-4e3f-4e53-af93-706acbfa9095) for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.786097 6032 master.cpp:1274] Status update TASK_FAILED (UUID: 02cd2a01-4e3f-4e53-af93-706acbfa9095) for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 from slave(22)@67.195.138.8:42794 I0925 23:16:27.786180 6029 sched.cpp:395] Scheduler::statusUpdate took 25.574us I0925 23:16:27.790035 6032 master.hpp:337] Removing task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) I0925 23:16:27.790410 6031 hierarchical_allocator_process.hpp:598] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 201309252316-143311683-42794-5995-0 from framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.790542 6030 status_update_manager.cpp:375] Received status update acknowledgement (UUID: 02cd2a01-4e3f-4e53-af93-706acbfa9095) for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.790644 6030 status_update_manager.hpp:337] Checkpointing ACK for status update TASK_FAILED (UUID: 02cd2a01-4e3f-4e53-af93-706acbfa9095) for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.791246 6030 status_update_manager.cpp:502] Cleaning up status update stream for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.791476 6025 slave.cpp:1386] Status update manager successfully handled status update acknowledgement (UUID: 02cd2a01-4e3f-4e53-af93-706acbfa9095) for task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.797886 6025 slave.cpp:3142] Completing task b3dff7b3-6fe1-4835-92e0-3a43d119d0d1 I0925 23:16:27.798022 6025 slave.cpp:2285] Cleaning up executor 'b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.798316 6032 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_vcx5XN/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/b3dff7b3-6fe1-4835-92e0-3a43d119d0d1/runs/9f43240a-8952-40ff-aabd-ea251dc13d02' for gc I0925 23:16:27.798470 6025 slave.cpp:2357] Cleaning up framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.798555 6032 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_vcx5XN/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' for gc I0925 23:16:27.798635 6030 status_update_manager.cpp:262] Closing status update streams for framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.798799 6032 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_vcx5XN/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/b3dff7b3-6fe1-4835-92e0-3a43d119d0d1/runs/9f43240a-8952-40ff-aabd-ea251dc13d02' for gc I0925 23:16:27.799033 6032 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_vcx5XN/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/b3dff7b3-6fe1-4835-92e0-3a43d119d0d1' for gc I0925 23:16:27.799185 6032 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_vcx5XN/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000' for gc I0925 23:16:27.799371 6032 gc.cpp:56] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_vcx5XN/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000' for gc I0925 23:16:27.802307 6026 sched.cpp:498] Stopping framework '201309252316-143311683-42794-5995-0000' I0925 23:16:27.802357 5995 master.cpp:481] Master terminating I0925 23:16:27.802589 5995 master.cpp:206] Shutting down master I0925 23:16:27.802623 6032 slave.cpp:1973] [email protected]:42794 exited I0925 23:16:27.802745 5995 master.cpp:237] Removing slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) W0925 23:16:27.802813 6032 slave.cpp:1976] Master disconnected! Waiting for a new master to be elected I0925 23:16:27.803272 5995 slave.cpp:454] Slave terminating [ OK ] SlaveRecoveryTest/0.RecoverTerminatedExecutor (198 ms) [ RUN ] SlaveRecoveryTest/0.RecoveryTimeout I0925 23:16:27.805270 6025 master.cpp:265] Master started on 67.195.138.8:42794 I0925 23:16:27.805291 6029 slave.cpp:108] Slave started on 23)@67.195.138.8:42794 I0925 23:16:27.805388 6025 master.cpp:280] Master ID: 201309252316-143311683-42794-5995 I0925 23:16:27.805436 6026 sched.cpp:178] New master at [email protected]:42794 I0925 23:16:27.805577 6029 slave.cpp:208] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0925 23:16:27.806046 6025 master.cpp:644] Elected as master! I0925 23:16:27.805783 6026 hierarchical_allocator_process.hpp:291] Initializing hierarchical allocator process with master : [email protected]:42794 I0925 23:16:27.805783 6028 master.cpp:80] No whitelist given. Advertising offers for all slaves I0925 23:16:27.806308 6025 master.cpp:694] Registering framework 201309252316-143311683-42794-5995-0000 at scheduler(19)@67.195.138.8:42794 I0925 23:16:27.806449 6026 process_isolator.cpp:314] Recovering isolator I0925 23:16:27.806720 6025 hierarchical_allocator_process.hpp:321] Added framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.806844 6025 hierarchical_allocator_process.hpp:687] No resources available to allocate! I0925 23:16:27.806767 6030 sched.cpp:237] Framework registered with 201309252316-143311683-42794-5995-0000 I0925 23:16:27.806468 6029 slave.cpp:543] New master detected at [email protected]:42794 I0925 23:16:27.806932 6025 hierarchical_allocator_process.hpp:649] Performed allocation for 0 slaves in 88.622us I0925 23:16:27.807173 6026 status_update_manager.cpp:157] New master detected at [email protected]:42794 I0925 23:16:27.807152 6029 slave.cpp:558] Postponing registration until recovery is complete I0925 23:16:27.807036 6030 sched.cpp:251] Scheduler::registered took 13.247us I0925 23:16:27.807394 6029 slave.cpp:399] Finished recovery I0925 23:16:27.807718 6031 master.cpp:1075] Attempting to register slave on minerva.apache.org at slave(23)@67.195.138.8:42794 I0925 23:16:27.807812 6031 master.cpp:2165] Adding slave 201309252316-143311683-42794-5995-0 at minerva.apache.org with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0925 23:16:27.808019 6032 slave.cpp:603] Registered with master [email protected]:42794; given slave ID 201309252316-143311683-42794-5995-0 I0925 23:16:27.808066 6029 hierarchical_allocator_process.hpp:434] Added slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I0925 23:16:27.808292 6029 hierarchical_allocator_process.hpp:712] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201309252316-143311683-42794-5995-0 to framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.808421 6032 slave.cpp:616] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/meta/slaves/201309252316-143311683-42794-5995-0/slave.info' I0925 23:16:27.808536 6029 hierarchical_allocator_process.hpp:669] Performed allocation for slave 201309252316-143311683-42794-5995-0 in 265.416us I0925 23:16:27.808573 6031 master.hpp:347] Adding offer 201309252316-143311683-42794-5995-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) I0925 23:16:27.808749 6031 master.cpp:1462] Sending 1 offers to framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.808958 6026 sched.cpp:340] Scheduler::resourceOffers took 26.918us I0925 23:16:27.810180 6027 master.cpp:1699] Processing reply for offer 201309252316-143311683-42794-5995-0 on slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) for framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.810365 6027 master.hpp:321] Adding task d2227ca8-ab64-4f0b-8761-28de4801a098 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) I0925 23:16:27.810510 6027 master.cpp:1823] Launching task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) I0925 23:16:27.810688 6031 slave.cpp:772] Got assigned task d2227ca8-ab64-4f0b-8761-28de4801a098 for framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.810731 6027 master.hpp:357] Removing offer 201309252316-143311683-42794-5995-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) I0925 23:16:27.810902 6031 slave.cpp:2824] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/framework.info' I0925 23:16:27.811139 6031 slave.cpp:2831] Checkpointing framework pid 'scheduler(19)@67.195.138.8:42794' to '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/framework.pid' I0925 23:16:27.811439 6031 slave.cpp:883] Launching task d2227ca8-ab64-4f0b-8761-28de4801a098 for framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.812530 6031 slave.cpp:3074] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/d2227ca8-ab64-4f0b-8761-28de4801a098/executor.info' I0925 23:16:27.812968 6031 slave.cpp:3163] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/d2227ca8-ab64-4f0b-8761-28de4801a098/runs/1bc37b05-f3ee-49ad-a571-4d0c730dd1ed/tasks/d2227ca8-ab64-4f0b-8761-28de4801a098/task.info' I0925 23:16:27.813010 6028 process_isolator.cpp:100] Launching d2227ca8-ab64-4f0b-8761-28de4801a098 (<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src/mesos-executor)> in /tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/d2227ca8-ab64-4f0b-8761-28de4801a098/runs/1bc37b05-f3ee-49ad-a571-4d0c730dd1ed with resources ' for framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.813211 6031 slave.cpp:994] Queuing task 'd2227ca8-ab64-4f0b-8761-28de4801a098' for executor d2227ca8-ab64-4f0b-8761-28de4801a098 of framework '201309252316-143311683-42794-5995-0000 I0925 23:16:27.813982 6031 slave.cpp:525] Successfully attached file '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/d2227ca8-ab64-4f0b-8761-28de4801a098/runs/1bc37b05-f3ee-49ad-a571-4d0c730dd1ed' I0925 23:16:27.814384 6028 process_isolator.cpp:163] Forked executor at 6303 Checkpointing executor's forked pid 6303 to '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/d2227ca8-ab64-4f0b-8761-28de4801a098/runs/1bc37b05-f3ee-49ad-a571-4d0c730dd1ed/pids/forked.pid' Fetching resources into '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/d2227ca8-ab64-4f0b-8761-28de4801a098/runs/1bc37b05-f3ee-49ad-a571-4d0c730dd1ed' WARNING: Logging before InitGoogleLogging() is written to STDERR I0925 23:16:27.862565 6321 process.cpp:1555] libprocess is initialized on 67.195.138.8:58600 for 8 cpus I0925 23:16:27.864779 6342 exec.cpp:174] Executor started at: executor(1)@67.195.138.8:58600 with pid 6321 I0925 23:16:27.865298 6028 slave.cpp:1440] Got registration for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.865545 6028 slave.cpp:1525] Checkpointing executor pid 'executor(1)@67.195.138.8:58600' to '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/d2227ca8-ab64-4f0b-8761-28de4801a098/runs/1bc37b05-f3ee-49ad-a571-4d0c730dd1ed/pids/libprocess.pid' I0925 23:16:27.866010 6028 slave.cpp:1561] Flushing queued task d2227ca8-ab64-4f0b-8761-28de4801a098 for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.866359 6337 exec.cpp:198] Executor registered on slave 201309252316-143311683-42794-5995-0 Registered executor on minerva.apache.org I0925 23:16:27.867207 6337 exec.cpp:210] Executor::registered took 81.38us I0925 23:16:27.867262 6343 process.cpp:986] Socket closed while receiving I0925 23:16:27.867389 6343 process.cpp:986] Socket closed while receiving I0925 23:16:27.867446 6341 exec.cpp:285] Executor asked to run task 'd2227ca8-ab64-4f0b-8761-28de4801a098' Starting task d2227ca8-ab64-4f0b-8761-28de4801a098 I0925 23:16:27.867514 6341 exec.cpp:294] Executor::launchTask took 46.312us sh -c 'sleep 1000' Forked command at 6344 I0925 23:16:27.869130 6338 exec.cpp:501] Executor sending status update TASK_RUNNING (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.869521 6032 slave.cpp:1773] Handling status update TASK_RUNNING (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 from executor(1)@67.195.138.8:58600 I0925 23:16:27.869897 6027 status_update_manager.cpp:300] Received status update TASK_RUNNING (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.870254 6027 status_update_manager.cpp:471] Creating StatusUpdate stream for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.871158 6027 status_update_manager.hpp:337] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.872720 6027 status_update_manager.cpp:351] Forwarding status update TASK_RUNNING (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 to [email protected]:42794 I0925 23:16:27.872931 6032 master.cpp:1274] Status update TASK_RUNNING (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 from slave(23)@67.195.138.8:42794 I0925 23:16:27.872969 6030 slave.cpp:1892] Status update manager successfully handled status update TASK_RUNNING (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.873091 6028 sched.cpp:395] Scheduler::statusUpdate took 33.655us I0925 23:16:27.877900 6030 slave.cpp:1898] Sending acknowledgement for status update TASK_RUNNING (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 to executor(1)@67.195.138.8:58600 I0925 23:16:27.878427 6343 process.cpp:986] Socket closed while receiving I0925 23:16:27.878451 6337 exec.cpp:331] Executor received status update acknowledgement 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.878480 6027 status_update_manager.cpp:375] Received status update acknowledgement (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.878562 6027 status_update_manager.hpp:337] Checkpointing ACK for status update TASK_RUNNING (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.879503 6029 slave.cpp:1386] Status update manager successfully handled status update acknowledgement (UUID: 4ae97359-35da-4f08-a3a3-ea2d75ee7cbd) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.879739 6029 slave.cpp:454] Slave terminating I0925 23:16:27.885977 6030 master.cpp:553] Slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) disconnected I0925 23:16:27.889822 6030 hierarchical_allocator_process.hpp:459] Removed slave 201309252316-143311683-42794-5995-0 I0925 23:16:27.891501 6026 slave.cpp:108] Slave started on 24)@67.195.138.8:42794 I0925 23:16:27.891679 6026 slave.cpp:208] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0925 23:16:27.892287 6026 state.cpp:33] Recovering state from /tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/meta I0925 23:16:27.893425 6026 slave.cpp:2763] Recovering framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.893520 6026 slave.cpp:2939] Recovering executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.894107 6032 status_update_manager.cpp:179] Recovering status update manager I0925 23:16:27.894178 6032 status_update_manager.cpp:183] Recovering executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.894295 6032 status_update_manager.cpp:471] Creating StatusUpdate stream for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.894505 6032 status_update_manager.hpp:301] Replaying status update stream for task d2227ca8-ab64-4f0b-8761-28de4801a098 I0925 23:16:27.894541 6026 slave.cpp:543] New master detected at [email protected]:42794 I0925 23:16:27.894644 6026 slave.cpp:558] Postponing registration until recovery is complete I0925 23:16:27.894767 6026 slave.cpp:525] Successfully attached file '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/executors/d2227ca8-ab64-4f0b-8761-28de4801a098/runs/1bc37b05-f3ee-49ad-a571-4d0c730dd1ed' I0925 23:16:27.894830 6032 status_update_manager.cpp:157] New master detected at [email protected]:42794 I0925 23:16:27.894886 6031 process_isolator.cpp:314] Recovering isolator I0925 23:16:27.895151 6031 process_isolator.cpp:322] Recovering executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.895669 6028 slave.cpp:2713] Sending reconnect request to executor d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 at executor(1)@67.195.138.8:58600 I0925 23:16:27.895998 6343 process.cpp:986] Socket closed while receiving I0925 23:16:27.896023 6342 exec.cpp:244] Received reconnect request from slave 201309252316-143311683-42794-5995-0 I0925 23:16:27.895933 6026 hierarchical_allocator_process.hpp:687] No resources available to allocate! I0925 23:16:27.896082 6026 hierarchical_allocator_process.hpp:649] Performed allocation for 0 slaves in 158.688us I0925 23:16:27.896301 6028 slave.cpp:1605] Re-registering executor d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:27.896550 6343 process.cpp:986] Socket closed while receiving I0925 23:16:27.896610 6341 exec.cpp:221] Executor re-registered on slave 201309252316-143311683-42794-5995-0 I0925 23:16:27.896580 6028 slave.cpp:1721] Cleaning up un-reregistered executors I0925 23:16:27.896703 6028 slave.cpp:399] Finished recovery W0925 23:16:27.896994 6026 master.cpp:1130] Slave at slave(24)@67.195.138.8:42794 (minerva.apache.org) is being allowed to re-register with an already in use id (201309252316-143311683-42794-5995-0) I0925 23:16:27.897353 6026 slave.cpp:644] Re-registered with master [email protected]:42794 I0925 23:16:27.897436 6026 slave.cpp:1332] Updating framework 201309252316-143311683-42794-5995-0000 pid to scheduler(19)@67.195.138.8:42794 Re-registered executor on minerva.apache.org I0925 23:16:27.897596 6341 exec.cpp:233] Executor::reregistered took 48.053us I0925 23:16:27.897436 6028 hierarchical_allocator_process.hpp:434] Added slave 201309252316-143311683-42794-5995-0 (minerva.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and available) I0925 23:16:27.897539 6026 slave.cpp:1340] Checkpointing framework pid 'scheduler(19)@67.195.138.8:42794' to '/tmp/SlaveRecoveryTest_0_RecoveryTimeout_vmwbQ3/meta/slaves/201309252316-143311683-42794-5995-0/frameworks/201309252316-143311683-42794-5995-0000/framework.pid' I0925 23:16:27.897706 6028 hierarchical_allocator_process.hpp:669] Performed allocation for slave 201309252316-143311683-42794-5995-0 in 32.74us I0925 23:16:27.907949 6030 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' Command terminated with signal Killed (pid: 6131) I0925 23:16:28.238515 6126 exec.cpp:501] Executor sending status update TASK_KILLED (UUID: 6a30173f-2d28-4ece-80b7-f0d88ab94609) for task c1f31cca-c6b0-4180-9020-4644a6657467 of framework 201309252316-143311683-42794-5995-0000 Command terminated with signal Killed (pid: 6174) I0925 23:16:28.360436 6169 exec.cpp:501] Executor sending status update TASK_KILLED (UUID: 7fd4aa65-cfd4-45c6-a8e5-1a6df05f8fc2) for task 5431b30d-ba8b-4d67-8454-1ed269eb8bce of framework 201309252316-143311683-42794-5995-0000 Command terminated with signal Killed (pid: 6217) I0925 23:16:28.442690 6210 exec.cpp:501] Executor sending status update TASK_KILLED (UUID: b742d33e-9d8f-421a-9c1a-ff0026299d05) for task a9d23ba0-3efa-4563-ad26-1888b7dd9d06 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:29.238997 6033 process.cpp:986] Socket closed while receiving I0925 23:16:29.361115 6033 process.cpp:986] Socket closed while receiving I0925 23:16:29.443315 6033 process.cpp:986] Socket closed while receiving I0925 23:16:30.892246 6029 hierarchical_allocator_process.hpp:649] Performed allocation for 1 slaves in 45.488us I0925 23:16:30.902858 6031 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:30.912642 6032 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:31.893432 6028 hierarchical_allocator_process.hpp:649] Performed allocation for 1 slaves in 31.514us I0925 23:16:31.913799 6032 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:31.923959 6032 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:32.806610 6032 master.cpp:80] No whitelist given. Advertising offers for all slaves I0925 23:16:32.893817 6028 hierarchical_allocator_process.hpp:649] Performed allocation for 1 slaves in 48.956us I0925 23:16:32.925102 6025 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:32.934659 6026 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:33.895143 6030 hierarchical_allocator_process.hpp:649] Performed allocation for 1 slaves in 21.454us I0925 23:16:33.937275 6032 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:33.947093 6029 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:34.896559 6029 hierarchical_allocator_process.hpp:649] Performed allocation for 1 slaves in 65.056us I0925 23:16:34.948992 6030 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:34.958528 6028 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:35.896796 6029 hierarchical_allocator_process.hpp:649] Performed allocation for 1 slaves in 15.467us I0925 23:16:35.960388 6029 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:35.970412 6030 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:36.897151 6031 hierarchical_allocator_process.hpp:649] Performed allocation for 1 slaves in 31.952us I0925 23:16:36.970964 6028 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:36.981082 6025 monitor.cpp:187] Publishing resource usage for executor 'd2227ca8-ab64-4f0b-8761-28de4801a098' of framework '201309252316-143311683-42794-5995-0000' I0925 23:16:37.807829 6032 master.cpp:80] No whitelist given. Advertising offers for all slaves I0925 23:16:37.898411 6030 hierarchical_allocator_process.hpp:649] Performed allocation for 1 slaves in 25.216us ../../src/tests/slave_recovery_tests.cpp:776: Failure Failed to wait 10secs for status I0925 23:16:37.973279 6343 process.cpp:986] Socket closed while receiving make[3]: *** [check-local] Segmentation fault I0925 23:16:37.973366 6342 exec.cpp:431] Slave exited, but framework has checkpointing enabled. Waiting 1ms to reconnect with slave 201309252316-143311683-42794-5995-0 I0925 23:16:37.973422 6342 exec.cpp:440] Slave exited ... shutting down I0925 23:16:37.973464 6342 exec.cpp:457] Executor::shutdown took 4.33us I0925 23:16:37.973481 6342 exec.cpp:76] Scheduling shutdown of the executor Shutting down Killing process tree at pid 6344 make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'> I0925 23:16:37.974545 6339 exec.cpp:412] Recovery timeout of 1ms exceeded; Shutting down I0925 23:16:37.974570 6339 exec.cpp:367] Ignoring shutdown message because the driver is aborted! make[2]: *** [check-am] Error 2 make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'> make[1]: *** [check] Error 2 make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src'> make: *** [check-recursive] Error 1 Killed the following process trees: [ -+- 6344 sh -c sleep 1000 \--- 6345 sleep 1000 ] Command terminated with signal Killed (pid: 6344) I0925 23:16:38.867609 6335 exec.cpp:501] Executor sending status update TASK_KILLED (UUID: 5bd7bd75-d21a-4381-850e-bf7e0f3ec868) for task d2227ca8-ab64-4f0b-8761-28de4801a098 of framework 201309252316-143311683-42794-5995-0000 I0925 23:16:38.867795 6343 process.cpp:1159] Socket error while connecting Build step 'Execute shell' marked build as failure
