See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/2097/changes>
Changes: [niklas] Fixed incorrect invocation of the mesos-executor within test_containerizer.py. ------------------------------------------ [...truncated 47848 lines...] I0429 03:49:12.418946 21196 master.cpp:2795] Authenticating slave(154)@140.211.11.27:59916 I0429 03:49:12.419564 21202 authenticator.hpp:148] Creating new server SASL connection I0429 03:49:12.420109 21204 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0429 03:49:12.420192 21204 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0429 03:49:12.420411 21201 authenticator.hpp:254] Received SASL authentication start I0429 03:49:12.420562 21201 authenticator.hpp:342] Authentication requires more steps I0429 03:49:12.420794 21198 authenticatee.hpp:265] Received SASL authentication step I0429 03:49:12.420892 21202 replica.cpp:643] Replica received learned notice for position 2 I0429 03:49:12.420922 21212 authenticator.hpp:282] Received SASL authentication step I0429 03:49:12.420954 21212 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0429 03:49:12.420965 21212 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0429 03:49:12.420975 21212 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0429 03:49:12.420984 21212 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0429 03:49:12.420992 21212 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0429 03:49:12.420997 21212 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0429 03:49:12.421010 21212 authenticator.hpp:334] Authentication success I0429 03:49:12.421203 21212 master.cpp:2835] Successfully authenticated slave(154)@140.211.11.27:59916 I0429 03:49:12.421190 21201 authenticatee.hpp:305] Authentication success I0429 03:49:12.421788 21199 slave.cpp:642] Successfully authenticated with master [email protected]:59916 I0429 03:49:12.421916 21199 slave.cpp:871] Will retry registration in 7.790278223secs if necessary I0429 03:49:12.422261 21203 registrar.cpp:379] Attempting to update the 'registry' I0429 03:49:12.431365 21202 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 10.448071ms I0429 03:49:12.431431 21202 leveldb.cpp:399] Deleting ~1 keys from leveldb took 35801ns I0429 03:49:12.431445 21202 replica.cpp:664] Persisted action at 2 I0429 03:49:12.431455 21202 replica.cpp:649] Replica learned TRUNCATE action at position 2 I0429 03:49:12.432122 21214 log.cpp:680] Attempting to append 332 bytes to the log I0429 03:49:12.432323 21217 coordinator.cpp:339] Coordinator attempting to write APPEND action at position 3 I0429 03:49:12.434015 21198 replica.cpp:508] Replica received write request for position 3 I0429 03:49:12.447573 21198 leveldb.cpp:341] Persisting action (351 bytes) to leveldb took 13.531767ms I0429 03:49:12.447605 21198 replica.cpp:664] Persisted action at 3 I0429 03:49:12.448128 21199 replica.cpp:643] Replica received learned notice for position 3 I0429 03:49:12.460044 21199 leveldb.cpp:341] Persisting action (353 bytes) to leveldb took 11.890691ms I0429 03:49:12.460077 21199 replica.cpp:664] Persisted action at 3 I0429 03:49:12.460088 21199 replica.cpp:649] Replica learned APPEND action at position 3 I0429 03:49:12.460587 21209 registrar.cpp:427] Successfully updated 'registry' I0429 03:49:12.461027 21214 master.cpp:2169] Admitted slave on hemera.apache.org at slave(154)@140.211.11.27:59916 I0429 03:49:12.461052 21214 master.cpp:3283] Adding slave 20140429-034912-453759884-59916-21175-0 at hemera.apache.org with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0429 03:49:12.461273 21209 log.cpp:699] Attempting to truncate the log to 3 I0429 03:49:12.461421 21197 slave.cpp:675] Registered with master [email protected]:59916; given slave ID 20140429-034912-453759884-59916-21175-0 I0429 03:49:12.461581 21217 coordinator.cpp:339] Coordinator attempting to write TRUNCATE action at position 4 I0429 03:49:12.461601 21197 slave.cpp:688] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/meta/slaves/20140429-034912-453759884-59916-21175-0/slave.info' I0429 03:49:12.461617 21207 hierarchical_allocator_process.hpp:445] Added slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I0429 03:49:12.461690 21207 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140429-034912-453759884-59916-21175-0 to framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:12.461869 21207 hierarchical_allocator_process.hpp:708] Performed allocation for slave 20140429-034912-453759884-59916-21175-0 in 205593ns I0429 03:49:12.462029 21196 master.hpp:586] Adding offer 20140429-034912-453759884-59916-21175-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) I0429 03:49:12.462090 21196 master.cpp:2744] Sending 1 offers to framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:12.462538 21203 sched.cpp:529] Scheduler::resourceOffers took 55574ns I0429 03:49:12.464007 21203 replica.cpp:508] Replica received write request for position 4 I0429 03:49:12.466547 21216 master.hpp:596] Removing offer 20140429-034912-453759884-59916-21175-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) I0429 03:49:12.466619 21216 master.cpp:1806] Processing reply for offers: [ 20140429-034912-453759884-59916-21175-0 ] on slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) for framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:12.466704 21216 master.hpp:558] Adding task d55ded0b-4198-4294-af85-98689084d6ae with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) I0429 03:49:12.466760 21216 master.cpp:2919] Launching task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) I0429 03:49:12.466909 21195 slave.cpp:905] Got assigned task d55ded0b-4198-4294-af85-98689084d6ae for framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:12.467005 21195 slave.cpp:3082] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/meta/slaves/20140429-034912-453759884-59916-21175-0/frameworks/20140429-034912-453759884-59916-21175-0000/framework.info' I0429 03:49:12.468610 21195 slave.cpp:3089] Checkpointing framework pid 'scheduler(139)@140.211.11.27:59916' to '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/meta/slaves/20140429-034912-453759884-59916-21175-0/frameworks/20140429-034912-453759884-59916-21175-0000/framework.pid' I0429 03:49:12.468861 21195 slave.cpp:1015] Launching task d55ded0b-4198-4294-af85-98689084d6ae for framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:12.471102 21195 slave.cpp:3396] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/meta/slaves/20140429-034912-453759884-59916-21175-0/frameworks/20140429-034912-453759884-59916-21175-0000/executors/d55ded0b-4198-4294-af85-98689084d6ae/executor.info' I0429 03:49:12.471571 21195 slave.cpp:3493] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/meta/slaves/20140429-034912-453759884-59916-21175-0/frameworks/20140429-034912-453759884-59916-21175-0000/executors/d55ded0b-4198-4294-af85-98689084d6ae/runs/6d541657-b2f8-46b9-a404-66f09782bef8/tasks/d55ded0b-4198-4294-af85-98689084d6ae/task.info' I0429 03:49:12.471591 21216 mesos_containerizer.cpp:426] Starting container '6d541657-b2f8-46b9-a404-66f09782bef8' for executor 'd55ded0b-4198-4294-af85-98689084d6ae' of framework '20140429-034912-453759884-59916-21175-0000' I0429 03:49:12.471777 21195 slave.cpp:1125] Queuing task 'd55ded0b-4198-4294-af85-98689084d6ae' for executor d55ded0b-4198-4294-af85-98689084d6ae of framework '20140429-034912-453759884-59916-21175-0000 I0429 03:49:12.471974 21195 slave.cpp:486] Successfully attached file '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/slaves/20140429-034912-453759884-59916-21175-0/frameworks/20140429-034912-453759884-59916-21175-0000/executors/d55ded0b-4198-4294-af85-98689084d6ae/runs/6d541657-b2f8-46b9-a404-66f09782bef8' I0429 03:49:12.472273 21218 mesos_containerizer.cpp:568] Fetching URIs for container '6d541657-b2f8-46b9-a404-66f09782bef8' using command '/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/mesos-0.19.0/_build/src/mesos-fetcher' I0429 03:49:12.478873 21203 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 14.672594ms I0429 03:49:12.478993 21203 replica.cpp:664] Persisted action at 4 I0429 03:49:12.482168 21206 replica.cpp:643] Replica received learned notice for position 4 I0429 03:49:12.510131 21206 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 27.916689ms I0429 03:49:12.510279 21206 leveldb.cpp:399] Deleting ~2 keys from leveldb took 53023ns I0429 03:49:12.510315 21206 replica.cpp:664] Persisted action at 4 I0429 03:49:12.510330 21206 replica.cpp:649] Replica learned TRUNCATE action at position 4 I0429 03:49:13.020884 21211 launcher.cpp:117] Forked child with pid '25271' for container '6d541657-b2f8-46b9-a404-66f09782bef8' I0429 03:49:13.021107 21211 mesos_containerizer.cpp:663] Checkpointing executor's forked pid 25271 to '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/meta/slaves/20140429-034912-453759884-59916-21175-0/frameworks/20140429-034912-453759884-59916-21175-0000/executors/d55ded0b-4198-4294-af85-98689084d6ae/runs/6d541657-b2f8-46b9-a404-66f09782bef8/pids/forked.pid' I0429 03:49:13.028185 21207 slave.cpp:2282] Monitoring executor 'd55ded0b-4198-4294-af85-98689084d6ae' of framework '20140429-034912-453759884-59916-21175-0000' in container '6d541657-b2f8-46b9-a404-66f09782bef8' WARNING: Logging before InitGoogleLogging() is written to STDERR I0429 03:49:13.072882 25274 process.cpp:1601] libprocess is initialized on 140.211.11.27:60948 for 24 cpus I0429 03:49:13.074736 25274 exec.cpp:131] Version: 0.19.0 I0429 03:49:13.076459 25289 exec.cpp:181] Executor started at: executor(1)@140.211.11.27:60948 with pid 25274 I0429 03:49:13.077503 21196 slave.cpp:1598] Got registration for executor 'd55ded0b-4198-4294-af85-98689084d6ae' of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.077636 21196 slave.cpp:1683] Checkpointing executor pid 'executor(1)@140.211.11.27:60948' to '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/meta/slaves/20140429-034912-453759884-59916-21175-0/frameworks/20140429-034912-453759884-59916-21175-0000/executors/d55ded0b-4198-4294-af85-98689084d6ae/runs/6d541657-b2f8-46b9-a404-66f09782bef8/pids/libprocess.pid' I0429 03:49:13.079090 21196 slave.cpp:1717] Flushing queued task d55ded0b-4198-4294-af85-98689084d6ae for executor 'd55ded0b-4198-4294-af85-98689084d6ae' of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.079377 25313 process.cpp:1013] Socket closed while receiving I0429 03:49:13.079589 25312 exec.cpp:205] Executor registered on slave 20140429-034912-453759884-59916-21175-0 I0429 03:49:13.079624 25313 process.cpp:1013] Socket closed while receiving Command terminated with signal Terminated (pid: 25248) I0429 03:49:13.081810 25227 exec.cpp:524] Executor sending status update TASK_KILLED (UUID: 6dd56d3e-144c-479f-9071-08721f87eb13) for task 9d2267ad-23d9-4dae-8078-ff405d4f0f01 of framework 20140429-034911-453759884-59916-21175-0000 I0429 03:49:13.081936 25312 exec.cpp:217] Executor::registered took 98945ns Registered executor on hemera.apache.org I0429 03:49:13.082036 25312 exec.cpp:292] Executor asked to run task 'd55ded0b-4198-4294-af85-98689084d6ae' I0429 03:49:13.082093 25312 exec.cpp:301] Executor::launchTask took 39084ns Starting task d55ded0b-4198-4294-af85-98689084d6ae Forked command at 25314 sh -c 'sleep 1000' I0429 03:49:13.085690 25301 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.086534 21205 slave.cpp:1953] Handling status update TASK_RUNNING (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 from executor(1)@140.211.11.27:60948 I0429 03:49:13.087550 21216 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.087579 21216 status_update_manager.cpp:499] Creating StatusUpdate stream for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.087837 21216 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.116039 21216 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 to [email protected]:59916 I0429 03:49:13.116236 21216 slave.cpp:2070] Status update manager successfully handled status update TASK_RUNNING (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.116255 21216 slave.cpp:2076] Sending acknowledgement for status update TASK_RUNNING (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 to executor(1)@140.211.11.27:60948 I0429 03:49:13.116353 21205 master.cpp:2444] Status update TASK_RUNNING (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 from slave(154)@140.211.11.27:59916 I0429 03:49:13.116758 25313 process.cpp:1013] Socket closed while receiving I0429 03:49:13.116883 25312 exec.cpp:338] Executor received status update acknowledgement c7903a09-5599-406b-98b4-8931cd9205c2 for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.117490 21210 sched.cpp:620] Scheduler::statusUpdate took 18380ns I0429 03:49:13.117655 21210 status_update_manager.cpp:398] Received status update acknowledgement (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.117679 21210 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.144670 21210 slave.cpp:1538] Status update manager successfully handled status update acknowledgement (UUID: c7903a09-5599-406b-98b4-8931cd9205c2) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.145786 21175 slave.cpp:414] Slave terminating I0429 03:49:13.146950 21206 master.cpp:689] Slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) disconnected I0429 03:49:13.146970 21206 master.cpp:1263] Disconnecting slave 20140429-034912-453759884-59916-21175-0 I0429 03:49:13.148180 21199 hierarchical_allocator_process.hpp:484] Slave 20140429-034912-453759884-59916-21175-0 disconnected I0429 03:49:13.150634 21175 containerizer.cpp:178] Using isolation: posix/cpu,posix/mem I0429 03:49:13.153769 21203 slave.cpp:140] Slave started on 155)@140.211.11.27:59916 I0429 03:49:13.153789 21203 credentials.hpp:35] Loading credentials for authentication W0429 03:49:13.153862 21203 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveRecoveryTest_0_KillTask_3gOllA/credential': No such file or directory I0429 03:49:13.153887 21203 slave.cpp:231] Slave using credential for: test-principal I0429 03:49:13.153987 21203 slave.cpp:244] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0429 03:49:13.154052 21203 slave.cpp:272] Slave hostname: hemera.apache.org I0429 03:49:13.154062 21203 slave.cpp:273] Slave checkpoint: true I0429 03:49:13.155035 21217 state.cpp:33] Recovering state from '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/meta' I0429 03:49:13.156342 21217 slave.cpp:3011] Recovering framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.156363 21217 slave.cpp:3246] Recovering executor 'd55ded0b-4198-4294-af85-98689084d6ae' of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.157461 21204 status_update_manager.cpp:193] Recovering status update manager I0429 03:49:13.157480 21204 status_update_manager.cpp:201] Recovering executor 'd55ded0b-4198-4294-af85-98689084d6ae' of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.157528 21217 slave.cpp:486] Successfully attached file '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/slaves/20140429-034912-453759884-59916-21175-0/frameworks/20140429-034912-453759884-59916-21175-0000/executors/d55ded0b-4198-4294-af85-98689084d6ae/runs/6d541657-b2f8-46b9-a404-66f09782bef8' I0429 03:49:13.157675 21204 status_update_manager.cpp:499] Creating StatusUpdate stream for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.157938 21204 status_update_manager.hpp:306] Replaying status update stream for task d55ded0b-4198-4294-af85-98689084d6ae I0429 03:49:13.158678 21214 mesos_containerizer.cpp:201] Recovering containerizer I0429 03:49:13.158709 21214 mesos_containerizer.cpp:243] Recovering container '6d541657-b2f8-46b9-a404-66f09782bef8' for executor 'd55ded0b-4198-4294-af85-98689084d6ae' of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.160243 21204 slave.cpp:2884] Sending reconnect request to executor d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 at executor(1)@140.211.11.27:60948 I0429 03:49:13.160760 25313 process.cpp:1013] Socket closed while receiving I0429 03:49:13.160971 25308 exec.cpp:251] Received reconnect request from slave 20140429-034912-453759884-59916-21175-0 I0429 03:49:13.161528 21211 slave.cpp:1777] Re-registering executor d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.161829 25313 process.cpp:1013] Socket closed while receiving I0429 03:49:13.162063 25305 exec.cpp:228] Executor re-registered on slave 20140429-034912-453759884-59916-21175-0 I0429 03:49:13.163965 25305 exec.cpp:240] Executor::reregistered took 44611ns Re-registered executor on hemera.apache.org I0429 03:49:13.174921 21200 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 30255ns I0429 03:49:13.175520 21213 slave.cpp:1902] Cleaning up un-reregistered executors I0429 03:49:13.175616 21213 slave.cpp:2943] Finished recovery I0429 03:49:13.176535 21203 slave.cpp:525] New master detected at [email protected]:59916 I0429 03:49:13.176679 21203 slave.cpp:585] Authenticating with master [email protected]:59916 I0429 03:49:13.176988 21214 status_update_manager.cpp:167] New master detected at [email protected]:59916 I0429 03:49:13.177175 21203 slave.cpp:558] Detecting new master I0429 03:49:13.177584 21198 authenticatee.hpp:128] Creating new client SASL connection I0429 03:49:13.177889 21198 master.cpp:2795] Authenticating slave(155)@140.211.11.27:59916 I0429 03:49:13.178618 21212 authenticator.hpp:148] Creating new server SASL connection I0429 03:49:13.178861 21212 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0429 03:49:13.178884 21212 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0429 03:49:13.178920 21212 authenticator.hpp:254] Received SASL authentication start I0429 03:49:13.179060 21212 authenticator.hpp:342] Authentication requires more steps I0429 03:49:13.179174 21199 authenticatee.hpp:265] Received SASL authentication step I0429 03:49:13.179667 21199 authenticator.hpp:282] Received SASL authentication step I0429 03:49:13.179692 21199 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0429 03:49:13.179702 21199 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0429 03:49:13.179713 21199 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0429 03:49:13.179723 21199 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0429 03:49:13.179730 21199 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0429 03:49:13.179736 21199 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0429 03:49:13.179749 21199 authenticator.hpp:334] Authentication success I0429 03:49:13.179893 21199 authenticatee.hpp:305] Authentication success I0429 03:49:13.179919 21200 master.cpp:2835] Successfully authenticated slave(155)@140.211.11.27:59916 I0429 03:49:13.180794 21199 slave.cpp:642] Successfully authenticated with master [email protected]:59916 I0429 03:49:13.180873 21199 slave.cpp:871] Will retry registration in 8.317393631secs if necessary W0429 03:49:13.181073 21203 master.cpp:2244] Slave at slave(155)@140.211.11.27:59916 (hemera.apache.org) is being allowed to re-register with an already in use id (20140429-034912-453759884-59916-21175-0) I0429 03:49:13.181221 21199 hierarchical_allocator_process.hpp:498] Slave 20140429-034912-453759884-59916-21175-0 reconnected I0429 03:49:13.181834 21218 slave.cpp:725] Re-registered with master [email protected]:59916 I0429 03:49:13.181893 21218 slave.cpp:1479] Updating framework 20140429-034912-453759884-59916-21175-0000 pid to scheduler(139)@140.211.11.27:59916 I0429 03:49:13.181937 21218 slave.cpp:1487] Checkpointing framework pid 'scheduler(139)@140.211.11.27:59916' to '/tmp/SlaveRecoveryTest_0_KillTask_3gOllA/meta/slaves/20140429-034912-453759884-59916-21175-0/frameworks/20140429-034912-453759884-59916-21175-0000/framework.pid' I0429 03:49:13.236105 21197 master.cpp:1912] Asked to kill task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.236167 21197 master.cpp:1995] Telling slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) to kill task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.236215 21197 slave.cpp:1181] Asked to kill task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:13.236685 25313 process.cpp:1013] Socket closed while receiving I0429 03:49:13.236819 25305 exec.cpp:312] Executor asked to kill task 'd55ded0b-4198-4294-af85-98689084d6ae' I0429 03:49:13.236974 25305 exec.cpp:321] Executor::killTask took 136742ns Shutting down Sending SIGTERM to process tree at pid 25314 2014-04-29 03:49:13,250:21175(0x2b5417422700):ZOO_ERROR@handle_socket_error_msg@1697: Socket [127.0.0.1:58850] zk retcode=-4, errno=111(Connection refused): server refused to accept the client Killing the following process trees: [ -+- 25314 sh -c sleep 1000 \--- 25315 sleep 1000 ] I0429 03:49:14.083509 21219 process.cpp:1013] Socket closed while receiving Command terminated with signal Terminated (pid: 25314) I0429 03:49:14.085544 25290 exec.cpp:524] Executor sending status update TASK_KILLED (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.085979 21213 slave.cpp:1953] Handling status update TASK_KILLED (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 from executor(1)@140.211.11.27:60948 I0429 03:49:14.086021 21213 slave.cpp:3444] Terminating task d55ded0b-4198-4294-af85-98689084d6ae I0429 03:49:14.086441 21213 status_update_manager.cpp:320] Received status update TASK_KILLED (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.086520 21213 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_KILLED (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.120295 21213 status_update_manager.cpp:373] Forwarding status update TASK_KILLED (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 to [email protected]:59916 I0429 03:49:14.120491 21213 master.cpp:2444] Status update TASK_KILLED (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 from slave(155)@140.211.11.27:59916 I0429 03:49:14.120626 21197 sched.cpp:620] Scheduler::statusUpdate took 19277ns I0429 03:49:14.120618 21213 master.hpp:576] Removing task d55ded0b-4198-4294-af85-98689084d6ae with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) I0429 03:49:14.120759 21209 slave.cpp:2070] Status update manager successfully handled status update TASK_KILLED (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.120781 21209 slave.cpp:2076] Sending acknowledgement for status update TASK_KILLED (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 to executor(1)@140.211.11.27:60948 I0429 03:49:14.121544 21213 hierarchical_allocator_process.hpp:637] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140429-034912-453759884-59916-21175-0 from framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.121598 21213 status_update_manager.cpp:398] Received status update acknowledgement (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.121618 21213 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_KILLED (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.121672 25313 process.cpp:1013] Socket closed while receiving I0429 03:49:14.121779 25312 exec.cpp:338] Executor received status update acknowledgement e271f0a5-1c56-4838-b858-e2ea800a5245 for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.125710 21209 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140429-034912-453759884-59916-21175-0 to framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.125905 21209 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 233362ns I0429 03:49:14.125969 21203 master.hpp:586] Adding offer 20140429-034912-453759884-59916-21175-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) I0429 03:49:14.126164 21203 master.cpp:2744] Sending 1 offers to framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.127038 21215 sched.cpp:529] Scheduler::resourceOffers took 21143ns I0429 03:49:14.144418 21213 status_update_manager.cpp:530] Cleaning up status update stream for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.144541 21213 slave.cpp:1538] Status update manager successfully handled status update acknowledgement (UUID: e271f0a5-1c56-4838-b858-e2ea800a5245) for task d55ded0b-4198-4294-af85-98689084d6ae of framework 20140429-034912-453759884-59916-21175-0000 I0429 03:49:14.144605 21213 slave.cpp:3468] Completing task d55ded0b-4198-4294-af85-98689084d6ae I0429 03:49:14.176162 21175 master.cpp:551] Master terminating I0429 03:49:14.176210 21218 sched.cpp:731] Stopping framework '20140429-034912-453759884-59916-21175-0000' I0429 03:49:14.176213 21175 master.hpp:596] Removing offer 20140429-034912-453759884-59916-21175-1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140429-034912-453759884-59916-21175-0 (hemera.apache.org) I0429 03:49:14.176730 21214 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 92433ns I0429 03:49:14.177558 21197 slave.cpp:2151] [email protected]:59916 exited W0429 03:49:14.177583 21197 slave.cpp:2154] Master disconnected! Waiting for a new master to be elected I0429 03:49:14.182333 21175 slave.cpp:414] Slave terminating [ OK ] SlaveRecoveryTest/0.KillTask (2029 ms) [----------] 24 tests from SlaveRecoveryTest/0 (54570 ms total) [----------] Global test environment tear-down ../../src/tests/environment.cpp:258: Failure Failed Tests completed with child processes remaining: -+- 21175 /x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/mesos-0.19.0/_build/src/.libs/lt-mesos-tests \-+- 25271 sh -c /x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/mesos-0.19.0/_build/src/mesos-executor \--- 25274 /x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/mesos-0.19.0/_build/src/.libs/lt-mesos-executor [==========] 310 tests from 52 test cases ran. (372581 ms total) [ PASSED ] 310 tests. [ FAILED ] 0 tests, listed below: 0 FAILED TESTS YOU HAVE 1 DISABLED TEST I0429 03:49:14.318917 25313 process.cpp:1013] Socket closed while receiving make[4]: *** [check-local] Error 1 make[4]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/mesos-0.19.0/_build/src' I0429 03:49:14.319124 25295 exec.cpp:449] Slave exited, but framework has checkpointing enabled. Waiting 15mins to reconnect with slave 20140429-034912-453759884-59916-21175-0 I0429 03:49:14.319196 25295 exec.cpp:458] Slave exited ... shutting down I0429 03:49:14.319274 25295 exec.cpp:475] Executor::shutdown took 4822ns I0429 03:49:14.319298 25295 exec.cpp:77] Scheduling shutdown of the executor make[3]: *** [check-am] Error 2 make[3]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/mesos-0.19.0/_build/src' make[2]: *** [check] Error 2 make[2]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/mesos-0.19.0/_build/src' make[1]: *** [check-recursive] Error 1 make[1]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Set-JAVA_HOME/build/mesos-0.19.0/_build' make: *** [distcheck] Error 1 Shutting down Build step 'Execute shell' marked build as failure
