You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by "Jie Yu (JIRA)" <ji...@apache.org> on 2013/11/26 19:30:35 UTC
[jira] [Created] (MESOS-846)
FaultToleranceTest.ReregisterFrameworkExitedExecutor is flaky.
Jie Yu created MESOS-846:
----------------------------
Summary: FaultToleranceTest.ReregisterFrameworkExitedExecutor is flaky.
Key: MESOS-846
URL: https://issues.apache.org/jira/browse/MESOS-846
Project: Mesos
Issue Type: Bug
Affects Versions: 0.15.0
Reporter: Jie Yu
Changes:
[vinod] Reduced the minimum number of cpus per offer to 0.1.
[vinod] Fixed status update manager to backoff on status update retries.
------------------------------------------
[...truncated 22338 lines...]
2013-11-25 22:38:15,448:27332(0x2ba1c8815700):ZOO_INFO@log_env@687: Client environment:user.home=/home/jenkins
2013-11-25 22:38:15,448:27332(0x2ba1c8815700):ZOO_INFO@log_env@699: Client environment:user.dir=<http://sfo2-aad-36-sr1.perf.twttr.net:8080/job/mesos-ubuntu-13.04-gcc/ws/src>
2013-11-25 22:38:15,448:27332(0x2ba1c8815700):ZOO_INFO@zookeeper_init@727: Initiating client connection, host=127.0.0.1:39535 sessionTimeout=10000 watcher=0x2ba1c1342ba0 sessionId=0 sessionPasswd=<null> context=0x2ba1e406afd0 flags=0
2013-11-25 22:38:15,451:27332(0x2ba1f3137700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:39535]
2013-11-25 22:38:15,452:27332(0x2ba1f2330700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:39535]
2013-11-25 22:38:15,452:27332(0x2ba1f212f700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:39535]
2013-11-25 22:38:15,453:27332(0x2ba1f2933700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:39535]
2013-11-25 22:38:15,463:27332(0x2ba1f3137700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:39535], sessionId=0x1429321286f0006, negotiated timeout=10000
I1125 22:38:15.463984 27351 group.cpp:297] Trying to create path '/znode' in ZooKeeper
2013-11-25 22:38:15,476:27332(0x2ba1f2330700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:39535], sessionId=0x1429321286f0007, negotiated timeout=10000
I1125 22:38:15.479897 27356 group.cpp:297] Trying to create path '/znode' in ZooKeeper
2013-11-25 22:38:15,483:27332(0x2ba1f212f700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:39535], sessionId=0x1429321286f0008, negotiated timeout=10000
I1125 22:38:15.484627 27355 group.cpp:297] Trying to create path '/znode' in ZooKeeper
I1125 22:38:15.487541 27352 contender.cpp:203] New candidate (id='4', data='master@127.0.1.1:49420') has entered the contest for leadership
2013-11-25 22:38:15,493:27332(0x2ba1f2933700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:39535], sessionId=0x1429321286f0009, negotiated timeout=10000
I1125 22:38:15.493517 27352 group.cpp:297] Trying to create path '/znode' in ZooKeeper
I1125 22:38:15.496569 27356 detector.cpp:130] Detected a new leader (id='4')
I1125 22:38:15.496688 27356 group.cpp:539] Trying to get '/znode/0000000004' in ZooKeeper
I1125 22:38:15.500653 27355 detector.cpp:130] Detected a new leader (id='4')
I1125 22:38:15.500761 27355 group.cpp:539] Trying to get '/znode/0000000004' in ZooKeeper
I1125 22:38:15.503913 27356 detector.cpp:322] A new leading master (UPID=master@127.0.1.1:49420) is detected
I1125 22:38:15.503964 27356 master.cpp:744] The newly elected leader is master@127.0.1.1:49420
I1125 22:38:15.503978 27356 master.cpp:748] Elected as the leading master!
I1125 22:38:15.507333 27355 detector.cpp:322] A new leading master (UPID=master@127.0.1.1:49420) is detected
I1125 22:38:15.507383 27355 slave.cpp:497] New master detected at master@127.0.1.1:49420
I1125 22:38:15.507457 27355 slave.cpp:524] Detecting new master
I1125 22:38:15.507488 27355 status_update_manager.cpp:160] New master detected at master@127.0.1.1:49420
I1125 22:38:15.507539 27355 master.cpp:1364] Attempting to register slave on raring at slave(136)@127.0.1.1:49420
I1125 22:38:15.507550 27355 master.cpp:2619] Adding slave 201311252238-16842879-49420-27332-0 at raring with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000]
I1125 22:38:15.507673 27355 slave.cpp:542] Registered with master master@127.0.1.1:49420; given slave ID 201311252238-16842879-49420-27332-0
I1125 22:38:15.507737 27355 hierarchical_allocator_process.hpp:445] Added slave 201311252238-16842879-49420-27332-0 (raring) with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] available)
I1125 22:38:15.507776 27355 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201311252238-16842879-49420-27332-0 in 9756ns
I1125 22:38:15.511750 27352 detector.cpp:130] Detected a new leader (id='4')
I1125 22:38:15.511868 27352 group.cpp:539] Trying to get '/znode/0000000004' in ZooKeeper
I1125 22:38:15.513358 27352 detector.cpp:322] A new leading master (UPID=master@127.0.1.1:49420) is detected
I1125 22:38:15.513403 27352 sched.cpp:207] New master detected at master@127.0.1.1:49420
I1125 22:38:15.513419 27352 sched.cpp:260] Authenticating with master master@127.0.1.1:49420
I1125 22:38:15.513476 27352 sched.cpp:229] Detecting new master
I1125 22:38:15.513525 27352 authenticatee.hpp:124] Creating new client SASL connection
I1125 22:38:15.513690 27352 master.cpp:1840] Authenticating framework at scheduler(131)@127.0.1.1:49420
I1125 22:38:15.513792 27352 authenticator.hpp:140] Creating new server SASL connection
I1125 22:38:15.513893 27352 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1125 22:38:15.513911 27352 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1125 22:38:15.513928 27352 authenticator.hpp:243] Received SASL authentication start
I1125 22:38:15.513978 27352 authenticator.hpp:325] Authentication requires more steps
I1125 22:38:15.513998 27352 authenticatee.hpp:258] Received SASL authentication step
I1125 22:38:15.514024 27352 authenticator.hpp:271] Received SASL authentication step
I1125 22:38:15.514039 27352 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'raring' server FQDN: 'raring' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1125 22:38:15.514047 27352 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1125 22:38:15.514058 27352 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1125 22:38:15.514067 27352 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'raring' server FQDN: 'raring' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1125 22:38:15.514073 27352 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1125 22:38:15.514077 27352 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1125 22:38:15.514088 27352 authenticator.hpp:317] Authentication success
I1125 22:38:15.514107 27352 authenticatee.hpp:298] Authentication success
I1125 22:38:15.514123 27352 master.cpp:1880] Successfully authenticated framework at scheduler(131)@127.0.1.1:49420
I1125 22:38:15.514181 27352 sched.cpp:334] Successfully authenticated with master master@127.0.1.1:49420
I1125 22:38:15.514228 27352 master.cpp:799] Received registration request from scheduler(131)@127.0.1.1:49420
I1125 22:38:15.514322 27352 master.cpp:817] Registering framework 201311252238-16842879-49420-27332-0000 at scheduler(131)@127.0.1.1:49420
I1125 22:38:15.514394 27352 sched.cpp:383] Framework registered with 201311252238-16842879-49420-27332-0000
I1125 22:38:15.514420 27352 sched.cpp:397] Scheduler::registered took 15108ns
I1125 22:38:15.514447 27352 hierarchical_allocator_process.hpp:332] Added framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.514489 27352 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave 201311252238-16842879-49420-27332-0 to framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.514581 27352 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 124021ns
I1125 22:38:15.514629 27352 master.hpp:432] Adding offer 201311252238-16842879-49420-27332-0 with resources cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:15.514667 27352 master.cpp:1801] Sending 1 offers to framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.520160 27352 sched.cpp:517] Scheduler::resourceOffers took 200980ns
I1125 22:38:15.521266 27357 master.cpp:2132] Processing reply for offer 201311252238-16842879-49420-27332-0 on slave 201311252238-16842879-49420-27332-0 (raring) for framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.521363 27357 master.hpp:404] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:15.521397 27357 master.cpp:2256] Launching task 0 of framework 201311252238-16842879-49420-27332-0000 with resources cpus(*):1; mem(*):500 on slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:15.521515 27357 master.hpp:442] Removing offer 201311252238-16842879-49420-27332-0 with resources cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] on slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:15.521584 27357 slave.cpp:722] Got assigned task 0 for framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.521733 27357 slave.cpp:833] Launching task 0 for framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.522094 27354 hierarchical_allocator_process.hpp:547] Framework 201311252238-16842879-49420-27332-0000 left cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] unused on slave 201311252238-16842879-49420-27332-0
I1125 22:38:15.522179 27354 hierarchical_allocator_process.hpp:590] Framework 201311252238-16842879-49420-27332-0000 filtered slave 201311252238-16842879-49420-27332-0 for 5secs
I1125 22:38:15.524315 27357 slave.cpp:943] Queuing task '0' for executor default of framework '201311252238-16842879-49420-27332-0000
I1125 22:38:15.528055 27357 slave.cpp:466] Successfully attached file '/tmp/AllocatorZooKeeperTest_0_SlaveReregistersFirst_QkwyzY/slaves/201311252238-16842879-49420-27332-0/frameworks/201311252238-16842879-49420-27332-0000/executors/default/runs/ba261d29-234b-4dfe-bfe3-711e0ae79f0e'
I1125 22:38:15.530829 27351 exec.cpp:178] Executor started at: executor(45)@127.0.1.1:49420 with pid 27332
I1125 22:38:15.530900 27351 slave.cpp:1411] Got registration for executor 'default' of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.531034 27351 slave.cpp:1532] Flushing queued task 0 for executor 'default' of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.531105 27351 exec.cpp:202] Executor registered on slave 201311252238-16842879-49420-27332-0
I1125 22:38:15.532032 27351 exec.cpp:214] Executor::registered took 21521ns
I1125 22:38:15.532083 27351 exec.cpp:289] Executor asked to run task '0'
I1125 22:38:15.535437 27351 exec.cpp:298] Executor::launchTask took 3.339311ms
I1125 22:38:15.537188 27351 exec.cpp:521] Executor sending status update TASK_RUNNING (UUID: 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2) for task 0 of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.539206 27358 slave.cpp:1745] Handling status update TASK_RUNNING (UUID: 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2) for task 0 of framework 201311252238-16842879-49420-27332-0000 from executor(45)@127.0.1.1:49420
I1125 22:38:15.539317 27358 status_update_manager.cpp:312] Received status update TASK_RUNNING (UUID: 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2) for task 0 of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.539331 27358 status_update_manager.cpp:491] Creating StatusUpdate stream for task 0 of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.539456 27358 status_update_manager.cpp:365] Forwarding status update TASK_RUNNING (UUID: 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2) for task 0 of framework 201311252238-16842879-49420-27332-0000 to master@127.0.1.1:49420
I1125 22:38:15.539605 27358 master.cpp:1550] Status update TASK_RUNNING (UUID: 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2) for task 0 of framework 201311252238-16842879-49420-27332-0000 from slave(136)@127.0.1.1:49420
I1125 22:38:15.539633 27358 slave.cpp:1864] Status update manager successfully handled status update TASK_RUNNING (UUID: 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2) for task 0 of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.539644 27358 slave.cpp:1870] Sending acknowledgement for status update TASK_RUNNING (UUID: 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2) for task 0 of framework 201311252238-16842879-49420-27332-0000 to executor(45)@127.0.1.1:49420
I1125 22:38:15.539719 27358 sched.cpp:608] Scheduler::statusUpdate took 23612ns
I1125 22:38:15.539827 27358 status_update_manager.cpp:390] Received status update acknowledgement (UUID: 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2) for task 0 of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.539875 27358 slave.cpp:1351] Status update manager successfully handled status update acknowledgement (UUID: 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2) for task 0 of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.540040 27332 master.cpp:554] Master terminating
I1125 22:38:15.540063 27332 master.cpp:210] Shutting down master
I1125 22:38:15.540109 27332 master.hpp:422] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:15.540204 27332 master.cpp:253] Removing slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:15.540482 27332 contender.cpp:172] Now cancelling the membership: 4
I1125 22:38:15.542873 27354 slave.cpp:1945] master@127.0.1.1:49420 exited
W1125 22:38:15.542894 27354 slave.cpp:1948] Master disconnected! Waiting for a new master to be elected
2013-11-25 22:38:15,542:27332(0x2ba1c0ac1b40):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x1429321286f0006 to [127.0.0.1:39535]
2013-11-25 22:38:15,543:27332(0x2ba1c0ac1b40):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x1429321286f0007 to [127.0.0.1:39535]
I1125 22:38:15.544715 27356 master.cpp:285] Master started on 127.0.1.1:49420
I1125 22:38:15.544747 27356 master.cpp:299] Master ID: 201311252238-16842879-49420-27332
I1125 22:38:15.544754 27356 master.cpp:302] Master only allowing authenticated frameworks to register!
I1125 22:38:15.545261 27356 master.cpp:85] No whitelist given. Advertising offers for all slaves
I1125 22:38:15.545457 27356 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@127.0.1.1:49420
I1125 22:38:15.545495 27356 contender.cpp:122] Joining the ZK group with data: 'master@127.0.1.1:49420'
2013-11-25 22:38:15,551:27332(0x2ba1c8e18700):ZOO_INFO@log_env@658: Client environment:zookeeper.version=zookeeper C client 3.3.4
2013-11-25 22:38:15,551:27332(0x2ba1c8e18700):ZOO_INFO@log_env@662: Client environment:host.name=raring
2013-11-25 22:38:15,551:27332(0x2ba1c8e18700):ZOO_INFO@log_env@669: Client environment:os.name=Linux
2013-11-25 22:38:15,551:27332(0x2ba1c8e18700):ZOO_INFO@log_env@670: Client environment:os.arch=3.8.0-33-generic
2013-11-25 22:38:15,551:27332(0x2ba1c8e18700):ZOO_INFO@log_env@671: Client environment:os.version=#48-Ubuntu SMP Wed Oct 23 09:16:58 UTC 2013
2013-11-25 22:38:15,551:27332(0x2ba1c8e18700):ZOO_INFO@log_env@679: Client environment:user.name=(null)
2013-11-25 22:38:15,551:27332(0x2ba1c8e18700):ZOO_INFO@log_env@687: Client environment:user.home=/home/jenkins
2013-11-25 22:38:15,551:27332(0x2ba1c8e18700):ZOO_INFO@log_env@699: Client environment:user.dir=<http://sfo2-aad-36-sr1.perf.twttr.net:8080/job/mesos-ubuntu-13.04-gcc/ws/src>
2013-11-25 22:38:15,551:27332(0x2ba1c8e18700):ZOO_INFO@zookeeper_init@727: Initiating client connection, host=127.0.0.1:39535 sessionTimeout=10000 watcher=0x2ba1c1342ba0 sessionId=0 sessionPasswd=<null> context=0x1583290 flags=0
2013-11-25 22:38:15,551:27332(0x2ba1c8a16700):ZOO_INFO@log_env@658: Client environment:zookeeper.version=zookeeper C client 3.3.4
2013-11-25 22:38:15,551:27332(0x2ba1c8a16700):ZOO_INFO@log_env@662: Client environment:host.name=raring
2013-11-25 22:38:15,551:27332(0x2ba1c8a16700):ZOO_INFO@log_env@669: Client environment:os.name=Linux
2013-11-25 22:38:15,551:27332(0x2ba1c8a16700):ZOO_INFO@log_env@670: Client environment:os.arch=3.8.0-33-generic
2013-11-25 22:38:15,551:27332(0x2ba1c8a16700):ZOO_INFO@log_env@671: Client environment:os.version=#48-Ubuntu SMP Wed Oct 23 09:16:58 UTC 2013
2013-11-25 22:38:15,551:27332(0x2ba1c8a16700):ZOO_INFO@log_env@679: Client environment:user.name=(null)
2013-11-25 22:38:15,551:27332(0x2ba1c8a16700):ZOO_INFO@log_env@687: Client environment:user.home=/home/jenkins
2013-11-25 22:38:15,551:27332(0x2ba1c8a16700):ZOO_INFO@log_env@699: Client environment:user.dir=<http://sfo2-aad-36-sr1.perf.twttr.net:8080/job/mesos-ubuntu-13.04-gcc/ws/src>
2013-11-25 22:38:15,551:27332(0x2ba1c8a16700):ZOO_INFO@zookeeper_init@727: Initiating client connection, host=127.0.0.1:39535 sessionTimeout=10000 watcher=0x2ba1c1342ba0 sessionId=0 sessionPasswd=<null> context=0x2ba1dc053800 flags=0
I1125 22:38:15.554348 27351 exec.cpp:335] Executor received status update acknowledgement 9c1cc30e-3e0c-4ed5-b6e2-db1ec1e82ca2 for task 0 of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:15.560539 27356 slave.cpp:2078] Monitoring executor default of framework 201311252238-16842879-49420-27332-0000 forked at pid 27332
2013-11-25 22:38:15,564:27332(0x2ba1f2f36700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:39535]
2013-11-25 22:38:15,564:27332(0x2ba1f2b34700):ZOO_INFO@check_events@1585: initiated connection to server [127.0.0.1:39535]
I1125 22:38:15.575990 27356 detector.cpp:116] The current leader (id=4) is lost
I1125 22:38:15.576020 27356 detector.cpp:138] No new leader is elected after election
I1125 22:38:15.576140 27356 slave.cpp:518] Lost leading master
I1125 22:38:15.576151 27356 slave.cpp:524] Detecting new master
I1125 22:38:15.585240 27357 detector.cpp:116] The current leader (id=4) is lost
I1125 22:38:15.585270 27357 detector.cpp:138] No new leader is elected after election
I1125 22:38:15.585400 27357 sched.cpp:201] Scheduler::disconnected took 9505ns
I1125 22:38:15.585412 27357 sched.cpp:223] No master detected
I1125 22:38:15.585417 27357 sched.cpp:229] Detecting new master
2013-11-25 22:38:15,591:27332(0x2ba1f2f36700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:39535], sessionId=0x1429321286f000a, negotiated timeout=10000
I1125 22:38:15.592154 27357 group.cpp:297] Trying to create path '/znode' in ZooKeeper
2013-11-25 22:38:15,593:27332(0x2ba1f2b34700):ZOO_INFO@check_events@1632: session establishment complete on server [127.0.0.1:39535], sessionId=0x1429321286f000b, negotiated timeout=10000
I1125 22:38:15.594601 27356 group.cpp:297] Trying to create path '/znode' in ZooKeeper
I1125 22:38:15.604816 27358 contender.cpp:203] New candidate (id='6', data='master@127.0.1.1:49420') has entered the contest for leadership
I1125 22:38:15.606328 27357 detector.cpp:130] Detected a new leader (id='6')
I1125 22:38:15.606453 27357 group.cpp:539] Trying to get '/znode/0000000006' in ZooKeeper
I1125 22:38:15.613036 27351 detector.cpp:130] Detected a new leader (id='6')
I1125 22:38:15.613184 27351 group.cpp:539] Trying to get '/znode/0000000006' in ZooKeeper
I1125 22:38:15.614622 27352 detector.cpp:130] Detected a new leader (id='6')
I1125 22:38:15.615380 27352 group.cpp:539] Trying to get '/znode/0000000006' in ZooKeeper
I1125 22:38:15.619530 27357 detector.cpp:322] A new leading master (UPID=master@127.0.1.1:49420) is detected
I1125 22:38:15.619597 27357 sched.cpp:207] New master detected at master@127.0.1.1:49420
I1125 22:38:15.619617 27357 sched.cpp:260] Authenticating with master master@127.0.1.1:49420
I1125 22:38:15.619681 27357 sched.cpp:229] Detecting new master
I1125 22:38:15.619740 27357 authenticatee.hpp:124] Creating new client SASL connection
I1125 22:38:15.619930 27357 master.cpp:1840] Authenticating framework at scheduler(131)@127.0.1.1:49420
I1125 22:38:15.620028 27357 authenticator.hpp:140] Creating new server SASL connection
I1125 22:38:15.620139 27357 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1125 22:38:15.620158 27357 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1125 22:38:15.620183 27357 authenticator.hpp:243] Received SASL authentication start
I1125 22:38:15.620235 27357 authenticator.hpp:325] Authentication requires more steps
I1125 22:38:15.620264 27357 authenticatee.hpp:258] Received SASL authentication step
I1125 22:38:15.620298 27357 authenticator.hpp:271] Received SASL authentication step
I1125 22:38:15.620316 27357 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'raring' server FQDN: 'raring' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1125 22:38:15.620323 27357 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1125 22:38:15.620336 27357 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1125 22:38:15.620343 27357 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'raring' server FQDN: 'raring' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1125 22:38:15.620349 27357 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1125 22:38:15.620354 27357 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1125 22:38:15.620364 27357 authenticator.hpp:317] Authentication success
I1125 22:38:15.620393 27357 authenticatee.hpp:298] Authentication success
I1125 22:38:15.620417 27357 master.cpp:1880] Successfully authenticated framework at scheduler(131)@127.0.1.1:49420
I1125 22:38:15.620486 27357 sched.cpp:334] Successfully authenticated with master master@127.0.1.1:49420
I1125 22:38:15.623761 27351 detector.cpp:322] A new leading master (UPID=master@127.0.1.1:49420) is detected
I1125 22:38:15.623826 27351 master.cpp:744] The newly elected leader is master@127.0.1.1:49420
I1125 22:38:15.623841 27351 master.cpp:748] Elected as the leading master!
I1125 22:38:15.624866 27352 detector.cpp:322] A new leading master (UPID=master@127.0.1.1:49420) is detected
I1125 22:38:15.625418 27352 slave.cpp:497] New master detected at master@127.0.1.1:49420
I1125 22:38:15.625553 27352 slave.cpp:524] Detecting new master
I1125 22:38:15.625594 27352 status_update_manager.cpp:160] New master detected at master@127.0.1.1:49420
I1125 22:38:15.625679 27352 master.cpp:1453] Attempting to re-register slave 201311252238-16842879-49420-27332-0 at slave(136)@127.0.1.1:49420 (raring)
I1125 22:38:15.625694 27352 master.cpp:2619] Adding slave 201311252238-16842879-49420-27332-0 at raring with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000]
I1125 22:38:15.626837 27354 slave.cpp:592] Re-registered with master master@127.0.1.1:49420
I1125 22:38:15.625794 27352 master.hpp:404] Adding task 0 with resources cpus(*):1; mem(*):500 on slave 201311252238-16842879-49420-27332-0 (raring)
W1125 22:38:15.627636 27352 master.cpp:2714] Possibly orphaned task 0 of framework 201311252238-16842879-49420-27332-0000 running on slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:15.627812 27352 hierarchical_allocator_process.hpp:445] Added slave 201311252238-16842879-49420-27332-0 (raring) with cpus(*):2; mem(*):1024; disk(*):24988; ports(*):[31000-32000] (and cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] available)
I1125 22:38:15.627856 27352 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201311252238-16842879-49420-27332-0 in 10211ns
2013-11-25 22:38:15,842:27332(0x2ba1f2d35700):ZOO_ERROR@handle_socket_error_msg@1579: Socket [127.0.0.1:51767] zk retcode=-4, errno=111(Connection refused): server refused to accept the client
I1125 22:38:16.253420 27354 monitor.cpp:193] Publishing resource usage for executor 'default' of framework '201311252238-16842879-49420-27332-0000'
I1125 22:38:16.514884 27354 master.cpp:887] Re-registering framework 201311252238-16842879-49420-27332-0000 at scheduler(131)@127.0.1.1:49420
I1125 22:38:16.515257 27354 sched.cpp:383] Framework registered with 201311252238-16842879-49420-27332-0000
I1125 22:38:16.515290 27354 sched.cpp:397] Scheduler::registered took 16770ns
I1125 22:38:16.515343 27354 slave.cpp:1292] Updating framework 201311252238-16842879-49420-27332-0000 pid to scheduler(131)@127.0.1.1:49420
I1125 22:38:16.515424 27354 hierarchical_allocator_process.hpp:332] Added framework 201311252238-16842879-49420-27332-0000
I1125 22:38:16.515468 27354 hierarchical_allocator_process.hpp:752] Offering cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] on slave 201311252238-16842879-49420-27332-0 to framework 201311252238-16842879-49420-27332-0000
I1125 22:38:16.515565 27354 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 127265ns
I1125 22:38:16.515625 27354 master.hpp:432] Adding offer 201311252238-16842879-49420-27332-0 with resources cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] on slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:16.515665 27354 master.cpp:1801] Sending 1 offers to framework 201311252238-16842879-49420-27332-0000
I1125 22:38:16.515771 27354 sched.cpp:517] Scheduler::resourceOffers took 23689ns
I1125 22:38:16.516059 27332 master.cpp:554] Master terminating
I1125 22:38:16.516083 27332 master.cpp:210] Shutting down master
I1125 22:38:16.516129 27332 master.hpp:422] Removing task 0 with resources cpus(*):1; mem(*):500 on slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:16.516191 27332 master.hpp:442] Removing offer 201311252238-16842879-49420-27332-0 with resources cpus(*):1; mem(*):524; disk(*):24988; ports(*):[31000-32000] on slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:16.516265 27332 master.cpp:253] Removing slave 201311252238-16842879-49420-27332-0 (raring)
I1125 22:38:16.516528 27332 contender.cpp:172] Now cancelling the membership: 6
I1125 22:38:16.516715 27356 slave.cpp:1945] master@127.0.1.1:49420 exited
W1125 22:38:16.516731 27356 slave.cpp:1948] Master disconnected! Waiting for a new master to be elected
2013-11-25 22:38:16,517:27332(0x2ba1c0ac1b40):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x1429321286f000b to [127.0.0.1:39535]
2013-11-25 22:38:16,518:27332(0x2ba1c0ac1b40):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x1429321286f000a to [127.0.0.1:39535]
I1125 22:38:16.520097 27332 slave.cpp:391] Slave terminating
I1125 22:38:16.520722 27332 slave.cpp:1122] Asked to shut down framework 201311252238-16842879-49420-27332-0000 by @0.0.0.0:0
I1125 22:38:16.520742 27332 slave.cpp:1147] Shutting down framework 201311252238-16842879-49420-27332-0000
I1125 22:38:16.520762 27332 slave.cpp:2411] Shutting down executor 'default' of framework 201311252238-16842879-49420-27332-0000
I1125 22:38:16.521291 27353 exec.cpp:375] Executor asked to shutdown
I1125 22:38:16.521327 27353 exec.cpp:390] Executor::shutdown took 16896ns
I1125 22:38:16.531615 27354 sched.cpp:719] Stopping framework '201311252238-16842879-49420-27332-0000'
I1125 22:38:16.547018 27357 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 31374ns
2013-11-25 22:38:16,548:27332(0x2ba1c0ac1b40):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x1429321286f0008 to [127.0.0.1:39535]
2013-11-25 22:38:16,555:27332(0x2ba1c0ac1b40):ZOO_INFO@zookeeper_close@2304: Closing zookeeper sessionId=0x1429321286f0009 to [127.0.0.1:39535]
[ OK ] AllocatorZooKeeperTest/0.SlaveReregistersFirst (1132 ms)
I1125 22:38:16.558648 27332 zookeeper_test_server.cpp:93] Shutdown ZooKeeperTestServer on port 39535
[----------] 2 tests from AllocatorZooKeeperTest/0 (3440 ms total)
[----------] Global test environment tear-down
[==========] 245 tests from 43 test cases ran. (141726 ms total)
[ PASSED ] 244 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] FaultToleranceTest.ReregisterFrameworkExitedExecutor
1 FAILED TEST
YOU HAVE 2 DISABLED TESTS
--
This message was sent by Atlassian JIRA
(v6.1#6144)