See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2120/changes>
Changes: [idownes] ProcTest.MultipleThreads waits for /proc to update. [bmahler] Ported some of the slave statistics to the new metrics library. ------------------------------------------ [...truncated 43415 lines...] I0509 21:21:13.000779 11455 hierarchical_allocator_process.hpp:687] Performed allocation for 0 slaves in 5747ns I0509 21:21:13.001163 11459 authenticatee.hpp:265] Received SASL authentication step I0509 21:21:13.001210 11459 authenticator.hpp:282] Received SASL authentication step I0509 21:21:13.001234 11459 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 I0509 21:21:13.001240 11459 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0509 21:21:13.001250 11459 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0509 21:21:13.001260 11459 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 I0509 21:21:13.001266 11459 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0509 21:21:13.001271 11459 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0509 21:21:13.001282 11459 authenticator.hpp:334] Authentication success I0509 21:21:13.001322 11456 authenticatee.hpp:305] Authentication success I0509 21:21:13.001337 11459 master.cpp:2838] Successfully authenticated slave(159)@67.195.138.9:33285 I0509 21:21:13.001389 11456 slave.cpp:644] Successfully authenticated with master [email protected]:33285 I0509 21:21:13.001426 11456 slave.cpp:873] Will retry registration in 9.179380694secs if necessary I0509 21:21:13.001523 11459 master.cpp:2134] Registering slave at slave(159)@67.195.138.9:33285 (vesta.apache.org) with id 20140509-212112-160088899-33285-11408-0 I0509 21:21:13.001657 11460 registrar.cpp:422] Attempting to update the 'registry' I0509 21:21:13.003172 11453 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 3.75055ms I0509 21:21:13.003219 11453 leveldb.cpp:399] Deleting ~1 keys from leveldb took 29045ns I0509 21:21:13.003231 11453 replica.cpp:676] Persisted action at 2 I0509 21:21:13.003239 11453 replica.cpp:661] Replica learned TRUNCATE action at position 2 I0509 21:21:13.003479 11459 log.cpp:680] Attempting to append 327 bytes to the log I0509 21:21:13.003522 11453 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I0509 21:21:13.003916 11457 replica.cpp:508] Replica received write request for position 3 I0509 21:21:13.047323 11457 leveldb.cpp:341] Persisting action (346 bytes) to leveldb took 43.35886ms I0509 21:21:13.047381 11457 replica.cpp:676] Persisted action at 3 I0509 21:21:13.047696 11458 replica.cpp:655] Replica received learned notice for position 3 I0509 21:21:13.054939 11458 leveldb.cpp:341] Persisting action (348 bytes) to leveldb took 7.221578ms I0509 21:21:13.054958 11458 replica.cpp:676] Persisted action at 3 I0509 21:21:13.054968 11458 replica.cpp:661] Replica learned APPEND action at position 3 I0509 21:21:13.055212 11458 registrar.cpp:479] Successfully updated 'registry' I0509 21:21:13.055311 11459 master.cpp:2174] Registered slave 20140509-212112-160088899-33285-11408-0 at slave(159)@67.195.138.9:33285 (vesta.apache.org) I0509 21:21:13.055323 11459 master.cpp:3283] Adding slave 20140509-212112-160088899-33285-11408-0 at slave(159)@67.195.138.9:33285 (vesta.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0509 21:21:13.055388 11453 slave.cpp:677] Registered with master [email protected]:33285; given slave ID 20140509-212112-160088899-33285-11408-0 I0509 21:21:13.055449 11453 hierarchical_allocator_process.hpp:444] Added slave 20140509-212112-160088899-33285-11408-0 (vesta.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I0509 21:21:13.055496 11453 hierarchical_allocator_process.hpp:751] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212112-160088899-33285-11408-0 to framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.055609 11453 hierarchical_allocator_process.hpp:707] Performed allocation for slave 20140509-212112-160088899-33285-11408-0 in 134410ns I0509 21:21:13.055655 11459 master.hpp:612] Adding offer 20140509-212112-160088899-33285-11408-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212112-160088899-33285-11408-0 (vesta.apache.org) I0509 21:21:13.055682 11458 log.cpp:699] Attempting to truncate the log to 3 I0509 21:21:13.055701 11459 master.cpp:2747] Sending 1 offers to framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.055743 11457 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I0509 21:21:13.055883 11459 sched.cpp:529] Scheduler::resourceOffers took 99102ns I0509 21:21:13.056046 11459 replica.cpp:508] Replica received write request for position 4 I0509 21:21:13.056512 11460 master.hpp:622] Removing offer 20140509-212112-160088899-33285-11408-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212112-160088899-33285-11408-0 (vesta.apache.org) I0509 21:21:13.056577 11460 master.cpp:1810] Processing reply for offers: [ 20140509-212112-160088899-33285-11408-0 ] on slave 20140509-212112-160088899-33285-11408-0 at slave(159)@67.195.138.9:33285 (vesta.apache.org) for framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.056673 11460 master.hpp:584] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212112-160088899-33285-11408-0 (vesta.apache.org) I0509 21:21:13.056721 11460 master.cpp:2922] Launching task 1 of framework 20140509-212112-160088899-33285-11408-0000 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212112-160088899-33285-11408-0 at slave(159)@67.195.138.9:33285 (vesta.apache.org) I0509 21:21:13.056848 11460 slave.cpp:907] Got assigned task 1 for framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.057086 11460 slave.cpp:1017] Launching task 1 for framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.058923 11459 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 2.856661ms I0509 21:21:13.058944 11459 replica.cpp:676] Persisted action at 4 I0509 21:21:13.059159 11458 replica.cpp:655] Replica received learned notice for position 4 I0509 21:21:13.062906 11458 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 3.731463ms I0509 21:21:13.062939 11458 leveldb.cpp:399] Deleting ~2 keys from leveldb took 12868ns I0509 21:21:13.062947 11458 replica.cpp:676] Persisted action at 4 I0509 21:21:13.062955 11458 replica.cpp:661] Replica learned TRUNCATE action at position 4 I0509 21:21:13.063191 11460 slave.cpp:1127] Queuing task '1' for executor 1 of framework '20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.063190 11455 mesos_containerizer.cpp:523] Starting container '3ef617c7-244c-43cf-9bd1-d0822f4ab738' for executor '1' of framework '20140509-212112-160088899-33285-11408-0000' I0509 21:21:13.063243 11460 slave.cpp:488] Successfully attached file '/tmp/SlaveTest_ShutdownUnregisteredExecutor_e2Vv2U/slaves/20140509-212112-160088899-33285-11408-0/frameworks/20140509-212112-160088899-33285-11408-0000/executors/1/runs/3ef617c7-244c-43cf-9bd1-d0822f4ab738' I0509 21:21:13.064520 11455 launcher.cpp:117] Forked child with pid '13437' for container '3ef617c7-244c-43cf-9bd1-d0822f4ab738' I0509 21:21:13.065605 11460 mesos_containerizer.cpp:623] Fetching URIs for container '3ef617c7-244c-43cf-9bd1-d0822f4ab738' using command '/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher' Command terminated with signal Terminated (pid: 13435) I0509 21:21:13.352846 13429 exec.cpp:524] Executor sending status update TASK_KILLED (UUID: d58b92ae-f981-420d-915b-066d58fb21a5) for task b1cfcb14-dbd1-417a-b991-5fa6feeecb52 of framework 20140509-212111-160088899-33285-11408-0000 I0509 21:21:13.482365 11455 slave.cpp:2299] Monitoring executor '1' of framework '20140509-212112-160088899-33285-11408-0000' in container '3ef617c7-244c-43cf-9bd1-d0822f4ab738' I0509 21:21:13.517626 11453 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 57598ns I0509 21:21:13.517762 11460 master.cpp:104] No whitelist given. Advertising offers for all slaves I0509 21:21:13.518221 11453 slave.cpp:2774] Terminating executor 1 of framework 20140509-212112-160088899-33285-11408-0000 because it did not register within 1mins I0509 21:21:13.518393 11453 slave.cpp:2817] Current usage 40.87%. Max allowed age: 3.438909898593472days I0509 21:21:13.518446 11453 mesos_containerizer.cpp:934] Destroying container '3ef617c7-244c-43cf-9bd1-d0822f4ab738' I0509 21:21:13.547793 11461 process.cpp:1037] Socket closed while receiving I0509 21:21:13.557473 11458 mesos_containerizer.cpp:1050] Executor for container '3ef617c7-244c-43cf-9bd1-d0822f4ab738' has exited I0509 21:21:13.558019 11460 hierarchical_allocator_process.hpp:687] Performed allocation for 1 slaves in 49359ns I0509 21:21:13.566515 11455 slave.cpp:2357] Executor '1' of framework 20140509-212112-160088899-33285-11408-0000 has terminated with signal Killed I0509 21:21:13.567411 11455 slave.cpp:1962] Handling status update TASK_FAILED (UUID: 90eb44f2-c9d2-45ff-aae7-b3a4913a21b8) for task 1 of framework 20140509-212112-160088899-33285-11408-0000 from @0.0.0.0:0 I0509 21:21:13.567436 11455 slave.cpp:3526] Terminating task 1 I0509 21:21:13.567704 11457 status_update_manager.cpp:320] Received status update TASK_FAILED (UUID: 90eb44f2-c9d2-45ff-aae7-b3a4913a21b8) for task 1 of framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.567746 11457 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.567832 11457 status_update_manager.cpp:373] Forwarding status update TASK_FAILED (UUID: 90eb44f2-c9d2-45ff-aae7-b3a4913a21b8) for task 1 of framework 20140509-212112-160088899-33285-11408-0000 to [email protected]:33285 I0509 21:21:13.568083 11458 slave.cpp:2083] Status update manager successfully handled status update TASK_FAILED (UUID: 90eb44f2-c9d2-45ff-aae7-b3a4913a21b8) for task 1 of framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.568099 11456 master.cpp:2450] Status update TASK_FAILED (UUID: 90eb44f2-c9d2-45ff-aae7-b3a4913a21b8) for task 1 of framework 20140509-212112-160088899-33285-11408-0000 from slave 20140509-212112-160088899-33285-11408-0 at slave(159)@67.195.138.9:33285 (vesta.apache.org) I0509 21:21:13.568200 11457 sched.cpp:620] Scheduler::statusUpdate took 18988ns I0509 21:21:13.568199 11456 master.hpp:602] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140509-212112-160088899-33285-11408-0 (vesta.apache.org) I0509 21:21:13.568373 11460 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 90eb44f2-c9d2-45ff-aae7-b3a4913a21b8) for task 1 of framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.568393 11458 hierarchical_allocator_process.hpp:636] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140509-212112-160088899-33285-11408-0 from framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.568409 11460 status_update_manager.cpp:530] Cleaning up status update stream for task 1 of framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.568506 11457 slave.cpp:1547] Status update manager successfully handled status update acknowledgement (UUID: 90eb44f2-c9d2-45ff-aae7-b3a4913a21b8) for task 1 of framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.568528 11457 slave.cpp:3550] Completing task 1 I0509 21:21:13.568539 11457 slave.cpp:2496] Cleaning up executor '1' of framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.568629 11460 gc.cpp:56] Scheduling '/tmp/SlaveTest_ShutdownUnregisteredExecutor_e2Vv2U/slaves/20140509-212112-160088899-33285-11408-0/frameworks/20140509-212112-160088899-33285-11408-0000/executors/1/runs/3ef617c7-244c-43cf-9bd1-d0822f4ab738' for gc 6.99999401708444days in the future I0509 21:21:13.568655 11457 slave.cpp:2571] Cleaning up framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.568713 11458 status_update_manager.cpp:282] Closing status update streams for framework 20140509-212112-160088899-33285-11408-0000 I0509 21:21:13.568728 11460 gc.cpp:56] Scheduling '/tmp/SlaveTest_ShutdownUnregisteredExecutor_e2Vv2U/slaves/20140509-212112-160088899-33285-11408-0/frameworks/20140509-212112-160088899-33285-11408-0000/executors/1' for gc 6.99999401708444days in the future I0509 21:21:13.568758 11460 gc.cpp:56] Scheduling '/tmp/SlaveTest_ShutdownUnregisteredExecutor_e2Vv2U/slaves/20140509-212112-160088899-33285-11408-0/frameworks/20140509-212112-160088899-33285-11408-0000' for gc 6.99999401708444days in the future I0509 21:21:13.587566 11456 sched.cpp:731] Stopping framework '20140509-212112-160088899-33285-11408-0000' I0509 21:21:13.587692 11408 master.cpp:550] Master terminating I0509 21:21:13.588059 11455 slave.cpp:2168] [email protected]:33285 exited W0509 21:21:13.588234 11455 slave.cpp:2171] Master disconnected! Waiting for a new master to be elected I0509 21:21:13.589833 11408 slave.cpp:416] Slave terminating [ OK ] SlaveTest.ShutdownUnregisteredExecutor (755 ms) [ RUN ] SlaveTest.MetricsInStatsEndpoint Using temporary directory '/tmp/SlaveTest_MetricsInStatsEndpoint_KDwoA3' I0509 21:21:13.698009 11408 leveldb.cpp:174] Opened db in 106.099982ms I0509 21:21:13.703616 11408 leveldb.cpp:181] Compacted db in 5.585579ms I0509 21:21:13.703644 11408 leveldb.cpp:196] Created db iterator in 5004ns I0509 21:21:13.703651 11408 leveldb.cpp:202] Seeked to beginning of db in 821ns I0509 21:21:13.703656 11408 leveldb.cpp:271] Iterated through 0 keys in the db in 357ns I0509 21:21:13.703670 11408 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0509 21:21:13.703950 11457 recover.cpp:425] Starting replica recovery I0509 21:21:13.704277 11460 recover.cpp:451] Replica is in EMPTY status I0509 21:21:13.704535 11457 master.cpp:267] Master 20140509-212113-160088899-33285-11408 (vesta.apache.org) started on 67.195.138.9:33285 I0509 21:21:13.704560 11457 master.cpp:304] Master only allowing authenticated frameworks to register I0509 21:21:13.704567 11457 master.cpp:309] Master only allowing authenticated slaves to register I0509 21:21:13.704573 11457 credentials.hpp:35] Loading credentials for authentication W0509 21:21:13.704645 11457 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveTest_MetricsInStatsEndpoint_KDwoA3/credentials': No such file or directory I0509 21:21:13.704939 11456 master.cpp:104] No whitelist given. Advertising offers for all slaves I0509 21:21:13.705096 11454 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request I0509 21:21:13.705342 11457 master.cpp:919] The newly elected leader is [email protected]:33285 with id 20140509-212113-160088899-33285-11408 I0509 21:21:13.705361 11457 master.cpp:929] Elected as the leading master! I0509 21:21:13.705369 11457 master.cpp:750] Recovering from registrar I0509 21:21:13.705368 11455 recover.cpp:188] Received a recover response from a replica in EMPTY status I0509 21:21:13.705492 11459 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : [email protected]:33285 I0509 21:21:13.705564 11457 recover.cpp:542] Updating replica status to STARTING I0509 21:21:13.705636 11453 registrar.cpp:313] Recovering registrar I0509 21:21:13.731544 11456 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 25.805326ms I0509 21:21:13.731575 11456 replica.cpp:320] Persisted replica status to STARTING I0509 21:21:13.731665 11456 recover.cpp:451] Replica is in STARTING status I0509 21:21:13.732009 11456 replica.cpp:638] Replica in STARTING status received a broadcasted recover request I0509 21:21:13.732107 11459 recover.cpp:188] Received a recover response from a replica in STARTING status I0509 21:21:13.732234 11459 recover.cpp:542] Updating replica status to VOTING I0509 21:21:13.738865 11459 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 6.567392ms I0509 21:21:13.738883 11459 replica.cpp:320] Persisted replica status to VOTING I0509 21:21:13.738926 11459 recover.cpp:556] Successfully joined the Paxos group I0509 21:21:13.739104 11459 recover.cpp:440] Recover process terminated I0509 21:21:13.739244 11458 log.cpp:656] Attempting to start the writer I0509 21:21:13.739717 11457 replica.cpp:474] Replica received implicit promise request with proposal 1 I0509 21:21:13.746844 11457 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 7.113171ms I0509 21:21:13.746865 11457 replica.cpp:342] Persisted promised to 1 I0509 21:21:13.747118 11453 coordinator.cpp:230] Coordinator attemping to fill missing position I0509 21:21:13.747755 11453 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2 I0509 21:21:13.754804 11453 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 7.031524ms I0509 21:21:13.754819 11453 replica.cpp:676] Persisted action at 0 I0509 21:21:13.755245 11453 replica.cpp:508] Replica received write request for position 0 I0509 21:21:13.755267 11453 leveldb.cpp:436] Reading position from leveldb took 11527ns I0509 21:21:13.762765 11453 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 7.48622ms I0509 21:21:13.762779 11453 replica.cpp:676] Persisted action at 0 I0509 21:21:13.763182 11457 replica.cpp:655] Replica received learned notice for position 0 I0509 21:21:13.770738 11457 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 7.533347ms I0509 21:21:13.770757 11457 replica.cpp:676] Persisted action at 0 I0509 21:21:13.770773 11457 replica.cpp:661] Replica learned NOP action at position 0 I0509 21:21:13.771103 11453 log.cpp:672] Writer started with ending position 0 I0509 21:21:13.771481 11460 leveldb.cpp:436] Reading position from leveldb took 16789ns I0509 21:21:13.772497 11458 registrar.cpp:346] Successfully fetched the registry (0B) I0509 21:21:13.772564 11458 registrar.cpp:422] Attempting to update the 'registry' I0509 21:21:13.773535 11455 log.cpp:680] Attempting to append 134 bytes to the log I0509 21:21:13.773660 11458 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I0509 21:21:13.773962 11453 replica.cpp:508] Replica received write request for position 1 I0509 21:21:13.782696 11453 leveldb.cpp:341] Persisting action (153 bytes) to leveldb took 8.657941ms I0509 21:21:13.782711 11453 replica.cpp:676] Persisted action at 1 I0509 21:21:13.782908 11453 replica.cpp:655] Replica received learned notice for position 1 I0509 21:21:13.790663 11453 leveldb.cpp:341] Persisting action (155 bytes) to leveldb took 7.739742ms I0509 21:21:13.790676 11453 replica.cpp:676] Persisted action at 1 I0509 21:21:13.790684 11453 replica.cpp:661] Replica learned APPEND action at position 1 I0509 21:21:13.791017 11457 registrar.cpp:479] Successfully updated 'registry' I0509 21:21:13.791152 11457 registrar.cpp:372] Successfully recovered registrar I0509 21:21:13.791252 11457 master.cpp:777] Recovered 0 slaves from the Registry (97B) ; allowing 10mins for slaves to re-register I0509 21:21:13.791290 11460 log.cpp:699] Attempting to truncate the log to 1 I0509 21:21:13.791422 11454 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I0509 21:21:13.791836 11458 replica.cpp:508] Replica received write request for position 2 I0509 21:21:13.792013 11408 mesos_containerizer.cpp:122] Using isolation: posix/cpu,posix/mem I0509 21:21:13.793577 11460 slave.cpp:143] Slave started on 160)@67.195.138.9:33285 I0509 21:21:13.793597 11460 credentials.hpp:35] Loading credentials for authentication W0509 21:21:13.793658 11460 credentials.hpp:48] Failed to stat credentials file 'file:///tmp/SlaveTest_MetricsInStatsEndpoint_jQy4Fc/credential': No such file or directory I0509 21:21:13.793692 11460 slave.cpp:233] Slave using credential for: test-principal I0509 21:21:13.793815 11460 slave.cpp:246] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0509 21:21:13.793870 11460 slave.cpp:274] Slave hostname: vesta.apache.org I0509 21:21:13.793881 11460 slave.cpp:275] Slave checkpoint: false I0509 21:21:13.794440 11453 state.cpp:33] Recovering state from '/tmp/SlaveTest_MetricsInStatsEndpoint_jQy4Fc/meta' I0509 21:21:13.794448 11460 process.cpp:3335] Handling HTTP event for process 'slave(160)' with path: '/slave(160)/stats.json' I0509 21:21:13.794620 11460 http.cpp:245] HTTP request for '/slave(160)/stats.json' I0509 21:21:13.794896 11456 process.cpp:3335] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' I0509 21:21:13.795228 11456 status_update_manager.cpp:193] Recovering status update manager I0509 21:21:13.795419 11457 mesos_containerizer.cpp:279] Recovering containerizer I0509 21:21:13.795925 11460 slave.cpp:2962] Finished recovery I0509 21:21:13.796193 11453 slave.cpp:527] New master detected at [email protected]:33285 I0509 21:21:13.796298 11453 slave.cpp:587] Authenticating with master [email protected]:33285 I0509 21:21:13.796344 11456 status_update_manager.cpp:167] New master detected at [email protected]:33285 I0509 21:21:13.796471 11453 slave.cpp:560] Detecting new master I0509 21:21:13.796504 11461 process.cpp:1037] Socket closed while receiving I0509 21:21:13.796593 11455 authenticatee.hpp:128] Creating new client SASL connection I0509 21:21:13.796742 11456 master.cpp:2798] Authenticating slave(160)@67.195.138.9:33285 I0509 21:21:13.796888 11459 authenticator.hpp:148] Creating new server SASL connection I0509 21:21:13.796996 11460 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5 I0509 21:21:13.797049 11460 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5' I0509 21:21:13.797204 11459 authenticator.hpp:254] Received SASL authentication start I0509 21:21:13.797263 11461 process.cpp:1037] Socket closed while receiving I0509 21:21:13.797271 11459 authenticator.hpp:342] Authentication requires more steps I0509 21:21:13.797319 11459 authenticatee.hpp:265] Received SASL authentication step I0509 21:21:13.797518 11457 authenticator.hpp:282] Received SASL authentication step I0509 21:21:13.797555 11457 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 I0509 21:21:13.797579 11457 auxprop.cpp:153] Looking up auxiliary property '*userPassword' I0509 21:21:13.797602 11457 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0509 21:21:13.797617 11457 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 I0509 21:21:13.797624 11457 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0509 21:21:13.797629 11457 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0509 21:21:13.797646 11457 authenticator.hpp:334] Authentication success I0509 21:21:13.797693 11460 authenticatee.hpp:305] Authentication success I0509 21:21:13.797724 11457 master.cpp:2838] Successfully authenticated slave(160)@67.195.138.9:33285 I0509 21:21:13.797844 11460 slave.cpp:644] Successfully authenticated with master [email protected]:33285 I0509 21:21:13.797911 11460 slave.cpp:873] Will retry registration in 7.702602943secs if necessary I0509 21:21:13.798005 11459 master.cpp:2134] Registering slave at slave(160)@67.195.138.9:33285 (vesta.apache.org) with id 20140509-212113-160088899-33285-11408-0 I0509 21:21:13.798136 11459 master.cpp:550] Master terminating I0509 21:21:13.798182 11456 registrar.cpp:422] Attempting to update the 'registry' I0509 21:21:13.798192 11459 slave.cpp:2168] [email protected]:33285 exited W0509 21:21:13.798204 11459 slave.cpp:2171] Master disconnected! Waiting for a new master to be elected I0509 21:21:13.798645 11458 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 6.790698ms I0509 21:21:13.798668 11458 replica.cpp:676] Persisted action at 2 I0509 21:21:13.798995 11458 replica.cpp:655] Replica received learned notice for position 2 I0509 21:21:13.806597 11458 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 7.572848ms I0509 21:21:13.806648 11458 leveldb.cpp:399] Deleting ~1 keys from leveldb took 23499ns I0509 21:21:13.806668 11458 replica.cpp:676] Persisted action at 2 I0509 21:21:13.806680 11458 replica.cpp:661] Replica learned TRUNCATE action at position 2 I0509 21:21:13.807502 11408 slave.cpp:416] Slave terminating [ OK ] SlaveTest.MetricsInStatsEndpoint (217 ms) [----------] 3 tests from SlaveTest (1254 ms total) [----------] Global test environment tear-down ../../src/tests/environment.cpp:258: Failure Failed Tests completed with child processes remaining: -+- 11408 /home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/.libs/lt-mesos-tests \-+- 13390 sh -c /home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-executor \--- 13412 /home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/.libs/lt-mesos-executor [==========] 279 tests from 45 test cases ran. (171208 ms total) [ PASSED ] 279 tests. [ FAILED ] 0 tests, listed below: 0 FAILED TESTS YOU HAVE 1 DISABLED TEST I0509 21:21:13.859972 13434 process.cpp:1098] Socket closed while receiving make[3]: *** [check-local] Error 1 I0509 21:21:13.860079 13433 exec.cpp:439] Ignoring exited event because the driver is aborted! make[3]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make[2]: *** [check-am] Error 2 make[2]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make[1]: *** [check] Error 2 make[1]: Leaving directory `/home/hudson/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src' make: *** [check-recursive] Error 1 Build step 'Execute shell' marked build as failure
