You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/12/10 21:55:40 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #1522
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/1522/changes>
Changes:
[bmahler] Fixed the python tests in the presence of muliple eggs.
------------------------------------------
[...truncated 22233 lines...]
I1210 20:55:35.079139 2473 slave.cpp:524] Detecting new master
I1210 20:55:35.079169 2469 master.cpp:1366] Attempting to register slave on hemera.apache.org at slave(136)@140.211.11.27:39024
I1210 20:55:35.079190 2469 master.cpp:2628] Adding slave 201312102055-453759884-39024-2442-0 at hemera.apache.org with cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000]
I1210 20:55:35.079254 2476 slave.cpp:542] Registered with master master@140.211.11.27:39024; given slave ID 201312102055-453759884-39024-2442-0
I1210 20:55:35.079336 2469 master.cpp:1849] Authenticating framework at scheduler(131)@140.211.11.27:39024
I1210 20:55:35.079336 2477 hierarchical_allocator_process.hpp:445] Added slave 201312102055-453759884-39024-2442-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] available)
I1210 20:55:35.079377 2477 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201312102055-453759884-39024-2442-0 in 4503ns
I1210 20:55:35.079463 2466 authenticator.hpp:140] Creating new server SASL connection
I1210 20:55:35.079566 2462 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1210 20:55:35.079581 2462 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1210 20:55:35.079608 2467 authenticator.hpp:243] Received SASL authentication start
I1210 20:55:35.079668 2467 authenticator.hpp:325] Authentication requires more steps
I1210 20:55:35.079695 2462 authenticatee.hpp:258] Received SASL authentication step
I1210 20:55:35.079726 2462 authenticator.hpp:271] Received SASL authentication step
I1210 20:55:35.079746 2462 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
I1210 20:55:35.079756 2462 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1210 20:55:35.079768 2462 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1210 20:55:35.079777 2462 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
I1210 20:55:35.079782 2462 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1210 20:55:35.079784 2462 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1210 20:55:35.079793 2462 authenticator.hpp:317] Authentication success
I1210 20:55:35.079820 2469 authenticatee.hpp:298] Authentication success
I1210 20:55:35.079839 2467 master.cpp:1889] Successfully authenticated framework at scheduler(131)@140.211.11.27:39024
I1210 20:55:35.079907 2479 sched.cpp:334] Successfully authenticated with master master@140.211.11.27:39024
I1210 20:55:35.079957 2483 master.cpp:801] Received registration request from scheduler(131)@140.211.11.27:39024
I1210 20:55:35.080063 2483 master.cpp:819] Registering framework 201312102055-453759884-39024-2442-0000 at scheduler(131)@140.211.11.27:39024
I1210 20:55:35.080106 2461 sched.cpp:383] Framework registered with 201312102055-453759884-39024-2442-0000
I1210 20:55:35.080119 2479 hierarchical_allocator_process.hpp:332] Added framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.080126 2461 sched.cpp:397] Scheduler::registered took 9692ns
I1210 20:55:35.080160 2479 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] on slave 201312102055-453759884-39024-2442-0 to framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.080278 2479 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 143324ns
I1210 20:55:35.080307 2483 master.hpp:437] Adding offer 201312102055-453759884-39024-2442-0 with resources cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:35.080340 2483 master.cpp:1804] Sending 1 offers to framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.080519 2466 sched.cpp:517] Scheduler::resourceOffers took 97815ns
I1210 20:55:35.080590 2466 master.cpp:2141] Processing reply for offer 201312102055-453759884-39024-2442-0 on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org) for framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.080653 2466 master.hpp:409] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:35.080674 2466 master.cpp:2265] Launching task 0 of framework 201312102055-453759884-39024-2442-0000 with resources cpus(*):1; mem(*):500 on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:35.080734 2469 slave.cpp:727] Got assigned task 0 for framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.080792 2479 hierarchical_allocator_process.hpp:547] Framework 201312102055-453759884-39024-2442-0000 left cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] unused on slave 201312102055-453759884-39024-2442-0
I1210 20:55:35.080801 2466 master.hpp:447] Removing offer 201312102055-453759884-39024-2442-0 with resources cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:35.080879 2479 hierarchical_allocator_process.hpp:590] Framework 201312102055-453759884-39024-2442-0000 filtered slave 201312102055-453759884-39024-2442-0 for 5secs
I1210 20:55:35.080899 2469 slave.cpp:836] Launching task 0 for framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.083348 2469 slave.cpp:946] Queuing task '0' for executor default of framework '201312102055-453759884-39024-2442-0000
I1210 20:55:35.083608 2468 slave.cpp:466] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_dkDInR/slaves/201312102055-453759884-39024-2442-0/frameworks/201312102055-453759884-39024-2442-0000/executors/default/runs/2a497e5f-329e-435b-a161-36f08e2e4108'
I1210 20:55:35.085834 2469 exec.cpp:178] Executor started at: executor(45)@140.211.11.27:39024 with pid 2442
I1210 20:55:35.085880 2467 slave.cpp:2089] Monitoring executor default of framework 201312102055-453759884-39024-2442-0000 forked at pid 2442
I1210 20:55:35.085922 2467 slave.cpp:1422] Got registration for executor 'default' of framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.085991 2467 slave.cpp:1543] Flushing queued task 0 for executor 'default' of framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.086069 2477 exec.cpp:202] Executor registered on slave 201312102055-453759884-39024-2442-0
I1210 20:55:35.087465 2477 exec.cpp:214] Executor::registered took 9713ns
I1210 20:55:35.087501 2477 exec.cpp:289] Executor asked to run task '0'
I1210 20:55:35.087519 2477 exec.cpp:298] Executor::launchTask took 13157ns
I1210 20:55:35.088785 2477 exec.cpp:521] Executor sending status update TASK_RUNNING (UUID: f58e75b8-c8ad-46d1-b579-16307a83e49f) for task 0 of framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.088850 2477 slave.cpp:1756] Handling status update TASK_RUNNING (UUID: f58e75b8-c8ad-46d1-b579-16307a83e49f) for task 0 of framework 201312102055-453759884-39024-2442-0000 from executor(45)@140.211.11.27:39024
I1210 20:55:35.088999 2483 status_update_manager.cpp:312] Received status update TASK_RUNNING (UUID: f58e75b8-c8ad-46d1-b579-16307a83e49f) for task 0 of framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.089015 2483 status_update_manager.cpp:491] Creating StatusUpdate stream for task 0 of framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.089048 2483 status_update_manager.cpp:365] Forwarding status update TASK_RUNNING (UUID: f58e75b8-c8ad-46d1-b579-16307a83e49f) for task 0 of framework 201312102055-453759884-39024-2442-0000 to master@140.211.11.27:39024
I1210 20:55:35.089876 2483 slave.cpp:1875] Status update manager successfully handled status update TASK_RUNNING (UUID: f58e75b8-c8ad-46d1-b579-16307a83e49f) for task 0 of framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.089889 2483 slave.cpp:1881] Sending acknowledgement for status update TASK_RUNNING (UUID: f58e75b8-c8ad-46d1-b579-16307a83e49f) for task 0 of framework 201312102055-453759884-39024-2442-0000 to executor(45)@140.211.11.27:39024
I1210 20:55:35.090023 2473 master.cpp:1552] Status update TASK_RUNNING (UUID: f58e75b8-c8ad-46d1-b579-16307a83e49f) for task 0 of framework 201312102055-453759884-39024-2442-0000 from slave(136)@140.211.11.27:39024
I1210 20:55:35.090114 2477 sched.cpp:608] Scheduler::statusUpdate took 14339ns
I1210 20:55:35.090396 2481 master.cpp:556] Master terminating
I1210 20:55:35.090411 2468 exec.cpp:335] Executor received status update acknowledgement f58e75b8-c8ad-46d1-b579-16307a83e49f for task 0 of framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.090437 2442 master.cpp:209] Shutting down master
I1210 20:55:35.090456 2483 slave.cpp:1956] master@140.211.11.27:39024 exited
W1210 20:55:35.090471 2483 slave.cpp:1959] Master disconnected! Waiting for a new master to be elected
I1210 20:55:35.090476 2442 master.hpp:427] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:35.090481 2470 status_update_manager.cpp:390] Received status update acknowledgement (UUID: f58e75b8-c8ad-46d1-b579-16307a83e49f) for task 0 of framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.090534 2470 slave.cpp:1362] Status update manager successfully handled status update acknowledgement (UUID: f58e75b8-c8ad-46d1-b579-16307a83e49f) for task 0 of framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.090631 2442 master.cpp:252] Removing slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:35.090647 2482 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000]) on slave 201312102055-453759884-39024-2442-0 from framework 201312102055-453759884-39024-2442-0000
I1210 20:55:35.091474 2480 contender.cpp:172] Now cancelling the membership: 4
I1210 20:55:35.092222 2484 group.cpp:519] Trying to remove '/znode/0000000004' in ZooKeeper
2013-12-10 20:55:35,093:2442(0x2ac226ca17c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142de4b1d980007 to [127.0.0.1:58949]
I1210 20:55:35.093782 2468 detector.cpp:116] The current leader (id=4) is lost
I1210 20:55:35.093794 2468 detector.cpp:138] No new leader is elected after election
I1210 20:55:35.094171 2474 detector.cpp:116] The current leader (id=4) is lost
I1210 20:55:35.094182 2474 detector.cpp:138] No new leader is elected after election
I1210 20:55:35.094398 2466 slave.cpp:518] Lost leading master
I1210 20:55:35.094409 2466 slave.cpp:524] Detecting new master
I1210 20:55:35.094502 2478 detector.cpp:116] The current leader (id=4) is lost
I1210 20:55:35.094516 2478 detector.cpp:138] No new leader is elected after election
2013-12-10 20:55:35,094:2442(0x2ac226ca17c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142de4b1d980006 to [127.0.0.1:58949]
I1210 20:55:35.094759 2474 sched.cpp:201] Scheduler::disconnected took 4700ns
I1210 20:55:35.094769 2474 sched.cpp:223] No master detected
I1210 20:55:35.094771 2474 sched.cpp:229] Detecting new master
I1210 20:55:35.095448 2479 master.cpp:284] Master started on 140.211.11.27:39024
I1210 20:55:35.095476 2479 master.cpp:298] Master ID: 201312102055-453759884-39024-2442
I1210 20:55:35.095485 2479 master.cpp:301] Master only allowing authenticated frameworks to register!
I1210 20:55:35.095654 2465 master.cpp:84] No whitelist given. Advertising offers for all slaves
I1210 20:55:35.095803 2472 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@140.211.11.27:39024
2013-12-10 20:55:35,095:2442(0x2ac2298bb700):ZOO_INFO@log_env@658: Client environment:zookeeper.version=zookeeper C client 3.3.4
2013-12-10 20:55:35,095:2442(0x2ac2298bb700):ZOO_INFO@log_env@662: Client environment:host.name=hemera
2013-12-10 20:55:35,095:2442(0x2ac2298bb700):ZOO_INFO@log_env@669: Client environment:os.name=Linux
2013-12-10 20:55:35,095:2442(0x2ac2298bb700):ZOO_INFO@log_env@670: Client environment:os.arch=3.2.0-57-generic
2013-12-10 20:55:35,095:2442(0x2ac2298bb700):ZOO_INFO@log_env@671: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2013-12-10 20:55:35,095:2442(0x2ac228eb6700):ZOO_INFO@log_env@658: Client environment:zookeeper.version=zookeeper C client 3.3.4
2013-12-10 20:55:35,095:2442(0x2ac228eb6700):ZOO_INFO@log_env@662: Client environment:host.name=hemera
2013-12-10 20:55:35,095:2442(0x2ac228eb6700):ZOO_INFO@log_env@669: Client environment:os.name=Linux
2013-12-10 20:55:35,095:2442(0x2ac228eb6700):ZOO_INFO@log_env@670: Client environment:os.arch=3.2.0-57-generic
2013-12-10 20:55:35,095:2442(0x2ac2298bb700):ZOO_INFO@log_env@679: Client environment:user.name=(null)
2013-12-10 20:55:35,095:2442(0x2ac228eb6700):ZOO_INFO@log_env@671: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
I1210 20:55:35.095990 2480 contender.cpp:122] Joining the ZK group with data: 'master@140.211.11.27:39024'
2013-12-10 20:55:35,096:2442(0x2ac2298bb700):ZOO_INFO@log_env@687: Client environment:user.home=/home/jenkins
2013-12-10 20:55:35,096:2442(0x2ac2298bb700):ZOO_INFO@log_env@699: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src
2013-12-10 20:55:35,096:2442(0x2ac228eb6700):ZOO_INFO@log_env@679: Client environment:user.name=(null)
2013-12-10 20:55:35,096:2442(0x2ac2298bb700):ZOO_INFO@zookeeper_init@727: Initiating client connection, host=127.0.0.1:58949 sessionTimeout=10000 watcher=0x2ac2245552d0 sessionId=0 sessionPasswd=<null> context=0x2ac2600c1190 flags=0
2013-12-10 20:55:35,096:2442(0x2ac228eb6700):ZOO_INFO@log_env@687: Client environment:user.home=/home/jenkins
2013-12-10 20:55:35,096:2442(0x2ac228eb6700):ZOO_INFO@log_env@699: Client environment:user.dir=/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src
2013-12-10 20:55:35,096:2442(0x2ac228eb6700):ZOO_INFO@zookeeper_init@727: Initiating client connection, host=127.0.0.1:58949 sessionTimeout=10000 watcher=0x2ac2245552d0 sessionId=0 sessionPasswd=<null> context=0x2ac298081b90 flags=0
2013-12-10 20:55:35,096:2442(0x2ac4b121c700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:58949]
2013-12-10 20:55:35,096:2442(0x2ac4b141d700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:58949]
2013-12-10 20:55:35,097:2442(0x2ac4b121c700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:58949], sessionId=0x142de4b1d98000a, negotiated timeout=10000
I1210 20:55:35.097123 2461 group.cpp:280] Group process ((1546)@140.211.11.27:39024) connected to ZooKeeper
I1210 20:55:35.097133 2461 group.cpp:675] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I1210 20:55:35.097138 2461 group.cpp:337] Trying to create path '/znode' in ZooKeeper
2013-12-10 20:55:35,097:2442(0x2ac4b141d700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:58949], sessionId=0x142de4b1d98000b, negotiated timeout=10000
I1210 20:55:35.097609 2466 group.cpp:280] Group process ((1548)@140.211.11.27:39024) connected to ZooKeeper
I1210 20:55:35.097623 2466 group.cpp:675] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I1210 20:55:35.097631 2466 group.cpp:337] Trying to create path '/znode' in ZooKeeper
I1210 20:55:35.099056 2463 contender.cpp:203] New candidate (id='6', data='master@140.211.11.27:39024') has entered the contest for leadership
I1210 20:55:35.099130 2474 detector.cpp:130] Detected a new leader (id='6')
I1210 20:55:35.099445 2483 detector.cpp:130] Detected a new leader (id='6')
I1210 20:55:35.099465 2474 group.cpp:562] Trying to get '/znode/0000000006' in ZooKeeper
I1210 20:55:35.099695 2468 group.cpp:562] Trying to get '/znode/0000000006' in ZooKeeper
I1210 20:55:35.099954 2463 detector.cpp:322] A new leading master (UPID=master@140.211.11.27:39024) is detected
I1210 20:55:35.100010 2464 sched.cpp:207] New master detected at master@140.211.11.27:39024
I1210 20:55:35.100030 2464 sched.cpp:260] Authenticating with master master@140.211.11.27:39024
I1210 20:55:35.100078 2464 sched.cpp:229] Detecting new master
I1210 20:55:35.100091 2484 authenticatee.hpp:124] Creating new client SASL connection
I1210 20:55:35.100225 2470 detector.cpp:130] Detected a new leader (id='6')
W1210 20:55:35.100256 2464 master.cpp:1819] Ignoring authenticate message from authenticatee(150)@140.211.11.27:39024 since not elected yet
I1210 20:55:35.100262 2466 detector.cpp:322] A new leading master (UPID=master@140.211.11.27:39024) is detected
I1210 20:55:35.100311 2463 master.cpp:746] The newly elected leader is master@140.211.11.27:39024
I1210 20:55:35.100325 2463 master.cpp:750] Elected as the leading master!
I1210 20:55:35.100368 2484 group.cpp:562] Trying to get '/znode/0000000006' in ZooKeeper
I1210 20:55:35.100739 2464 detector.cpp:322] A new leading master (UPID=master@140.211.11.27:39024) is detected
I1210 20:55:35.100785 2469 slave.cpp:497] New master detected at master@140.211.11.27:39024
I1210 20:55:35.100838 2463 status_update_manager.cpp:160] New master detected at master@140.211.11.27:39024
I1210 20:55:35.100874 2469 slave.cpp:524] Detecting new master
I1210 20:55:35.100919 2466 master.cpp:1455] Attempting to re-register slave 201312102055-453759884-39024-2442-0 at slave(136)@140.211.11.27:39024 (hemera.apache.org)
I1210 20:55:35.100932 2466 master.cpp:2628] Adding slave 201312102055-453759884-39024-2442-0 at hemera.apache.org with cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000]
I1210 20:55:35.100996 2468 slave.cpp:592] Re-registered with master master@140.211.11.27:39024
I1210 20:55:35.101009 2466 master.hpp:409] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
W1210 20:55:35.101033 2466 master.cpp:2723] Possibly orphaned task 0 of framework 201312102055-453759884-39024-2442-0000 running on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:35.101199 2482 hierarchical_allocator_process.hpp:445] Added slave 201312102055-453759884-39024-2442-0 (hemera.apache.org) with cpus(*):2; mem(*):1024; disk(*):127026; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] available)
I1210 20:55:35.101235 2482 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201312102055-453759884-39024-2442-0 in 3971ns
I1210 20:55:36.066045 2462 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:36.087582 2482 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:36.096761 2461 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 17710ns
I1210 20:55:37.068197 2461 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:37.088235 2461 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:37.097439 2461 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 18510ns
2013-12-10 20:55:37,523:2442(0x2ac500401700):ZOO_ERROR@handle_socket_error_msg@1579: Socket [127.0.0.1:33938] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I1210 20:55:38.069762 2461 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:38.088994 2473 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:38.098119 2473 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 57932ns
I1210 20:55:39.071090 2473 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:39.089685 2475 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:39.098814 2471 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 48007ns
I1210 20:55:40.073209 2475 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:40.090739 2484 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:40.095819 2483 master.cpp:84] No whitelist given. Advertising offers for all slaves
I1210 20:55:40.098955 2464 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 62043ns
W1210 20:55:40.101080 2483 sched.cpp:355] Authentication timed out
W1210 20:55:40.101202 2483 sched.cpp:315] Failed to authenticate with master master@140.211.11.27:39024: future discarded
I1210 20:55:40.101232 2483 sched.cpp:260] Authenticating with master master@140.211.11.27:39024
I1210 20:55:40.101397 2479 authenticatee.hpp:124] Creating new client SASL connection
I1210 20:55:40.101953 2479 master.cpp:1849] Authenticating framework at scheduler(131)@140.211.11.27:39024
I1210 20:55:40.102612 2475 authenticator.hpp:140] Creating new server SASL connection
I1210 20:55:40.102812 2475 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1210 20:55:40.102833 2475 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1210 20:55:40.102857 2475 authenticator.hpp:243] Received SASL authentication start
I1210 20:55:40.103025 2475 authenticator.hpp:325] Authentication requires more steps
I1210 20:55:40.103049 2475 authenticatee.hpp:258] Received SASL authentication step
I1210 20:55:40.103083 2475 authenticator.hpp:271] Received SASL authentication step
I1210 20:55:40.103211 2475 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
I1210 20:55:40.103227 2475 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1210 20:55:40.103245 2475 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1210 20:55:40.103261 2475 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
I1210 20:55:40.103271 2475 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1210 20:55:40.103278 2475 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1210 20:55:40.103296 2475 authenticator.hpp:317] Authentication success
I1210 20:55:40.103812 2475 master.cpp:1889] Successfully authenticated framework at scheduler(131)@140.211.11.27:39024
I1210 20:55:40.103819 2483 authenticatee.hpp:298] Authentication success
I1210 20:55:40.104408 2483 sched.cpp:334] Successfully authenticated with master master@140.211.11.27:39024
I1210 20:55:40.105216 2473 master.cpp:889] Re-registering framework 201312102055-453759884-39024-2442-0000 at scheduler(131)@140.211.11.27:39024
I1210 20:55:40.105681 2479 sched.cpp:383] Framework registered with 201312102055-453759884-39024-2442-0000
I1210 20:55:40.105723 2468 slave.cpp:1303] Updating framework 201312102055-453759884-39024-2442-0000 pid to scheduler(131)@140.211.11.27:39024
I1210 20:55:40.105787 2473 hierarchical_allocator_process.hpp:332] Added framework 201312102055-453759884-39024-2442-0000
I1210 20:55:40.105803 2479 sched.cpp:397] Scheduler::registered took 14583ns
I1210 20:55:40.105849 2473 hierarchical_allocator_process.hpp:752] Offering cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] on slave 201312102055-453759884-39024-2442-0 to framework 201312102055-453759884-39024-2442-0000
I1210 20:55:40.106117 2473 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 225523ns
I1210 20:55:40.106183 2480 master.hpp:437] Adding offer 201312102055-453759884-39024-2442-0 with resources cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:40.106250 2480 master.cpp:1804] Sending 1 offers to framework 201312102055-453759884-39024-2442-0000
I1210 20:55:40.106432 2472 sched.cpp:517] Scheduler::resourceOffers took 33625ns
I1210 20:55:40.106974 2442 master.cpp:556] Master terminating
I1210 20:55:40.106976 2470 sched.cpp:719] Stopping framework '201312102055-453759884-39024-2442-0000'
I1210 20:55:40.107023 2442 master.cpp:209] Shutting down master
I1210 20:55:40.107064 2481 slave.cpp:1956] master@140.211.11.27:39024 exited
W1210 20:55:40.107090 2481 slave.cpp:1959] Master disconnected! Waiting for a new master to be elected
I1210 20:55:40.107082 2442 master.hpp:427] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:40.107163 2442 master.hpp:447] Removing offer 201312102055-453759884-39024-2442-0 with resources cpus(*):1; mem(*):524; disk(*):127026; ports(*):[31000-32000] on slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:40.107215 2442 master.cpp:252] Removing slave 201312102055-453759884-39024-2442-0 (hemera.apache.org)
I1210 20:55:40.107527 2471 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):1; mem(*):500) on slave 201312102055-453759884-39024-2442-0 from framework 201312102055-453759884-39024-2442-0000
I1210 20:55:40.108193 2467 contender.cpp:172] Now cancelling the membership: 6
I1210 20:55:40.108335 2461 group.cpp:519] Trying to remove '/znode/0000000006' in ZooKeeper
2013-12-10 20:55:40,110:2442(0x2ac226ca17c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142de4b1d98000a to [127.0.0.1:58949]
I1210 20:55:40.110330 2475 detector.cpp:116] The current leader (id=6) is lost
I1210 20:55:40.110348 2475 detector.cpp:138] No new leader is elected after election
I1210 20:55:40.110489 2476 slave.cpp:518] Lost leading master
I1210 20:55:40.110509 2476 slave.cpp:524] Detecting new master
I1210 20:55:40.110868 2475 detector.cpp:116] The current leader (id=6) is lost
I1210 20:55:40.110890 2475 detector.cpp:138] No new leader is elected after election
2013-12-10 20:55:40,110:2442(0x2ac226ca17c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142de4b1d98000b to [127.0.0.1:58949]
I1210 20:55:40.111310 2462 slave.cpp:391] Slave terminating
I1210 20:55:40.111333 2462 slave.cpp:1133] Asked to shut down framework 201312102055-453759884-39024-2442-0000 by @0.0.0.0:0
W1210 20:55:40.111342 2462 slave.cpp:1141] Ignoring shutdown framework message for 201312102055-453759884-39024-2442-0000 because the slave has not yet registered with the master
I1210 20:55:40.111408 2477 exec.cpp:455] Slave exited ... shutting down
I1210 20:55:40.111456 2477 exec.cpp:472] Executor::shutdown took 19815ns
2013-12-10 20:55:40,111:2442(0x2ac226ca17c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142de4b1d980008 to [127.0.0.1:58949]
2013-12-10 20:55:40,112:2442(0x2ac226ca17c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142de4b1d980009 to [127.0.0.1:58949]
[ OK ] AllocatorZooKeeperTest/0.SlaveReregistersFirst (5041 ms)
I1210 20:55:40.113980 2442 zookeeper_test_server.cpp:93] Shutdown ZooKeeperTestServer on port 58949
[----------] 2 tests from AllocatorZooKeeperTest/0 (6071 ms total)
[----------] Global test environment tear-down
[==========] 246 tests from 43 test cases ran. (152930 ms total)
[ PASSED ] 245 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] ExamplesTest.PythonFramework
1 FAILED TEST
YOU HAVE 2 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src'
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src'
make[1]: *** [check] Error 2
make[1]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/src'
make: *** [check-recursive] Error 1
Build step 'Execute shell' marked build as failure
Jenkins build is back to normal :
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #1524
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/1524/changes>
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #1523
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/1523/changes>
Changes:
[niklas] Added stringifier.hpp to stout/Makefile.am.
[rossgit] Printed timezone, full ISO 8601, with timestamps.
[benjamin.hindman] Added min/max functions to stout which take two Options.
------------------------------------------
[...truncated 23162 lines...]
I1211 14:40:37.761520 26086 group.cpp:280] Group process ((1533)@67.195.138.60:47859) connected to ZooKeeper
I1211 14:40:37.761536 26086 group.cpp:675] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I1211 14:40:37.761545 26086 group.cpp:337] Trying to create path '/znode' in ZooKeeper
I1211 14:40:37.784162 26087 contender.cpp:203] New candidate (id='4', data='master@67.195.138.60:47859') has entered the contest for leadership
I1211 14:40:37.784337 26082 detector.cpp:130] Detected a new leader (id='4')
I1211 14:40:37.784454 26080 group.cpp:562] Trying to get '/znode/0000000004' in ZooKeeper
I1211 14:40:37.784579 26084 detector.cpp:130] Detected a new leader (id='4')
I1211 14:40:37.784664 26087 group.cpp:562] Trying to get '/znode/0000000004' in ZooKeeper
I1211 14:40:37.784806 26086 detector.cpp:130] Detected a new leader (id='4')
I1211 14:40:37.784867 26086 group.cpp:562] Trying to get '/znode/0000000004' in ZooKeeper
I1211 14:40:37.785302 26080 detector.cpp:322] A new leading master (UPID=master@67.195.138.60:47859) is detected
I1211 14:40:37.785352 26084 master.cpp:746] The newly elected leader is master@67.195.138.60:47859
I1211 14:40:37.785369 26084 master.cpp:750] Elected as the leading master!
I1211 14:40:37.785823 26084 detector.cpp:322] A new leading master (UPID=master@67.195.138.60:47859) is detected
I1211 14:40:37.785852 26087 detector.cpp:322] A new leading master (UPID=master@67.195.138.60:47859) is detected
I1211 14:40:37.785859 26084 slave.cpp:497] New master detected at master@67.195.138.60:47859
I1211 14:40:37.785888 26087 status_update_manager.cpp:160] New master detected at master@67.195.138.60:47859
I1211 14:40:37.785925 26084 slave.cpp:524] Detecting new master
I1211 14:40:37.785924 26081 sched.cpp:207] New master detected at master@67.195.138.60:47859
I1211 14:40:37.785956 26085 master.cpp:1366] Attempting to register slave on janus.apache.org at slave(136)@67.195.138.60:47859
I1211 14:40:37.785956 26081 sched.cpp:260] Authenticating with master master@67.195.138.60:47859
I1211 14:40:37.785974 26085 master.cpp:2628] Adding slave 201312111440-1015726915-47859-26059-0 at janus.apache.org with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000]
I1211 14:40:37.786031 26081 sched.cpp:229] Detecting new master
I1211 14:40:37.786038 26087 authenticatee.hpp:124] Creating new client SASL connection
I1211 14:40:37.786039 26086 slave.cpp:542] Registered with master master@67.195.138.60:47859; given slave ID 201312111440-1015726915-47859-26059-0
I1211 14:40:37.786139 26082 hierarchical_allocator_process.hpp:445] Added slave 201312111440-1015726915-47859-26059-0 (janus.apache.org) with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] available)
I1211 14:40:37.786170 26086 master.cpp:1849] Authenticating framework at scheduler(131)@67.195.138.60:47859
I1211 14:40:37.786185 26082 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201312111440-1015726915-47859-26059-0 in 9416ns
I1211 14:40:37.786239 26087 authenticator.hpp:140] Creating new server SASL connection
I1211 14:40:37.786339 26087 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1211 14:40:37.786360 26087 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1211 14:40:37.786386 26087 authenticator.hpp:243] Received SASL authentication start
I1211 14:40:37.786465 26087 authenticator.hpp:325] Authentication requires more steps
I1211 14:40:37.786491 26087 authenticatee.hpp:258] Received SASL authentication step
I1211 14:40:37.786531 26087 authenticator.hpp:271] Received SASL authentication step
I1211 14:40:37.786550 26087 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1211 14:40:37.786559 26087 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1211 14:40:37.786576 26087 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1211 14:40:37.786589 26087 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1211 14:40:37.786597 26087 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1211 14:40:37.786602 26087 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1211 14:40:37.786615 26087 authenticator.hpp:317] Authentication success
I1211 14:40:37.786653 26085 master.cpp:1889] Successfully authenticated framework at scheduler(131)@67.195.138.60:47859
I1211 14:40:37.786659 26081 authenticatee.hpp:298] Authentication success
I1211 14:40:37.786778 26081 sched.cpp:334] Successfully authenticated with master master@67.195.138.60:47859
I1211 14:40:37.786839 26087 master.cpp:801] Received registration request from scheduler(131)@67.195.138.60:47859
I1211 14:40:37.786998 26087 master.cpp:819] Registering framework 201312111440-1015726915-47859-26059-0000 at scheduler(131)@67.195.138.60:47859
I1211 14:40:37.787061 26081 sched.cpp:383] Framework registered with 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.787075 26085 hierarchical_allocator_process.hpp:332] Added framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.787091 26081 sched.cpp:397] Scheduler::registered took 14795ns
I1211 14:40:37.787114 26085 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 201312111440-1015726915-47859-26059-0 to framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.787240 26085 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 151501ns
I1211 14:40:37.787288 26084 master.hpp:437] Adding offer 201312111440-1015726915-47859-26059-0 with resources cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.787344 26084 master.cpp:1804] Sending 1 offers to framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.787606 26084 sched.cpp:517] Scheduler::resourceOffers took 173365ns
I1211 14:40:37.787706 26087 master.cpp:2141] Processing reply for offer 201312111440-1015726915-47859-26059-0 on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org) for framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.787806 26087 master.hpp:409] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.787837 26087 master.cpp:2265] Launching task 0 of framework 201312111440-1015726915-47859-26059-0000 with resources cpus(*):1; mem(*):500 on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.787905 26084 slave.cpp:727] Got assigned task 0 for framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.787992 26087 master.hpp:447] Removing offer 201312111440-1015726915-47859-26059-0 with resources cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.787994 26080 hierarchical_allocator_process.hpp:547] Framework 201312111440-1015726915-47859-26059-0000 left cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] unused on slave 201312111440-1015726915-47859-26059-0
I1211 14:40:37.788069 26084 slave.cpp:836] Launching task 0 for framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.788135 26080 hierarchical_allocator_process.hpp:590] Framework 201312111440-1015726915-47859-26059-0000 filtered slave 201312111440-1015726915-47859-26059-0 for 5secs
I1211 14:40:37.789963 26084 slave.cpp:946] Queuing task '0' for executor default of framework '201312111440-1015726915-47859-26059-0000
I1211 14:40:37.790011 26084 slave.cpp:466] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_YMHpEZ/slaves/201312111440-1015726915-47859-26059-0/frameworks/201312111440-1015726915-47859-26059-0000/executors/default/runs/53497ae9-6c56-484b-8459-28c1d2c6a5f5'
I1211 14:40:37.791718 26087 exec.cpp:178] Executor started at: executor(45)@67.195.138.60:47859 with pid 26059
I1211 14:40:37.791728 26080 slave.cpp:2089] Monitoring executor default of framework 201312111440-1015726915-47859-26059-0000 forked at pid 26059
I1211 14:40:37.791805 26080 slave.cpp:1422] Got registration for executor 'default' of framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.791982 26080 slave.cpp:1543] Flushing queued task 0 for executor 'default' of framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.791992 26086 exec.cpp:202] Executor registered on slave 201312111440-1015726915-47859-26059-0
I1211 14:40:37.793479 26086 exec.cpp:214] Executor::registered took 17231ns
I1211 14:40:37.793526 26086 exec.cpp:289] Executor asked to run task '0'
I1211 14:40:37.793562 26086 exec.cpp:298] Executor::launchTask took 22999ns
I1211 14:40:37.795044 26086 exec.cpp:521] Executor sending status update TASK_RUNNING (UUID: d28695aa-2d3e-4702-be50-a9e1be87cbae) for task 0 of framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.795112 26086 slave.cpp:1756] Handling status update TASK_RUNNING (UUID: d28695aa-2d3e-4702-be50-a9e1be87cbae) for task 0 of framework 201312111440-1015726915-47859-26059-0000 from executor(45)@67.195.138.60:47859
I1211 14:40:37.795189 26087 status_update_manager.cpp:312] Received status update TASK_RUNNING (UUID: d28695aa-2d3e-4702-be50-a9e1be87cbae) for task 0 of framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.795207 26087 status_update_manager.cpp:491] Creating StatusUpdate stream for task 0 of framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.795267 26087 status_update_manager.cpp:365] Forwarding status update TASK_RUNNING (UUID: d28695aa-2d3e-4702-be50-a9e1be87cbae) for task 0 of framework 201312111440-1015726915-47859-26059-0000 to master@67.195.138.60:47859
I1211 14:40:37.795371 26080 slave.cpp:1875] Status update manager successfully handled status update TASK_RUNNING (UUID: d28695aa-2d3e-4702-be50-a9e1be87cbae) for task 0 of framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.795388 26080 slave.cpp:1881] Sending acknowledgement for status update TASK_RUNNING (UUID: d28695aa-2d3e-4702-be50-a9e1be87cbae) for task 0 of framework 201312111440-1015726915-47859-26059-0000 to executor(45)@67.195.138.60:47859
I1211 14:40:37.795420 26086 master.cpp:1552] Status update TASK_RUNNING (UUID: d28695aa-2d3e-4702-be50-a9e1be87cbae) for task 0 of framework 201312111440-1015726915-47859-26059-0000 from slave(136)@67.195.138.60:47859
I1211 14:40:37.795446 26084 exec.cpp:335] Executor received status update acknowledgement d28695aa-2d3e-4702-be50-a9e1be87cbae for task 0 of framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.795491 26085 sched.cpp:608] Scheduler::statusUpdate took 27476ns
I1211 14:40:37.795685 26086 status_update_manager.cpp:390] Received status update acknowledgement (UUID: d28695aa-2d3e-4702-be50-a9e1be87cbae) for task 0 of framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.795718 26059 master.cpp:556] Master terminating
I1211 14:40:37.795753 26059 master.cpp:209] Shutting down master
I1211 14:40:37.795778 26082 slave.cpp:1956] master@67.195.138.60:47859 exited
W1211 14:40:37.795796 26082 slave.cpp:1959] Master disconnected! Waiting for a new master to be elected
I1211 14:40:37.795795 26059 master.hpp:427] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.795819 26082 slave.cpp:1362] Status update manager successfully handled status update acknowledgement (UUID: d28695aa-2d3e-4702-be50-a9e1be87cbae) for task 0 of framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.795881 26059 master.cpp:252] Removing slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.795912 26086 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000]) on slave 201312111440-1015726915-47859-26059-0 from framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.851781 26080 contender.cpp:172] Now cancelling the membership: 4
I1211 14:40:37.851851 26087 group.cpp:519] Trying to remove '/znode/0000000004' in ZooKeeper
2013-12-11 14:40:37,864:26059(0x2aeb257467c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142e21a2c6c0006 to [127.0.0.1:48827]
I1211 14:40:37.865260 26084 detector.cpp:116] The current leader (id=4) is lost
I1211 14:40:37.865272 26084 detector.cpp:138] No new leader is elected after election
I1211 14:40:37.865376 26087 sched.cpp:201] Scheduler::disconnected took 17402ns
I1211 14:40:37.865387 26087 sched.cpp:223] No master detected
I1211 14:40:37.865394 26087 sched.cpp:229] Detecting new master
I1211 14:40:37.865586 26082 detector.cpp:116] The current leader (id=4) is lost
I1211 14:40:37.865602 26082 detector.cpp:138] No new leader is elected after election
I1211 14:40:37.865685 26082 slave.cpp:518] Lost leading master
I1211 14:40:37.865697 26082 slave.cpp:524] Detecting new master
2013-12-11 14:40:37,865:26059(0x2aeb257467c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142e21a2c6c0007 to [127.0.0.1:48827]
I1211 14:40:37.866741 26084 master.cpp:284] Master started on 67.195.138.60:47859
I1211 14:40:37.866770 26084 master.cpp:298] Master ID: 201312111440-1015726915-47859-26059
I1211 14:40:37.866776 26084 master.cpp:301] Master only allowing authenticated frameworks to register!
I1211 14:40:37.866972 26082 master.cpp:84] No whitelist given. Advertising offers for all slaves
I1211 14:40:37.867169 26080 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@67.195.138.60:47859
I1211 14:40:37.867280 26082 contender.cpp:122] Joining the ZK group with data: 'master@67.195.138.60:47859'
2013-12-11 14:40:37,867:26059(0x2aeb25b4c700):ZOO_INFO@log_env@658: Client environment:zookeeper.version=zookeeper C client 3.3.4
2013-12-11 14:40:37,867:26059(0x2aeb25b4c700):ZOO_INFO@log_env@662: Client environment:host.name=janus
2013-12-11 14:40:37,867:26059(0x2aeb25b4c700):ZOO_INFO@log_env@669: Client environment:os.name=Linux
2013-12-11 14:40:37,867:26059(0x2aeb25b4c700):ZOO_INFO@log_env@670: Client environment:os.arch=3.2.0-57-generic
2013-12-11 14:40:37,867:26059(0x2aeb25b4c700):ZOO_INFO@log_env@671: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2013-12-11 14:40:37,867:26059(0x2aeb25f4e700):ZOO_INFO@log_env@658: Client environment:zookeeper.version=zookeeper C client 3.3.4
2013-12-11 14:40:37,867:26059(0x2aeb25f4e700):ZOO_INFO@log_env@662: Client environment:host.name=janus
2013-12-11 14:40:37,867:26059(0x2aeb25f4e700):ZOO_INFO@log_env@669: Client environment:os.name=Linux
2013-12-11 14:40:37,867:26059(0x2aeb25b4c700):ZOO_INFO@log_env@679: Client environment:user.name=(null)
2013-12-11 14:40:37,867:26059(0x2aeb25f4e700):ZOO_INFO@log_env@670: Client environment:os.arch=3.2.0-57-generic
2013-12-11 14:40:37,867:26059(0x2aeb25f4e700):ZOO_INFO@log_env@671: Client environment:os.version=#87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013
2013-12-11 14:40:37,867:26059(0x2aeb25b4c700):ZOO_INFO@log_env@687: Client environment:user.home=/home/jenkins
2013-12-11 14:40:37,867:26059(0x2aeb25b4c700):ZOO_INFO@log_env@699: Client environment:user.dir=<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src>
2013-12-11 14:40:37,867:26059(0x2aeb25b4c700):ZOO_INFO@zookeeper_init@727: Initiating client connection, host=127.0.0.1:48827 sessionTimeout=10000 watcher=0x2aeb22ffa2d0 sessionId=0 sessionPasswd=<null> context=0x2aeb4018c4d0 flags=0
2013-12-11 14:40:37,867:26059(0x2aeb25f4e700):ZOO_INFO@log_env@679: Client environment:user.name=(null)
2013-12-11 14:40:37,867:26059(0x2aeb25f4e700):ZOO_INFO@log_env@687: Client environment:user.home=/home/jenkins
2013-12-11 14:40:37,867:26059(0x2aeb25f4e700):ZOO_INFO@log_env@699: Client environment:user.dir=<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src>
2013-12-11 14:40:37,867:26059(0x2aeb25f4e700):ZOO_INFO@zookeeper_init@727: Initiating client connection, host=127.0.0.1:48827 sessionTimeout=10000 watcher=0x2aeb22ffa2d0 sessionId=0 sessionPasswd=<null> context=0x2aeb28177590 flags=0
2013-12-11 14:40:37,867:26059(0x2aecbd51a700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:48827]
2013-12-11 14:40:37,868:26059(0x2aecd8200700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:48827]
2013-12-11 14:40:37,916:26059(0x2aecbd51a700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:48827], sessionId=0x142e21a2c6c000a, negotiated timeout=10000
I1211 14:40:37.916880 26087 group.cpp:280] Group process ((1546)@67.195.138.60:47859) connected to ZooKeeper
I1211 14:40:37.916900 26087 group.cpp:675] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I1211 14:40:37.916916 26087 group.cpp:337] Trying to create path '/znode' in ZooKeeper
2013-12-11 14:40:37,917:26059(0x2aecd8200700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:48827], sessionId=0x142e21a2c6c000b, negotiated timeout=10000
I1211 14:40:37.917409 26081 group.cpp:280] Group process ((1548)@67.195.138.60:47859) connected to ZooKeeper
I1211 14:40:37.917423 26081 group.cpp:675] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I1211 14:40:37.917431 26081 group.cpp:337] Trying to create path '/znode' in ZooKeeper
I1211 14:40:37.936923 26086 contender.cpp:203] New candidate (id='6', data='master@67.195.138.60:47859') has entered the contest for leadership
I1211 14:40:37.937067 26081 detector.cpp:130] Detected a new leader (id='6')
I1211 14:40:37.937177 26081 group.cpp:562] Trying to get '/znode/0000000006' in ZooKeeper
I1211 14:40:37.937597 26083 detector.cpp:130] Detected a new leader (id='6')
I1211 14:40:37.937656 26084 detector.cpp:130] Detected a new leader (id='6')
I1211 14:40:37.937700 26080 group.cpp:562] Trying to get '/znode/0000000006' in ZooKeeper
I1211 14:40:37.937819 26084 group.cpp:562] Trying to get '/znode/0000000006' in ZooKeeper
I1211 14:40:37.938117 26081 detector.cpp:322] A new leading master (UPID=master@67.195.138.60:47859) is detected
I1211 14:40:37.938175 26083 master.cpp:746] The newly elected leader is master@67.195.138.60:47859
I1211 14:40:37.938190 26083 master.cpp:750] Elected as the leading master!
I1211 14:40:37.938348 26080 detector.cpp:322] A new leading master (UPID=master@67.195.138.60:47859) is detected
I1211 14:40:37.938446 26086 slave.cpp:497] New master detected at master@67.195.138.60:47859
I1211 14:40:37.938488 26080 status_update_manager.cpp:160] New master detected at master@67.195.138.60:47859
I1211 14:40:37.938534 26084 detector.cpp:322] A new leading master (UPID=master@67.195.138.60:47859) is detected
I1211 14:40:37.938556 26086 slave.cpp:524] Detecting new master
I1211 14:40:37.938609 26086 sched.cpp:207] New master detected at master@67.195.138.60:47859
I1211 14:40:37.938628 26086 sched.cpp:260] Authenticating with master master@67.195.138.60:47859
I1211 14:40:37.938634 26084 master.cpp:1455] Attempting to re-register slave 201312111440-1015726915-47859-26059-0 at slave(136)@67.195.138.60:47859 (janus.apache.org)
I1211 14:40:37.938649 26084 master.cpp:2628] Adding slave 201312111440-1015726915-47859-26059-0 at janus.apache.org with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000]
I1211 14:40:37.938689 26086 sched.cpp:229] Detecting new master
I1211 14:40:37.938705 26083 authenticatee.hpp:124] Creating new client SASL connection
I1211 14:40:37.938746 26086 slave.cpp:592] Re-registered with master master@67.195.138.60:47859
I1211 14:40:37.938742 26084 master.hpp:409] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
W1211 14:40:37.938784 26084 master.cpp:2723] Possibly orphaned task 0 of framework 201312111440-1015726915-47859-26059-0000 running on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.938941 26084 master.cpp:1849] Authenticating framework at scheduler(131)@67.195.138.60:47859
I1211 14:40:37.939043 26084 authenticator.hpp:140] Creating new server SASL connection
I1211 14:40:37.939041 26087 hierarchical_allocator_process.hpp:445] Added slave 201312111440-1015726915-47859-26059-0 (janus.apache.org) with cpus(*):2; mem(*):1024; disk(*):23038; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] available)
I1211 14:40:37.939081 26087 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201312111440-1015726915-47859-26059-0 in 7854ns
I1211 14:40:37.939254 26080 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1211 14:40:37.939276 26080 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1211 14:40:37.939306 26080 authenticator.hpp:243] Received SASL authentication start
I1211 14:40:37.939379 26080 authenticator.hpp:325] Authentication requires more steps
I1211 14:40:37.939406 26080 authenticatee.hpp:258] Received SASL authentication step
I1211 14:40:37.939438 26080 authenticator.hpp:271] Received SASL authentication step
I1211 14:40:37.939461 26080 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1211 14:40:37.939471 26080 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1211 14:40:37.939486 26080 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1211 14:40:37.939499 26080 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1211 14:40:37.939507 26080 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1211 14:40:37.939513 26080 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1211 14:40:37.939527 26080 authenticator.hpp:317] Authentication success
I1211 14:40:37.939554 26080 authenticatee.hpp:298] Authentication success
I1211 14:40:37.939574 26080 master.cpp:1889] Successfully authenticated framework at scheduler(131)@67.195.138.60:47859
I1211 14:40:37.939642 26080 sched.cpp:334] Successfully authenticated with master master@67.195.138.60:47859
I1211 14:40:37.939697 26080 master.cpp:889] Re-registering framework 201312111440-1015726915-47859-26059-0000 at scheduler(131)@67.195.138.60:47859
I1211 14:40:37.939904 26086 sched.cpp:383] Framework registered with 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.939954 26080 slave.cpp:1303] Updating framework 201312111440-1015726915-47859-26059-0000 pid to scheduler(131)@67.195.138.60:47859
I1211 14:40:37.939981 26086 sched.cpp:397] Scheduler::registered took 61035ns
I1211 14:40:37.939997 26083 hierarchical_allocator_process.hpp:332] Added framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.940053 26083 hierarchical_allocator_process.hpp:752] Offering cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] on slave 201312111440-1015726915-47859-26059-0 to framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.940201 26083 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 186687ns
I1211 14:40:37.940249 26080 master.hpp:437] Adding offer 201312111440-1015726915-47859-26059-0 with resources cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.940310 26080 master.cpp:1804] Sending 1 offers to framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.940424 26087 sched.cpp:517] Scheduler::resourceOffers took 24368ns
I1211 14:40:37.940608 26087 sched.cpp:719] Stopping framework '201312111440-1015726915-47859-26059-0000'
I1211 14:40:37.940613 26080 master.cpp:556] Master terminating
I1211 14:40:37.940650 26082 slave.cpp:1956] master@67.195.138.60:47859 exited
W1211 14:40:37.940665 26082 slave.cpp:1959] Master disconnected! Waiting for a new master to be elected
I1211 14:40:37.940668 26059 master.cpp:209] Shutting down master
I1211 14:40:37.940721 26059 master.hpp:427] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.940821 26059 master.hpp:447] Removing offer 201312111440-1015726915-47859-26059-0 with resources cpus(*):1; mem(*):524; disk(*):23038; ports(*):[31000-32000] on slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
I1211 14:40:37.940892 26083 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):500 (total allocatable: cpus(*):1; mem(*):500) on slave 201312111440-1015726915-47859-26059-0 from framework 201312111440-1015726915-47859-26059-0000
I1211 14:40:37.940914 26059 master.cpp:252] Removing slave 201312111440-1015726915-47859-26059-0 (janus.apache.org)
2013-12-11 14:40:37,958:26059(0x2aecf0200700):ZOO_ERROR@handle_socket_error_msg@1579: Socket [127.0.0.1:41674] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I1211 14:40:38.013669 26059 contender.cpp:172] Now cancelling the membership: 6
I1211 14:40:38.013736 26086 group.cpp:519] Trying to remove '/znode/0000000006' in ZooKeeper
2013-12-11 14:40:38,023:26059(0x2aeb257467c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142e21a2c6c000a to [127.0.0.1:48827]
I1211 14:40:38.023362 26080 detector.cpp:116] The current leader (id=6) is lost
I1211 14:40:38.023377 26080 detector.cpp:138] No new leader is elected after election
2013-12-11 14:40:38,023:26059(0x2aeb257467c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142e21a2c6c000b to [127.0.0.1:48827]
I1211 14:40:38.023794 26081 detector.cpp:116] The current leader (id=6) is lost
I1211 14:40:38.023809 26081 detector.cpp:138] No new leader is elected after election
I1211 14:40:38.023825 26080 detector.cpp:116] The current leader (id=6) is lost
I1211 14:40:38.023840 26080 detector.cpp:138] No new leader is elected after election
I1211 14:40:38.023907 26082 slave.cpp:518] Lost leading master
I1211 14:40:38.023921 26082 slave.cpp:524] Detecting new master
I1211 14:40:38.023954 26082 slave.cpp:391] Slave terminating
I1211 14:40:38.023973 26082 slave.cpp:1133] Asked to shut down framework 201312111440-1015726915-47859-26059-0000 by @0.0.0.0:0
W1211 14:40:38.023983 26082 slave.cpp:1141] Ignoring shutdown framework message for 201312111440-1015726915-47859-26059-0000 because the slave has not yet registered with the master
I1211 14:40:38.024045 26085 exec.cpp:455] Slave exited ... shutting down
I1211 14:40:38.024070 26085 exec.cpp:472] Executor::shutdown took 12294ns
2013-12-11 14:40:38,024:26059(0x2aeb257467c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142e21a2c6c0009 to [127.0.0.1:48827]
2013-12-11 14:40:38,024:26059(0x2aeb257467c0):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x142e21a2c6c0008 to [127.0.0.1:48827]
[ OK ] AllocatorZooKeeperTest/0.SlaveReregistersFirst (341 ms)
I1211 14:40:38.031440 26059 zookeeper_test_server.cpp:93] Shutdown ZooKeeperTestServer on port 48827
[----------] 2 tests from AllocatorZooKeeperTest/0 (2588 ms total)
[----------] Global test environment tear-down
[==========] 246 tests from 43 test cases ran. (204932 ms total)
[ PASSED ] 245 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] ExamplesTest.PythonFramework
1 FAILED TEST
YOU HAVE 2 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
Build step 'Execute shell' marked build as failure