See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2289/changes>
Changes: [benjamin.hindman] Use JSON instead of own format for passing URIs to mesos-fetcher. ------------------------------------------ [...truncated 72258 lines...] I1116 04:05:14.163908 25646 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 581730ns I1116 04:05:15.145012 25643 hierarchical_allocator_process.hpp:697] No resources available to allocate! I1116 04:05:16.090865 25646 replica.cpp:676] Persisted action at 0 I1116 04:05:16.090872 25643 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 945.869666ms I1116 04:05:16.091720 25642 replica.cpp:655] Replica received learned notice for position 0 I1116 04:05:16.092301 25642 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 529114ns I1116 04:05:16.092329 25642 replica.cpp:676] Persisted action at 0 I1116 04:05:16.092353 25642 replica.cpp:661] Replica learned NOP action at position 0 I1116 04:05:16.092978 25637 log.cpp:672] Writer started with ending position 0 I1116 04:05:16.094524 25638 leveldb.cpp:438] Reading position from leveldb took 30290ns I1116 04:05:16.097945 25635 registrar.cpp:346] Successfully fetched the registry (0B) in 1.942691072secs I1116 04:05:16.098068 25635 registrar.cpp:445] Applied 1 operations in 26094ns; attempting to update the 'registry' I1116 04:05:16.101238 25633 log.cpp:680] Attempting to append 139 bytes to the log I1116 04:05:16.101449 25641 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I1116 04:05:16.102406 25642 replica.cpp:508] Replica received write request for position 1 I1116 04:05:16.102813 25642 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 373151ns I1116 04:05:16.102838 25642 replica.cpp:676] Persisted action at 1 I1116 04:05:16.103467 25644 replica.cpp:655] Replica received learned notice for position 1 I1116 04:05:16.103839 25644 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 340591ns I1116 04:05:16.103867 25644 replica.cpp:676] Persisted action at 1 I1116 04:05:16.103888 25644 replica.cpp:661] Replica learned APPEND action at position 1 I1116 04:05:16.104859 25638 registrar.cpp:490] Successfully updated the 'registry' in 6.737152ms I1116 04:05:16.104990 25638 registrar.cpp:376] Successfully recovered registrar I1116 04:05:16.105149 25634 log.cpp:699] Attempting to truncate the log to 1 I1116 04:05:16.105360 25639 master.cpp:1121] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register I1116 04:05:16.105398 25638 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I1116 04:05:16.106230 25637 replica.cpp:508] Replica received write request for position 2 I1116 04:05:16.106727 25637 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 464736ns I1116 04:05:16.106758 25637 replica.cpp:676] Persisted action at 2 I1116 04:05:16.107430 25640 replica.cpp:655] Replica received learned notice for position 2 I1116 04:05:16.107918 25640 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 456200ns I1116 04:05:16.107965 25640 leveldb.cpp:401] Deleting ~1 keys from leveldb took 22912ns I1116 04:05:16.107983 25640 replica.cpp:676] Persisted action at 2 I1116 04:05:16.108006 25640 replica.cpp:661] Replica learned TRUNCATE action at position 2 2014-11-16 04:05:16,117:25617(0x2b373ba89700):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5 2014-11-16 04:05:16,117:25617(0x2b373ba89700):ZOO_INFO@log_env@716: Client environment:host.name=pomona.apache.org 2014-11-16 04:05:16,117:25617(0x2b373ba89700):ZOO_INFO@log_env@723: Client environment:os.name=Linux 2014-11-16 04:05:16,117:25617(0x2b373ba89700):ZOO_INFO@log_env@724: Client environment:os.arch=3.13.0-36-lowlatency 2014-11-16 04:05:16,117:25617(0x2b373ba89700):ZOO_INFO@log_env@725: Client environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC 2014 2014-11-16 04:05:16,117:25617(0x2b373ba89700):ZOO_INFO@log_env@733: Client environment:user.name=jenkins 2014-11-16 04:05:16,117:25617(0x2b373ba89700):ZOO_INFO@log_env@741: Client environment:user.home=/home/jenkins 2014-11-16 04:05:16,117:25617(0x2b373ba89700):ZOO_INFO@log_env@753: Client environment:user.dir=/tmp/RegistrarZooKeeperTest_TaskRunning_gakXAv 2014-11-16 04:05:16,117:25617(0x2b373ba89700):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:55568 sessionTimeout=10000 watcher=0x2b3735243ec0 sessionId=0 sessionPasswd=<null> context=0x2b37640a9060 flags=0 2014-11-16 04:05:16,118:25617(0x2b3af550a700):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:55568] 2014-11-16 04:05:16,120:25617(0x2b3af550a700):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:55568], sessionId=0x149b6c6acbd0004, negotiated timeout=10000 I1116 04:05:16.120661 25637 group.cpp:313] Group process (group(58)@67.195.81.187:46518) connected to ZooKeeper I1116 04:05:16.120697 25637 group.cpp:790] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0) I1116 04:05:16.120718 25637 group.cpp:385] Trying to create path '/znode' in ZooKeeper I1116 04:05:16.123447 25637 group.cpp:717] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper I1116 04:05:16.123646 25644 detector.cpp:138] Detected a new leader: (id='1') I1116 04:05:16.123900 25636 group.cpp:659] Trying to get '/znode/info_0000000001' in ZooKeeper I1116 04:05:16.125036 25642 slave.cpp:172] Slave started on 225)@67.195.81.187:46518 I1116 04:05:16.125077 25642 credentials.hpp:84] Loading credential for authentication from '/tmp/RegistrarZooKeeperTest_TaskRunning_XqSCyZ/credential' I1116 04:05:16.125258 25642 slave.cpp:281] Slave using credential for: test-principal I1116 04:05:16.125380 25633 detector.cpp:433] A new leading master ([email protected]:46518) is detected I1116 04:05:16.125540 25642 slave.cpp:294] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1116 04:05:16.125645 25642 slave.cpp:323] Slave hostname: pomona.apache.org I1116 04:05:16.125663 25642 slave.cpp:324] Slave checkpoint: false W1116 04:05:16.125674 25642 slave.cpp:326] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag I1116 04:05:16.126468 25645 state.cpp:33] Recovering state from '/tmp/RegistrarZooKeeperTest_TaskRunning_XqSCyZ/meta' I1116 04:05:16.126745 25633 status_update_manager.cpp:197] Recovering status update manager I1116 04:05:16.127105 25631 slave.cpp:3483] Finished recovery I1116 04:05:16.127730 25635 status_update_manager.cpp:171] Pausing sending status updates I1116 04:05:16.127730 25645 slave.cpp:607] New master detected at [email protected]:46518 I1116 04:05:16.127805 25645 slave.cpp:670] Authenticating with master [email protected]:46518 I1116 04:05:16.127826 25645 slave.cpp:675] Using default CRAM-MD5 authenticatee I1116 04:05:16.127967 25645 slave.cpp:643] Detecting new master I1116 04:05:16.128172 25642 authenticatee.hpp:138] Creating new client SASL connection I1116 04:05:16.128936 25635 master.cpp:3896] Authenticating slave(225)@67.195.81.187:46518 I1116 04:05:16.128975 25635 master.cpp:3907] Using default CRAM-MD5 authenticator I1116 04:05:16.129374 25643 authenticator.hpp:170] Creating new server SASL connection I1116 04:05:16.129624 25646 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5 I1116 04:05:16.129655 25646 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5' I1116 04:05:16.129818 25646 authenticator.hpp:276] Received SASL authentication start I1116 04:05:16.129884 25646 authenticator.hpp:398] Authentication requires more steps I1116 04:05:16.129982 25644 authenticatee.hpp:275] Received SASL authentication step I1116 04:05:16.130178 25631 authenticator.hpp:304] Received SASL authentication step I1116 04:05:16.130216 25631 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1116 04:05:16.130229 25631 auxprop.cpp:171] Looking up auxiliary property '*userPassword' I1116 04:05:16.130272 25631 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1116 04:05:16.130322 25631 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1116 04:05:16.132616 25617 sched.cpp:148] Version: 0.22.0 I1116 04:05:16.212853 25631 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1116 04:05:16.212880 25631 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1116 04:05:16.212919 25631 authenticator.hpp:390] Authentication success I1116 04:05:16.213059 25637 authenticatee.hpp:315] Authentication success I1116 04:05:16.213136 25635 master.cpp:3954] Successfully authenticated principal 'test-principal' at slave(225)@67.195.81.187:46518 I1116 04:05:16.213505 25637 slave.cpp:741] Successfully authenticated with master [email protected]:46518 I1116 04:05:16.213600 25632 sched.cpp:245] New master detected at [email protected]:46518 I1116 04:05:16.213647 25632 sched.cpp:301] Authenticating with master [email protected]:46518 I1116 04:05:16.213675 25632 sched.cpp:308] Using default CRAM-MD5 authenticatee I1116 04:05:16.213649 25637 slave.cpp:1069] Will retry registration in 1.18292ms if necessary I1116 04:05:16.213888 25643 master.cpp:3063] Registering slave at slave(225)@67.195.81.187:46518 (pomona.apache.org) with id 20141116-040514-3142697795-46518-25617-S0 I1116 04:05:16.214038 25642 authenticatee.hpp:138] Creating new client SASL connection I1116 04:05:16.214391 25643 master.cpp:3896] Authenticating [email protected]:46518 I1116 04:05:16.214432 25643 master.cpp:3907] Using default CRAM-MD5 authenticator I1116 04:05:16.214457 25644 registrar.cpp:445] Applied 1 operations in 58983ns; attempting to update the 'registry' I1116 04:05:16.214692 25638 authenticator.hpp:170] Creating new server SASL connection I1116 04:05:16.214861 25641 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5 I1116 04:05:16.214897 25641 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5' I1116 04:05:16.214992 25641 authenticator.hpp:276] Received SASL authentication start I1116 04:05:16.215045 25641 authenticator.hpp:398] Authentication requires more steps I1116 04:05:16.215152 25646 authenticatee.hpp:275] Received SASL authentication step I1116 04:05:16.215272 25635 authenticator.hpp:304] Received SASL authentication step I1116 04:05:16.215322 25635 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1116 04:05:16.215337 25635 auxprop.cpp:171] Looking up auxiliary property '*userPassword' I1116 04:05:16.215374 25635 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1116 04:05:16.215399 25635 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1116 04:05:16.215411 25635 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1116 04:05:16.215420 25635 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1116 04:05:16.215436 25635 authenticator.hpp:390] Authentication success I1116 04:05:16.215509 25646 authenticatee.hpp:315] Authentication success I1116 04:05:16.215538 25635 master.cpp:3954] Successfully authenticated principal 'test-principal' at [email protected]:46518 I1116 04:05:16.215849 25633 sched.cpp:389] Successfully authenticated with master [email protected]:46518 I1116 04:05:16.215874 25633 sched.cpp:512] Sending registration request to [email protected]:46518 I1116 04:05:16.215924 25633 sched.cpp:545] Will retry registration in 1.814313558secs if necessary I1116 04:05:16.216006 25635 master.cpp:1383] Received registration request for framework 'default' at [email protected]:46518 I1116 04:05:16.216075 25635 master.cpp:1342] Authorizing framework principal 'test-principal' to receive offers for role '*' I1116 04:05:16.216073 25634 slave.cpp:1069] Will retry registration in 3.549467ms if necessary I1116 04:05:16.216408 25635 master.cpp:3051] Ignoring register slave message from slave(225)@67.195.81.187:46518 (pomona.apache.org) as admission is already in progress I1116 04:05:16.216521 25635 master.cpp:1447] Registering framework 20141116-040514-3142697795-46518-25617-0000 (default) at [email protected]:46518 I1116 04:05:16.216730 25640 hierarchical_allocator_process.hpp:329] Added framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.216748 25640 hierarchical_allocator_process.hpp:697] No resources available to allocate! I1116 04:05:16.216755 25640 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 10374ns I1116 04:05:16.216971 25638 sched.cpp:439] Framework registered with 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.217005 25638 sched.cpp:453] Scheduler::registered took 14676ns I1116 04:05:16.217641 25638 log.cpp:680] Attempting to append 316 bytes to the log I1116 04:05:16.217772 25633 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I1116 04:05:16.218564 25638 replica.cpp:508] Replica received write request for position 3 I1116 04:05:16.218830 25638 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 233624ns I1116 04:05:16.218859 25638 replica.cpp:676] Persisted action at 3 I1116 04:05:16.219501 25633 replica.cpp:655] Replica received learned notice for position 3 I1116 04:05:16.220087 25633 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 559043ns I1116 04:05:16.220111 25633 replica.cpp:676] Persisted action at 3 I1116 04:05:16.220132 25633 replica.cpp:661] Replica learned APPEND action at position 3 I1116 04:05:16.220505 25631 slave.cpp:1069] Will retry registration in 65.520788ms if necessary I1116 04:05:16.220636 25644 master.cpp:3051] Ignoring register slave message from slave(225)@67.195.81.187:46518 (pomona.apache.org) as admission is already in progress I1116 04:05:16.221295 25646 registrar.cpp:490] Successfully updated the 'registry' in 6.767104ms I1116 04:05:16.221698 25645 log.cpp:699] Attempting to truncate the log to 3 I1116 04:05:16.221864 25641 master.cpp:3117] Registered slave 20141116-040514-3142697795-46518-25617-S0 at slave(225)@67.195.81.187:46518 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I1116 04:05:16.221906 25632 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I1116 04:05:16.222004 25637 slave.cpp:775] Registered with master [email protected]:46518; given slave ID 20141116-040514-3142697795-46518-25617-S0 I1116 04:05:16.222064 25645 hierarchical_allocator_process.hpp:442] Added slave 20141116-040514-3142697795-46518-25617-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I1116 04:05:16.222131 25638 status_update_manager.cpp:178] Resuming sending status updates I1116 04:05:16.222193 25637 slave.cpp:2555] Received ping from slave-observer(205)@67.195.81.187:46518 I1116 04:05:16.222267 25645 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141116-040514-3142697795-46518-25617-S0 to framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.222698 25645 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141116-040514-3142697795-46518-25617-S0 in 562237ns I1116 04:05:16.222853 25642 replica.cpp:508] Replica received write request for position 4 I1116 04:05:16.223091 25640 master.cpp:3838] Sending 1 offers to framework 20141116-040514-3142697795-46518-25617-0000 (default) at [email protected]:46518 I1116 04:05:16.223395 25642 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 508929ns I1116 04:05:16.334072 25642 replica.cpp:676] Persisted action at 4 I1116 04:05:16.334540 25633 sched.cpp:602] Scheduler::resourceOffers took 102629ns I1116 04:05:16.335144 25636 replica.cpp:655] Replica received learned notice for position 4 I1116 04:05:16.335736 25636 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 557768ns I1116 04:05:16.335798 25636 leveldb.cpp:401] Deleting ~2 keys from leveldb took 34709ns I1116 04:05:16.335819 25636 replica.cpp:676] Persisted action at 4 I1116 04:05:16.335845 25636 replica.cpp:661] Replica learned TRUNCATE action at position 4 I1116 04:05:16.338590 25636 master.cpp:2356] Processing reply for offers: [ 20141116-040514-3142697795-46518-25617-O0 ] on slave 20141116-040514-3142697795-46518-25617-S0 at slave(225)@67.195.81.187:46518 (pomona.apache.org) for framework 20141116-040514-3142697795-46518-25617-0000 (default) at [email protected]:46518 I1116 04:05:16.338626 25636 master.cpp:2454] Authorizing framework principal 'test-principal' to launch task ab31b9b3-20b5-460a-b931-a1f35d6f38da as user 'jenkins' W1116 04:05:16.339476 25633 master.cpp:1991] Executor default for task ab31b9b3-20b5-460a-b931-a1f35d6f38da uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. W1116 04:05:16.339519 25633 master.cpp:2003] Executor default for task ab31b9b3-20b5-460a-b931-a1f35d6f38da uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. I1116 04:05:16.339882 25633 master.hpp:753] Adding task ab31b9b3-20b5-460a-b931-a1f35d6f38da with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141116-040514-3142697795-46518-25617-S0 (pomona.apache.org) I1116 04:05:16.339995 25633 master.cpp:2522] Launching task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 (default) at [email protected]:46518 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141116-040514-3142697795-46518-25617-S0 at slave(225)@67.195.81.187:46518 (pomona.apache.org) I1116 04:05:16.340416 25639 slave.cpp:1100] Got assigned task ab31b9b3-20b5-460a-b931-a1f35d6f38da for framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.341002 25639 slave.cpp:1210] Launching task ab31b9b3-20b5-460a-b931-a1f35d6f38da for framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.343880 25639 slave.cpp:4014] Launching executor default of framework 20141116-040514-3142697795-46518-25617-0000 in work directory '/tmp/RegistrarZooKeeperTest_TaskRunning_XqSCyZ/slaves/20141116-040514-3142697795-46518-25617-S0/frameworks/20141116-040514-3142697795-46518-25617-0000/executors/default/runs/d86afacd-bf3d-4294-9a57-ba7c684034f9' I1116 04:05:16.346976 25639 exec.cpp:132] Version: 0.22.0 I1116 04:05:16.347225 25636 exec.cpp:182] Executor started at: executor(76)@67.195.81.187:46518 with pid 25617 I1116 04:05:16.347337 25639 slave.cpp:1333] Queuing task 'ab31b9b3-20b5-460a-b931-a1f35d6f38da' for executor default of framework '20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.347443 25639 slave.cpp:560] Successfully attached file '/tmp/RegistrarZooKeeperTest_TaskRunning_XqSCyZ/slaves/20141116-040514-3142697795-46518-25617-S0/frameworks/20141116-040514-3142697795-46518-25617-0000/executors/default/runs/d86afacd-bf3d-4294-9a57-ba7c684034f9' I1116 04:05:16.347543 25639 slave.cpp:2857] Monitoring executor 'default' of framework '20141116-040514-3142697795-46518-25617-0000' in container 'd86afacd-bf3d-4294-9a57-ba7c684034f9' I1116 04:05:16.347697 25639 slave.cpp:1877] Got registration for executor 'default' of framework 20141116-040514-3142697795-46518-25617-0000 from executor(76)@67.195.81.187:46518 I1116 04:05:16.348028 25639 slave.cpp:1996] Flushing queued task ab31b9b3-20b5-460a-b931-a1f35d6f38da for executor 'default' of framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.348204 25643 exec.cpp:206] Executor registered on slave 20141116-040514-3142697795-46518-25617-S0 I1116 04:05:16.350656 25643 exec.cpp:218] Executor::registered took 24249ns I1116 04:05:16.350857 25643 exec.cpp:293] Executor asked to run task 'ab31b9b3-20b5-460a-b931-a1f35d6f38da' I1116 04:05:16.350932 25643 exec.cpp:302] Executor::launchTask took 53661ns I1116 04:05:16.353370 25643 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.353590 25643 slave.cpp:2232] Handling status update TASK_RUNNING (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 from executor(76)@67.195.81.187:46518 I1116 04:05:16.353893 25636 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.353936 25636 status_update_manager.cpp:494] Creating StatusUpdate stream for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.354162 25636 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 to the slave I1116 04:05:16.354413 25643 slave.cpp:2475] Forwarding the update TASK_RUNNING (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 to [email protected]:46518 I1116 04:05:16.354624 25643 slave.cpp:2402] Status update manager successfully handled status update TASK_RUNNING (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.354660 25643 slave.cpp:2408] Sending acknowledgement for status update TASK_RUNNING (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 to executor(76)@67.195.81.187:46518 I1116 04:05:16.354702 25636 master.cpp:3441] Forwarding status update TASK_RUNNING (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.354830 25631 exec.cpp:339] Executor received status update acknowledgement ef9da2d7-58ec-4657-879e-02ccf43c2a9e for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.354876 25636 master.cpp:3413] Status update TASK_RUNNING (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 from slave 20141116-040514-3142697795-46518-25617-S0 at slave(225)@67.195.81.187:46518 (pomona.apache.org) I1116 04:05:16.354940 25636 master.cpp:4688] Updating the latest state of task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 to TASK_RUNNING I1116 04:05:16.355007 25640 sched.cpp:693] Scheduler::statusUpdate took 56913ns I1116 04:05:16.355224 25640 master.cpp:2913] Forwarding status update acknowledgement ef9da2d7-58ec-4657-879e-02ccf43c2a9e for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 (default) at [email protected]:46518 to slave 20141116-040514-3142697795-46518-25617-S0 at slave(225)@67.195.81.187:46518 (pomona.apache.org) I1116 04:05:16.355567 25617 sched.cpp:1364] Asked to stop the driver I1116 04:05:16.460021 25645 sched.cpp:805] Stopping framework '20141116-040514-3142697795-46518-25617-0000' I1116 04:05:16.460026 25640 master.cpp:698] Master terminating I1116 04:05:16.460324 25639 status_update_manager.cpp:389] Received status update acknowledgement (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 W1116 04:05:16.460222 25640 master.cpp:4733] Removing task ab31b9b3-20b5-460a-b931-a1f35d6f38da with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20141116-040514-3142697795-46518-25617-0000 on slave 20141116-040514-3142697795-46518-25617-S0 at slave(225)@67.195.81.187:46518 (pomona.apache.org) in non-terminal state TASK_RUNNING I1116 04:05:16.460531 25641 slave.cpp:1817] Status update manager successfully handled status update acknowledgement (UUID: ef9da2d7-58ec-4657-879e-02ccf43c2a9e) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.460912 25635 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20141116-040514-3142697795-46518-25617-S0 from framework 20141116-040514-3142697795-46518-25617-0000 I1116 04:05:16.461318 25640 master.cpp:4776] Removing executor 'default' with resources of framework 20141116-040514-3142697795-46518-25617-0000 on slave 20141116-040514-3142697795-46518-25617-S0 at slave(225)@67.195.81.187:46518 (pomona.apache.org) I1116 04:05:16.462203 25645 slave.cpp:2640] [email protected]:46518 exited W1116 04:05:16.462237 25645 slave.cpp:2643] Master disconnected! Waiting for a new master to be elected 2014-11-16 04:05:16,477:25617(0x2b373ba89700):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x149b6c6acbd0003 to [127.0.0.1:55568] I1116 04:05:16.477571 25634 contender.cpp:186] Now cancelling the membership: 1 I1116 04:05:16.477751 25645 group.cpp:619] Trying to remove '/znode/info_0000000001' in ZooKeeper 2014-11-16 04:05:16,480:25617(0x2b373aa81700):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x149b6c6acbd0002 to [127.0.0.1:55568] I1116 04:05:16.481145 25637 group.cpp:717] Found non-sequence node 'log_replicas' at '/znode' in ZooKeeper I1116 04:05:16.481348 25645 detector.cpp:126] The current leader (id=1) is lost I1116 04:05:16.481377 25645 detector.cpp:138] Detected a new leader: None I1116 04:05:16.481729 25634 slave.cpp:600] Lost leading master I1116 04:05:16.481758 25634 slave.cpp:643] Detecting new master I1116 04:05:16.481843 25643 status_update_manager.cpp:171] Pausing sending status updates 2014-11-16 04:05:16,483:25617(0x2b373225f080):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x149b6c6acbd0001 to [127.0.0.1:55568] 2014-11-16 04:05:16,484:25617(0x2b373ba89700):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x149b6c6acbd0000 to [127.0.0.1:55568] I1116 04:05:16.485820 25636 slave.cpp:2915] Executor 'default' of framework 20141116-040514-3142697795-46518-25617-0000 exited with status 0 I1116 04:05:16.488272 25636 slave.cpp:2232] Handling status update TASK_LOST (UUID: fb62c6cb-6294-429b-ab77-4899c413b17b) for task ab31b9b3-20b5-460a-b931-a1f35d6f38da of framework 20141116-040514-3142697795-46518-25617-0000 from @0.0.0.0:0 I1116 04:05:16.488390 25636 slave.cpp:4322] Terminating task ab31b9b3-20b5-460a-b931-a1f35d6f38da I1116 04:05:16.488762 25636 slave.cpp:489] Slave terminating I1116 04:05:16.488839 25636 slave.cpp:1550] Asked to shut down framework 20141116-040514-3142697795-46518-25617-0000 by @0.0.0.0:0 W1116 04:05:16.488859 25636 slave.cpp:1558] Ignoring shutdown framework message for 20141116-040514-3142697795-46518-25617-0000 because the slave has not yet registered with the master 2014-11-16 04:05:16,496:25617(0x2b373a880700):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x149b6c6acbd0004 to [127.0.0.1:55568] [ OK ] RegistrarZooKeeperTest.TaskRunning (2452 ms) I1116 04:05:16.498229 25617 zookeeper_test_server.cpp:118] Shutting down ZooKeeperTestServer on port 55568 [----------] 1 test from RegistrarZooKeeperTest (2452 ms total) [----------] Global test environment tear-down [==========] 473 tests from 75 test cases ran. (337661 ms total) [ PASSED ] 472 tests. [ FAILED ] 1 test, listed below: [ FAILED ] LogStateTest.FetchAndStoreAndStoreAndFetch 1 FAILED TEST YOU HAVE 6 DISABLED TESTS make[3]: *** [check-local] Error 1 make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'> make[2]: *** [check-am] Error 2 make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'> make[1]: *** [check] Error 2 make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'> make: *** [check-recursive] Error 1 Test finished Exit status: 2 Build step 'Execute shell' marked build as failure Recording test results
