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:36:35 UTC
[jira] [Updated] (MESOS-846)
FaultToleranceTest.ReregisterFrameworkExitedExecutor is flaky.
[ https://issues.apache.org/jira/browse/MESOS-846?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jie Yu updated MESOS-846:
-------------------------
Description:
Changes:
[vinod] Reduced the minimum number of cpus per offer to 0.1.
[vinod] Fixed status update manager to backoff on status update retries.
------------------------------------------
[ RUN ] FaultToleranceTest.ReregisterFrameworkExitedExecutor
I1125 22:36:18.160614 27352 master.cpp:285] Master started on 127.0.1.1:49420
I1125 22:36:18.160640 27352 master.cpp:299] Master ID: 201311252236-16842879-49420-27332
I1125 22:36:18.160646 27352 master.cpp:302] Master only allowing authenticated frameworks to register!
I1125 22:36:18.160995 27352 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@127.0.1.1:49420
I1125 22:36:18.161031 27352 master.cpp:85] No whitelist given. Advertising offers for all slaves
I1125 22:36:18.161062 27352 master.cpp:744] The newly elected leader is master@127.0.1.1:49420
I1125 22:36:18.161073 27352 master.cpp:748] Elected as the leading master!
I1125 22:36:18.164682 27352 slave.cpp:112] Slave started on 37)@127.0.1.1:49420
I1125 22:36:18.164753 27352 slave.cpp:212] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1125 22:36:18.165174 27352 state.cpp:33] Recovering state from '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/meta'
I1125 22:36:18.165279 27352 sched.cpp:207] New master detected at master@127.0.1.1:49420
I1125 22:36:18.165297 27352 sched.cpp:260] Authenticating with master master@127.0.1.1:49420
I1125 22:36:18.165336 27352 sched.cpp:229] Detecting new master
I1125 22:36:18.165366 27352 status_update_manager.cpp:186] Recovering status update manager
I1125 22:36:18.165426 27352 authenticatee.hpp:124] Creating new client SASL connection
I1125 22:36:18.165592 27352 master.cpp:1840] Authenticating framework at scheduler(53)@127.0.1.1:49420
I1125 22:36:18.165701 27352 slave.cpp:2748] Finished recovery
I1125 22:36:18.165762 27352 authenticator.hpp:140] Creating new server SASL connection
I1125 22:36:18.165890 27352 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1125 22:36:18.165915 27352 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1125 22:36:18.165940 27352 slave.cpp:497] New master detected at master@127.0.1.1:49420
I1125 22:36:18.165981 27352 slave.cpp:524] Detecting new master
I1125 22:36:18.166015 27352 authenticator.hpp:243] Received SASL authentication start
I1125 22:36:18.166045 27352 authenticator.hpp:325] Authentication requires more steps
I1125 22:36:18.166069 27352 status_update_manager.cpp:160] New master detected at master@127.0.1.1:49420
I1125 22:36:18.166108 27352 master.cpp:1364] Attempting to register slave on raring at slave(37)@127.0.1.1:49420
I1125 22:36:18.166120 27352 master.cpp:2619] Adding slave 201311252236-16842879-49420-27332-0 at raring with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1125 22:36:18.166234 27352 authenticatee.hpp:258] Received SASL authentication step
I1125 22:36:18.166276 27352 slave.cpp:542] Registered with master master@127.0.1.1:49420; given slave ID 201311252236-16842879-49420-27332-0
I1125 22:36:18.166348 27352 hierarchical_allocator_process.hpp:445] Added slave 201311252236-16842879-49420-27332-0 (raring) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1125 22:36:18.166384 27352 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201311252236-16842879-49420-27332-0 in 5201ns
I1125 22:36:18.166410 27352 authenticator.hpp:271] Received SASL authentication step
I1125 22:36:18.166426 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:36:18.166434 27352 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1125 22:36:18.166442 27352 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1125 22:36:18.166450 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:36:18.166456 27352 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1125 22:36:18.166460 27352 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1125 22:36:18.166471 27352 authenticator.hpp:317] Authentication success
I1125 22:36:18.166504 27352 authenticatee.hpp:298] Authentication success
I1125 22:36:18.166524 27352 master.cpp:1880] Successfully authenticated framework at scheduler(53)@127.0.1.1:49420
I1125 22:36:18.166587 27352 sched.cpp:334] Successfully authenticated with master master@127.0.1.1:49420
I1125 22:36:18.166630 27352 master.cpp:799] Received registration request from scheduler(53)@127.0.1.1:49420
I1125 22:36:18.166709 27352 master.cpp:817] Registering framework 201311252236-16842879-49420-27332-0000 at scheduler(53)@127.0.1.1:49420
I1125 22:36:18.171562 27355 sched.cpp:383] Framework registered with 201311252236-16842879-49420-27332-0000
I1125 22:36:18.171588 27355 sched.cpp:397] Scheduler::registered took 8718ns
I1125 22:36:18.172461 27357 hierarchical_allocator_process.hpp:332] Added framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.172500 27357 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 to framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.172605 27357 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 123176ns
I1125 22:36:18.173145 27352 master.hpp:432] Adding offer 201311252236-16842879-49420-27332-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:18.174803 27352 master.cpp:1801] Sending 1 offers to framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.177089 27353 sched.cpp:517] Scheduler::resourceOffers took 175617ns
I1125 22:36:18.177611 27352 master.cpp:2132] Processing reply for offer 201311252236-16842879-49420-27332-0 on slave 201311252236-16842879-49420-27332-0 (raring) for framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.179319 27352 master.hpp:404] Adding task 0 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:18.180062 27352 master.cpp:2256] Launching task 0 of framework 201311252236-16842879-49420-27332-0000 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:18.180862 27357 slave.cpp:722] Got assigned task 0 for framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.180997 27357 slave.cpp:833] Launching task 0 for framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.186247 27357 slave.cpp:943] Queuing task '0' for executor default of framework '201311252236-16842879-49420-27332-0000
I1125 22:36:18.186784 27358 slave.cpp:466] Successfully attached file '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/slaves/201311252236-16842879-49420-27332-0/frameworks/201311252236-16842879-49420-27332-0000/executors/default/runs/6657cedc-9aaa-4cc8-a343-307be204d5fd'
I1125 22:36:18.187747 27355 exec.cpp:178] Executor started at: executor(12)@127.0.1.1:49420 with pid 27332
I1125 22:36:18.187790 27355 slave.cpp:1411] Got registration for executor 'default' of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.187868 27355 slave.cpp:1532] Flushing queued task 0 for executor 'default' of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.187927 27355 exec.cpp:202] Executor registered on slave 201311252236-16842879-49420-27332-0
I1125 22:36:18.188717 27355 exec.cpp:214] Executor::registered took 13513ns
I1125 22:36:18.188768 27355 exec.cpp:289] Executor asked to run task '0'
I1125 22:36:18.189280 27355 exec.cpp:298] Executor::launchTask took 497500ns
I1125 22:36:18.191086 27355 exec.cpp:521] Executor sending status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.191160 27355 slave.cpp:1745] Handling status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000 from executor(12)@127.0.1.1:49420
I1125 22:36:18.191229 27355 status_update_manager.cpp:312] Received status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.191241 27355 status_update_manager.cpp:491] Creating StatusUpdate stream for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.191270 27355 status_update_manager.cpp:365] Forwarding status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000 to master@127.0.1.1:49420
I1125 22:36:18.191336 27355 slave.cpp:1864] Status update manager successfully handled status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.191349 27355 slave.cpp:1870] Sending acknowledgement for status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000 to executor(12)@127.0.1.1:49420
I1125 22:36:18.191385 27355 exec.cpp:335] Executor received status update acknowledgement c58f6f61-4476-4bd1-a4ff-6959a2acaf4a for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.192888 27357 slave.cpp:2078] Monitoring executor default of framework 201311252236-16842879-49420-27332-0000 forked at pid 27332
I1125 22:36:18.193528 27352 master.hpp:442] Removing offer 201311252236-16842879-49420-27332-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:18.194406 27357 hierarchical_allocator_process.hpp:547] Framework 201311252236-16842879-49420-27332-0000 left cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] unused on slave 201311252236-16842879-49420-27332-0
I1125 22:36:18.195057 27357 hierarchical_allocator_process.hpp:590] Framework 201311252236-16842879-49420-27332-0000 filtered slave 201311252236-16842879-49420-27332-0 for 5secs
I1125 22:36:18.196144 27352 master.cpp:1550] Status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000 from slave(37)@127.0.1.1:49420
I1125 22:36:18.203510 27352 master.cpp:554] Master terminating
I1125 22:36:18.200878 27357 sched.cpp:608] Scheduler::statusUpdate took 4.310326ms
I1125 22:36:18.204670 27351 slave.cpp:1945] master@127.0.1.1:49420 exited
W1125 22:36:18.204689 27351 slave.cpp:1948] Master disconnected! Waiting for a new master to be elected
I1125 22:36:18.205960 27332 master.cpp:210] Shutting down master
I1125 22:36:18.206015 27332 master.hpp:422] Removing task 0 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:18.206468 27332 master.cpp:253] Removing slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:18.211899 27351 master.cpp:285] Master started on 127.0.1.1:49420
I1125 22:36:18.211942 27351 master.cpp:299] Master ID: 201311252236-16842879-49420-27332
I1125 22:36:18.211949 27351 master.cpp:302] Master only allowing authenticated frameworks to register!
I1125 22:36:18.212282 27351 slave.cpp:497] New master detected at master@127.0.1.1:49420
I1125 22:36:18.212350 27351 slave.cpp:524] Detecting new master
I1125 22:36:18.212404 27351 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@127.0.1.1:49420
I1125 22:36:18.212430 27351 master.cpp:85] No whitelist given. Advertising offers for all slaves
I1125 22:36:18.212584 27355 status_update_manager.cpp:390] Received status update acknowledgement (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:18.212635 27355 status_update_manager.cpp:160] New master detected at master@127.0.1.1:49420
W1125 22:36:18.212689 27355 master.cpp:1379] Ignoring re-register slave message from raring since not elected yet
I1125 22:36:18.212719 27355 master.cpp:744] The newly elected leader is master@127.0.1.1:49420
I1125 22:36:18.212729 27355 master.cpp:748] Elected as the leading master!
I1125 22:36:18.212769 27355 slave.cpp:1351] Status update manager successfully handled status update acknowledgement (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.166620 27354 master.cpp:1453] Attempting to re-register slave 201311252236-16842879-49420-27332-0 at slave(37)@127.0.1.1:49420 (raring)
I1125 22:36:19.166658 27354 master.cpp:2619] Adding slave 201311252236-16842879-49420-27332-0 at raring with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1125 22:36:19.166874 27354 master.hpp:404] Adding task 0 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
W1125 22:36:19.166904 27354 master.cpp:2714] Possibly orphaned task 0 of framework 201311252236-16842879-49420-27332-0000 running on slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:19.167070 27354 slave.cpp:592] Re-registered with master master@127.0.1.1:49420
I1125 22:36:19.167156 27354 hierarchical_allocator_process.hpp:445] Added slave 201311252236-16842879-49420-27332-0 (raring) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] available)
I1125 22:36:19.167196 27354 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201311252236-16842879-49420-27332-0 in 10374ns
I1125 22:36:19.167572 27354 slave.cpp:2134] Executor 'default' of framework 201311252236-16842879-49420-27332-0000 has exited with status 0
I1125 22:36:19.168340 27354 slave.cpp:1745] Handling status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000 from @0.0.0.0:0
I1125 22:36:19.168370 27354 slave.cpp:3182] Terminating task 0
I1125 22:36:19.168534 27354 status_update_manager.cpp:312] Received status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.168565 27354 status_update_manager.cpp:365] Forwarding status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000 to master@127.0.1.1:49420
I1125 22:36:19.168680 27354 master.cpp:1606] Executor default of framework 201311252236-16842879-49420-27332-0000 on slave 201311252236-16842879-49420-27332-0 (raring) has exited with status 0
I1125 22:36:19.168810 27354 slave.cpp:1864] Status update manager successfully handled status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.169783 27355 sched.cpp:201] Scheduler::disconnected took 7280ns
I1125 22:36:19.169798 27355 sched.cpp:207] New master detected at master@127.0.1.1:49420
I1125 22:36:19.169811 27355 sched.cpp:260] Authenticating with master master@127.0.1.1:49420
I1125 22:36:19.169860 27355 sched.cpp:229] Detecting new master
I1125 22:36:19.169911 27355 authenticatee.hpp:124] Creating new client SASL connection
I1125 22:36:19.170068 27355 master.cpp:1840] Authenticating framework at scheduler(53)@127.0.1.1:49420
I1125 22:36:19.170152 27355 authenticator.hpp:140] Creating new server SASL connection
I1125 22:36:19.170254 27355 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
I1125 22:36:19.170272 27355 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I1125 22:36:19.170295 27355 authenticator.hpp:243] Received SASL authentication start
I1125 22:36:19.170325 27355 authenticator.hpp:325] Authentication requires more steps
I1125 22:36:19.170349 27355 authenticatee.hpp:258] Received SASL authentication step
I1125 22:36:19.170382 27355 authenticator.hpp:271] Received SASL authentication step
I1125 22:36:19.170397 27355 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:36:19.170404 27355 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1125 22:36:19.170416 27355 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1125 22:36:19.170424 27355 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:36:19.170430 27355 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1125 22:36:19.170434 27355 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1125 22:36:19.170444 27355 authenticator.hpp:317] Authentication success
I1125 22:36:19.170470 27355 authenticatee.hpp:298] Authentication success
I1125 22:36:19.170490 27355 master.cpp:1880] Successfully authenticated framework at scheduler(53)@127.0.1.1:49420
I1125 22:36:19.170550 27355 sched.cpp:334] Successfully authenticated with master master@127.0.1.1:49420
I1125 22:36:19.170603 27355 master.cpp:887] Re-registering framework 201311252236-16842879-49420-27332-0000 at scheduler(53)@127.0.1.1:49420
I1125 22:36:19.175477 27355 sched.cpp:383] Framework registered with 201311252236-16842879-49420-27332-0000
I1125 22:36:19.175504 27355 sched.cpp:397] Scheduler::registered took 8628ns
I1125 22:36:19.175544 27355 hierarchical_allocator_process.hpp:332] Added framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.175576 27355 hierarchical_allocator_process.hpp:752] Offering cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 to framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.175662 27355 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 108398ns
I1125 22:36:19.175689 27355 slave.cpp:1292] Updating framework 201311252236-16842879-49420-27332-0000 pid to scheduler(53)@127.0.1.1:49420
I1125 22:36:19.175778 27355 master.hpp:432] Adding offer 201311252236-16842879-49420-27332-0 with resources cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:19.175818 27355 master.cpp:1801] Sending 1 offers to framework 201311252236-16842879-49420-27332-0000
W1125 22:36:19.175854 27355 status_update_manager.cpp:174] Resending status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.175865 27355 status_update_manager.cpp:365] Forwarding status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000 to master@127.0.1.1:49420
I1125 22:36:19.176014 27356 sched.cpp:517] Scheduler::resourceOffers took 8776ns
I1125 22:36:19.176688 27356 master.cpp:1550] Status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000 from slave(37)@127.0.1.1:49420
I1125 22:36:19.176760 27356 master.hpp:422] Removing task 0 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
tests/fault_tolerance_tests.cpp:1129: Failure
Mock function called more times than expected - returning directly.
Function call: statusUpdate(0x7fff52e13a90, @0x2ba1d800f7b0 72-byte object <90-2A 9B-C1 A1-2B 00-00 00-00 00-00 00-00 00-00 20-94 01-D8 A1-2B 00-00 40-92 01-D8 A1-2B 00-00 20-0E C7-00 00-00 00-00 B0-11 01-D8 A1-2B 00-00 1F-BA CA-58 10-A5 D4-41 05-00 00-00 00-00 00-00 37-00 00-00 A1-2B 00-00>)
Expected: to be called once
Actual: called twice - over-saturated and active
I1125 22:36:19.176985 27356 sched.cpp:608] Scheduler::statusUpdate took 141896ns
I1125 22:36:19.177077 27356 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):16 (total allocatable: cpus(*):1; mem(*):16) on slave 201311252236-16842879-49420-27332-0 from framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.177139 27356 status_update_manager.cpp:390] Received status update acknowledgement (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.177165 27356 status_update_manager.cpp:522] Cleaning up status update stream for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.177217 27356 slave.cpp:1351] Status update manager successfully handled status update acknowledgement (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.177230 27356 slave.cpp:3205] Completing task 0
I1125 22:36:19.177247 27356 slave.cpp:2269] Cleaning up executor 'default' of framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.177350 27356 slave.cpp:2340] Cleaning up framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.177404 27356 gc.cpp:56] Scheduling '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/slaves/201311252236-16842879-49420-27332-0/frameworks/201311252236-16842879-49420-27332-0000/executors/default/runs/6657cedc-9aaa-4cc8-a343-307be204d5fd' for gc 6.99999794793778days in the future
I1125 22:36:19.177450 27356 gc.cpp:56] Scheduling '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/slaves/201311252236-16842879-49420-27332-0/frameworks/201311252236-16842879-49420-27332-0000/executors/default' for gc 6.99999794749037days in the future
I1125 22:36:19.177479 27356 gc.cpp:56] Scheduling '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/slaves/201311252236-16842879-49420-27332-0/frameworks/201311252236-16842879-49420-27332-0000' for gc 6.99999794698963days in the future
I1125 22:36:19.177516 27356 status_update_manager.cpp:274] Closing status update streams for framework 201311252236-16842879-49420-27332-0000
I1125 22:36:19.177556 27332 master.cpp:554] Master terminating
I1125 22:36:19.177573 27332 master.cpp:210] Shutting down master
I1125 22:36:19.177605 27332 master.hpp:442] Removing offer 201311252236-16842879-49420-27332-0 with resources cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:19.177650 27332 master.cpp:253] Removing slave 201311252236-16842879-49420-27332-0 (raring)
I1125 22:36:19.177902 27332 slave.cpp:391] Slave terminating
I1125 22:36:19.178063 27332 sched.cpp:719] Stopping framework '201311252236-16842879-49420-27332-0000'
[ FAILED ] FaultToleranceTest.ReregisterFrameworkExitedExecutor (1019 ms)
...
[----------] 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
was:
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
> 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.
> ------------------------------------------
> [ RUN ] FaultToleranceTest.ReregisterFrameworkExitedExecutor
> I1125 22:36:18.160614 27352 master.cpp:285] Master started on 127.0.1.1:49420
> I1125 22:36:18.160640 27352 master.cpp:299] Master ID: 201311252236-16842879-49420-27332
> I1125 22:36:18.160646 27352 master.cpp:302] Master only allowing authenticated frameworks to register!
> I1125 22:36:18.160995 27352 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@127.0.1.1:49420
> I1125 22:36:18.161031 27352 master.cpp:85] No whitelist given. Advertising offers for all slaves
> I1125 22:36:18.161062 27352 master.cpp:744] The newly elected leader is master@127.0.1.1:49420
> I1125 22:36:18.161073 27352 master.cpp:748] Elected as the leading master!
> I1125 22:36:18.164682 27352 slave.cpp:112] Slave started on 37)@127.0.1.1:49420
> I1125 22:36:18.164753 27352 slave.cpp:212] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1125 22:36:18.165174 27352 state.cpp:33] Recovering state from '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/meta'
> I1125 22:36:18.165279 27352 sched.cpp:207] New master detected at master@127.0.1.1:49420
> I1125 22:36:18.165297 27352 sched.cpp:260] Authenticating with master master@127.0.1.1:49420
> I1125 22:36:18.165336 27352 sched.cpp:229] Detecting new master
> I1125 22:36:18.165366 27352 status_update_manager.cpp:186] Recovering status update manager
> I1125 22:36:18.165426 27352 authenticatee.hpp:124] Creating new client SASL connection
> I1125 22:36:18.165592 27352 master.cpp:1840] Authenticating framework at scheduler(53)@127.0.1.1:49420
> I1125 22:36:18.165701 27352 slave.cpp:2748] Finished recovery
> I1125 22:36:18.165762 27352 authenticator.hpp:140] Creating new server SASL connection
> I1125 22:36:18.165890 27352 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I1125 22:36:18.165915 27352 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1125 22:36:18.165940 27352 slave.cpp:497] New master detected at master@127.0.1.1:49420
> I1125 22:36:18.165981 27352 slave.cpp:524] Detecting new master
> I1125 22:36:18.166015 27352 authenticator.hpp:243] Received SASL authentication start
> I1125 22:36:18.166045 27352 authenticator.hpp:325] Authentication requires more steps
> I1125 22:36:18.166069 27352 status_update_manager.cpp:160] New master detected at master@127.0.1.1:49420
> I1125 22:36:18.166108 27352 master.cpp:1364] Attempting to register slave on raring at slave(37)@127.0.1.1:49420
> I1125 22:36:18.166120 27352 master.cpp:2619] Adding slave 201311252236-16842879-49420-27332-0 at raring with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1125 22:36:18.166234 27352 authenticatee.hpp:258] Received SASL authentication step
> I1125 22:36:18.166276 27352 slave.cpp:542] Registered with master master@127.0.1.1:49420; given slave ID 201311252236-16842879-49420-27332-0
> I1125 22:36:18.166348 27352 hierarchical_allocator_process.hpp:445] Added slave 201311252236-16842879-49420-27332-0 (raring) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I1125 22:36:18.166384 27352 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201311252236-16842879-49420-27332-0 in 5201ns
> I1125 22:36:18.166410 27352 authenticator.hpp:271] Received SASL authentication step
> I1125 22:36:18.166426 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:36:18.166434 27352 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I1125 22:36:18.166442 27352 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1125 22:36:18.166450 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:36:18.166456 27352 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1125 22:36:18.166460 27352 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1125 22:36:18.166471 27352 authenticator.hpp:317] Authentication success
> I1125 22:36:18.166504 27352 authenticatee.hpp:298] Authentication success
> I1125 22:36:18.166524 27352 master.cpp:1880] Successfully authenticated framework at scheduler(53)@127.0.1.1:49420
> I1125 22:36:18.166587 27352 sched.cpp:334] Successfully authenticated with master master@127.0.1.1:49420
> I1125 22:36:18.166630 27352 master.cpp:799] Received registration request from scheduler(53)@127.0.1.1:49420
> I1125 22:36:18.166709 27352 master.cpp:817] Registering framework 201311252236-16842879-49420-27332-0000 at scheduler(53)@127.0.1.1:49420
> I1125 22:36:18.171562 27355 sched.cpp:383] Framework registered with 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.171588 27355 sched.cpp:397] Scheduler::registered took 8718ns
> I1125 22:36:18.172461 27357 hierarchical_allocator_process.hpp:332] Added framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.172500 27357 hierarchical_allocator_process.hpp:752] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 to framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.172605 27357 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 123176ns
> I1125 22:36:18.173145 27352 master.hpp:432] Adding offer 201311252236-16842879-49420-27332-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:18.174803 27352 master.cpp:1801] Sending 1 offers to framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.177089 27353 sched.cpp:517] Scheduler::resourceOffers took 175617ns
> I1125 22:36:18.177611 27352 master.cpp:2132] Processing reply for offer 201311252236-16842879-49420-27332-0 on slave 201311252236-16842879-49420-27332-0 (raring) for framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.179319 27352 master.hpp:404] Adding task 0 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:18.180062 27352 master.cpp:2256] Launching task 0 of framework 201311252236-16842879-49420-27332-0000 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:18.180862 27357 slave.cpp:722] Got assigned task 0 for framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.180997 27357 slave.cpp:833] Launching task 0 for framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.186247 27357 slave.cpp:943] Queuing task '0' for executor default of framework '201311252236-16842879-49420-27332-0000
> I1125 22:36:18.186784 27358 slave.cpp:466] Successfully attached file '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/slaves/201311252236-16842879-49420-27332-0/frameworks/201311252236-16842879-49420-27332-0000/executors/default/runs/6657cedc-9aaa-4cc8-a343-307be204d5fd'
> I1125 22:36:18.187747 27355 exec.cpp:178] Executor started at: executor(12)@127.0.1.1:49420 with pid 27332
> I1125 22:36:18.187790 27355 slave.cpp:1411] Got registration for executor 'default' of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.187868 27355 slave.cpp:1532] Flushing queued task 0 for executor 'default' of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.187927 27355 exec.cpp:202] Executor registered on slave 201311252236-16842879-49420-27332-0
> I1125 22:36:18.188717 27355 exec.cpp:214] Executor::registered took 13513ns
> I1125 22:36:18.188768 27355 exec.cpp:289] Executor asked to run task '0'
> I1125 22:36:18.189280 27355 exec.cpp:298] Executor::launchTask took 497500ns
> I1125 22:36:18.191086 27355 exec.cpp:521] Executor sending status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.191160 27355 slave.cpp:1745] Handling status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000 from executor(12)@127.0.1.1:49420
> I1125 22:36:18.191229 27355 status_update_manager.cpp:312] Received status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.191241 27355 status_update_manager.cpp:491] Creating StatusUpdate stream for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.191270 27355 status_update_manager.cpp:365] Forwarding status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000 to master@127.0.1.1:49420
> I1125 22:36:18.191336 27355 slave.cpp:1864] Status update manager successfully handled status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.191349 27355 slave.cpp:1870] Sending acknowledgement for status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000 to executor(12)@127.0.1.1:49420
> I1125 22:36:18.191385 27355 exec.cpp:335] Executor received status update acknowledgement c58f6f61-4476-4bd1-a4ff-6959a2acaf4a for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.192888 27357 slave.cpp:2078] Monitoring executor default of framework 201311252236-16842879-49420-27332-0000 forked at pid 27332
> I1125 22:36:18.193528 27352 master.hpp:442] Removing offer 201311252236-16842879-49420-27332-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:18.194406 27357 hierarchical_allocator_process.hpp:547] Framework 201311252236-16842879-49420-27332-0000 left cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] unused on slave 201311252236-16842879-49420-27332-0
> I1125 22:36:18.195057 27357 hierarchical_allocator_process.hpp:590] Framework 201311252236-16842879-49420-27332-0000 filtered slave 201311252236-16842879-49420-27332-0 for 5secs
> I1125 22:36:18.196144 27352 master.cpp:1550] Status update TASK_RUNNING (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000 from slave(37)@127.0.1.1:49420
> I1125 22:36:18.203510 27352 master.cpp:554] Master terminating
> I1125 22:36:18.200878 27357 sched.cpp:608] Scheduler::statusUpdate took 4.310326ms
> I1125 22:36:18.204670 27351 slave.cpp:1945] master@127.0.1.1:49420 exited
> W1125 22:36:18.204689 27351 slave.cpp:1948] Master disconnected! Waiting for a new master to be elected
> I1125 22:36:18.205960 27332 master.cpp:210] Shutting down master
> I1125 22:36:18.206015 27332 master.hpp:422] Removing task 0 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:18.206468 27332 master.cpp:253] Removing slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:18.211899 27351 master.cpp:285] Master started on 127.0.1.1:49420
> I1125 22:36:18.211942 27351 master.cpp:299] Master ID: 201311252236-16842879-49420-27332
> I1125 22:36:18.211949 27351 master.cpp:302] Master only allowing authenticated frameworks to register!
> I1125 22:36:18.212282 27351 slave.cpp:497] New master detected at master@127.0.1.1:49420
> I1125 22:36:18.212350 27351 slave.cpp:524] Detecting new master
> I1125 22:36:18.212404 27351 hierarchical_allocator_process.hpp:302] Initializing hierarchical allocator process with master : master@127.0.1.1:49420
> I1125 22:36:18.212430 27351 master.cpp:85] No whitelist given. Advertising offers for all slaves
> I1125 22:36:18.212584 27355 status_update_manager.cpp:390] Received status update acknowledgement (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:18.212635 27355 status_update_manager.cpp:160] New master detected at master@127.0.1.1:49420
> W1125 22:36:18.212689 27355 master.cpp:1379] Ignoring re-register slave message from raring since not elected yet
> I1125 22:36:18.212719 27355 master.cpp:744] The newly elected leader is master@127.0.1.1:49420
> I1125 22:36:18.212729 27355 master.cpp:748] Elected as the leading master!
> I1125 22:36:18.212769 27355 slave.cpp:1351] Status update manager successfully handled status update acknowledgement (UUID: c58f6f61-4476-4bd1-a4ff-6959a2acaf4a) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.166620 27354 master.cpp:1453] Attempting to re-register slave 201311252236-16842879-49420-27332-0 at slave(37)@127.0.1.1:49420 (raring)
> I1125 22:36:19.166658 27354 master.cpp:2619] Adding slave 201311252236-16842879-49420-27332-0 at raring with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I1125 22:36:19.166874 27354 master.hpp:404] Adding task 0 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
> W1125 22:36:19.166904 27354 master.cpp:2714] Possibly orphaned task 0 of framework 201311252236-16842879-49420-27332-0000 running on slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:19.167070 27354 slave.cpp:592] Re-registered with master master@127.0.1.1:49420
> I1125 22:36:19.167156 27354 hierarchical_allocator_process.hpp:445] Added slave 201311252236-16842879-49420-27332-0 (raring) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] available)
> I1125 22:36:19.167196 27354 hierarchical_allocator_process.hpp:708] Performed allocation for slave 201311252236-16842879-49420-27332-0 in 10374ns
> I1125 22:36:19.167572 27354 slave.cpp:2134] Executor 'default' of framework 201311252236-16842879-49420-27332-0000 has exited with status 0
> I1125 22:36:19.168340 27354 slave.cpp:1745] Handling status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000 from @0.0.0.0:0
> I1125 22:36:19.168370 27354 slave.cpp:3182] Terminating task 0
> I1125 22:36:19.168534 27354 status_update_manager.cpp:312] Received status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.168565 27354 status_update_manager.cpp:365] Forwarding status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000 to master@127.0.1.1:49420
> I1125 22:36:19.168680 27354 master.cpp:1606] Executor default of framework 201311252236-16842879-49420-27332-0000 on slave 201311252236-16842879-49420-27332-0 (raring) has exited with status 0
> I1125 22:36:19.168810 27354 slave.cpp:1864] Status update manager successfully handled status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.169783 27355 sched.cpp:201] Scheduler::disconnected took 7280ns
> I1125 22:36:19.169798 27355 sched.cpp:207] New master detected at master@127.0.1.1:49420
> I1125 22:36:19.169811 27355 sched.cpp:260] Authenticating with master master@127.0.1.1:49420
> I1125 22:36:19.169860 27355 sched.cpp:229] Detecting new master
> I1125 22:36:19.169911 27355 authenticatee.hpp:124] Creating new client SASL connection
> I1125 22:36:19.170068 27355 master.cpp:1840] Authenticating framework at scheduler(53)@127.0.1.1:49420
> I1125 22:36:19.170152 27355 authenticator.hpp:140] Creating new server SASL connection
> I1125 22:36:19.170254 27355 authenticatee.hpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I1125 22:36:19.170272 27355 authenticatee.hpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1125 22:36:19.170295 27355 authenticator.hpp:243] Received SASL authentication start
> I1125 22:36:19.170325 27355 authenticator.hpp:325] Authentication requires more steps
> I1125 22:36:19.170349 27355 authenticatee.hpp:258] Received SASL authentication step
> I1125 22:36:19.170382 27355 authenticator.hpp:271] Received SASL authentication step
> I1125 22:36:19.170397 27355 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:36:19.170404 27355 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I1125 22:36:19.170416 27355 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1125 22:36:19.170424 27355 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:36:19.170430 27355 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1125 22:36:19.170434 27355 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1125 22:36:19.170444 27355 authenticator.hpp:317] Authentication success
> I1125 22:36:19.170470 27355 authenticatee.hpp:298] Authentication success
> I1125 22:36:19.170490 27355 master.cpp:1880] Successfully authenticated framework at scheduler(53)@127.0.1.1:49420
> I1125 22:36:19.170550 27355 sched.cpp:334] Successfully authenticated with master master@127.0.1.1:49420
> I1125 22:36:19.170603 27355 master.cpp:887] Re-registering framework 201311252236-16842879-49420-27332-0000 at scheduler(53)@127.0.1.1:49420
> I1125 22:36:19.175477 27355 sched.cpp:383] Framework registered with 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.175504 27355 sched.cpp:397] Scheduler::registered took 8628ns
> I1125 22:36:19.175544 27355 hierarchical_allocator_process.hpp:332] Added framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.175576 27355 hierarchical_allocator_process.hpp:752] Offering cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 to framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.175662 27355 hierarchical_allocator_process.hpp:688] Performed allocation for 1 slaves in 108398ns
> I1125 22:36:19.175689 27355 slave.cpp:1292] Updating framework 201311252236-16842879-49420-27332-0000 pid to scheduler(53)@127.0.1.1:49420
> I1125 22:36:19.175778 27355 master.hpp:432] Adding offer 201311252236-16842879-49420-27332-0 with resources cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:19.175818 27355 master.cpp:1801] Sending 1 offers to framework 201311252236-16842879-49420-27332-0000
> W1125 22:36:19.175854 27355 status_update_manager.cpp:174] Resending status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.175865 27355 status_update_manager.cpp:365] Forwarding status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000 to master@127.0.1.1:49420
> I1125 22:36:19.176014 27356 sched.cpp:517] Scheduler::resourceOffers took 8776ns
> I1125 22:36:19.176688 27356 master.cpp:1550] Status update TASK_LOST (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000 from slave(37)@127.0.1.1:49420
> I1125 22:36:19.176760 27356 master.hpp:422] Removing task 0 with resources cpus(*):1; mem(*):16 on slave 201311252236-16842879-49420-27332-0 (raring)
> tests/fault_tolerance_tests.cpp:1129: Failure
> Mock function called more times than expected - returning directly.
> Function call: statusUpdate(0x7fff52e13a90, @0x2ba1d800f7b0 72-byte object <90-2A 9B-C1 A1-2B 00-00 00-00 00-00 00-00 00-00 20-94 01-D8 A1-2B 00-00 40-92 01-D8 A1-2B 00-00 20-0E C7-00 00-00 00-00 B0-11 01-D8 A1-2B 00-00 1F-BA CA-58 10-A5 D4-41 05-00 00-00 00-00 00-00 37-00 00-00 A1-2B 00-00>)
> Expected: to be called once
> Actual: called twice - over-saturated and active
> I1125 22:36:19.176985 27356 sched.cpp:608] Scheduler::statusUpdate took 141896ns
> I1125 22:36:19.177077 27356 hierarchical_allocator_process.hpp:637] Recovered cpus(*):1; mem(*):16 (total allocatable: cpus(*):1; mem(*):16) on slave 201311252236-16842879-49420-27332-0 from framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.177139 27356 status_update_manager.cpp:390] Received status update acknowledgement (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.177165 27356 status_update_manager.cpp:522] Cleaning up status update stream for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.177217 27356 slave.cpp:1351] Status update manager successfully handled status update acknowledgement (UUID: a8573332-e4c0-4d78-b43d-456a59105fc4) for task 0 of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.177230 27356 slave.cpp:3205] Completing task 0
> I1125 22:36:19.177247 27356 slave.cpp:2269] Cleaning up executor 'default' of framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.177350 27356 slave.cpp:2340] Cleaning up framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.177404 27356 gc.cpp:56] Scheduling '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/slaves/201311252236-16842879-49420-27332-0/frameworks/201311252236-16842879-49420-27332-0000/executors/default/runs/6657cedc-9aaa-4cc8-a343-307be204d5fd' for gc 6.99999794793778days in the future
> I1125 22:36:19.177450 27356 gc.cpp:56] Scheduling '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/slaves/201311252236-16842879-49420-27332-0/frameworks/201311252236-16842879-49420-27332-0000/executors/default' for gc 6.99999794749037days in the future
> I1125 22:36:19.177479 27356 gc.cpp:56] Scheduling '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_6QBOLC/slaves/201311252236-16842879-49420-27332-0/frameworks/201311252236-16842879-49420-27332-0000' for gc 6.99999794698963days in the future
> I1125 22:36:19.177516 27356 status_update_manager.cpp:274] Closing status update streams for framework 201311252236-16842879-49420-27332-0000
> I1125 22:36:19.177556 27332 master.cpp:554] Master terminating
> I1125 22:36:19.177573 27332 master.cpp:210] Shutting down master
> I1125 22:36:19.177605 27332 master.hpp:442] Removing offer 201311252236-16842879-49420-27332-0 with resources cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] on slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:19.177650 27332 master.cpp:253] Removing slave 201311252236-16842879-49420-27332-0 (raring)
> I1125 22:36:19.177902 27332 slave.cpp:391] Slave terminating
> I1125 22:36:19.178063 27332 sched.cpp:719] Stopping framework '201311252236-16842879-49420-27332-0000'
> [ FAILED ] FaultToleranceTest.ReregisterFrameworkExitedExecutor (1019 ms)
> ...
> [----------] 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)