Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
None
-
Twitter Mesos Q1 Sprint 1
-
1
Description
Bad Run:
[ RUN ] FaultToleranceTest.SchedulerFailoverFrameworkMessage
Using temporary directory '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_f3jYkr'
I0123 18:50:11.669674 15688 leveldb.cpp:176] Opened db in 31.920683ms
I0123 18:50:11.678328 15688 leveldb.cpp:183] Compacted db in 8.580569ms
I0123 18:50:11.678455 15688 leveldb.cpp:198] Created db iterator in 38478ns
I0123 18:50:11.678478 15688 leveldb.cpp:204] Seeked to beginning of db in 3057ns
I0123 18:50:11.678489 15688 leveldb.cpp:273] Iterated through 0 keys in the db in 427ns
I0123 18:50:11.678539 15688 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0123 18:50:11.682271 15705 recover.cpp:449] Starting replica recovery
I0123 18:50:11.682634 15705 recover.cpp:475] Replica is in EMPTY status
I0123 18:50:11.684389 15708 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
I0123 18:50:11.685132 15708 recover.cpp:195] Received a recover response from a replica in EMPTY status
I0123 18:50:11.689842 15708 recover.cpp:566] Updating replica status to STARTING
I0123 18:50:11.702548 15708 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 12.484558ms
I0123 18:50:11.702615 15708 replica.cpp:323] Persisted replica status to STARTING
I0123 18:50:11.703531 15708 recover.cpp:475] Replica is in STARTING status
I0123 18:50:11.705080 15704 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
I0123 18:50:11.712587 15708 recover.cpp:195] Received a recover response from a replica in STARTING status
I0123 18:50:11.722898 15708 recover.cpp:566] Updating replica status to VOTING
I0123 18:50:11.725427 15703 master.cpp:262] Master 20150123-185011-16777343-37526-15688 (localhost.localdomain) started on 127.0.0.1:37526
W0123 18:50:11.725464 15703 master.cpp:266]
**************************************************
Master bound to loopback interface! Cannot communicate with remote schedulers or slaves. You might want to set '--ip' flag to a routable IP address.
**************************************************
I0123 18:50:11.725502 15703 master.cpp:308] Master only allowing authenticated frameworks to register
I0123 18:50:11.725513 15703 master.cpp:313] Master only allowing authenticated slaves to register
I0123 18:50:11.725543 15703 credentials.hpp:36] Loading credentials for authentication from '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_f3jYkr/credentials'
I0123 18:50:11.725774 15703 master.cpp:357] Authorization enabled
I0123 18:50:11.728428 15707 whitelist_watcher.cpp:65] No whitelist given
I0123 18:50:11.729169 15707 master.cpp:1219] The newly elected leader is master@127.0.0.1:37526 with id 20150123-185011-16777343-37526-15688
I0123 18:50:11.729200 15707 master.cpp:1232] Elected as the leading master!
I0123 18:50:11.729223 15707 master.cpp:1050] Recovering from registrar
I0123 18:50:11.729595 15706 registrar.cpp:313] Recovering registrar
I0123 18:50:11.730715 15703 hierarchical_allocator_process.hpp:285] Initialized hierarchical allocator process
I0123 18:50:11.737431 15708 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.259597ms
I0123 18:50:11.737511 15708 replica.cpp:323] Persisted replica status to VOTING
I0123 18:50:11.737768 15708 recover.cpp:580] Successfully joined the Paxos group
I0123 18:50:11.737977 15708 recover.cpp:464] Recover process terminated
I0123 18:50:11.739083 15706 log.cpp:660] Attempting to start the writer
I0123 18:50:11.741236 15706 replica.cpp:477] Replica received implicit promise request with proposal 1
I0123 18:50:11.750435 15706 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 8.813783ms
I0123 18:50:11.750514 15706 replica.cpp:345] Persisted promised to 1
I0123 18:50:11.752239 15708 coordinator.cpp:230] Coordinator attemping to fill missing position
I0123 18:50:11.754176 15706 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0123 18:50:11.763464 15706 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 8.799822ms
I0123 18:50:11.763535 15706 replica.cpp:679] Persisted action at 0
I0123 18:50:11.765697 15709 replica.cpp:511] Replica received write request for position 0
I0123 18:50:11.766293 15709 leveldb.cpp:438] Reading position from leveldb took 54028ns
I0123 18:50:11.776468 15709 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 9.789169ms
I0123 18:50:11.776561 15709 replica.cpp:679] Persisted action at 0
I0123 18:50:11.777515 15709 replica.cpp:658] Replica received learned notice for position 0
I0123 18:50:11.785459 15709 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.897242ms
I0123 18:50:11.785531 15709 replica.cpp:679] Persisted action at 0
I0123 18:50:11.785565 15709 replica.cpp:664] Replica learned NOP action at position 0
I0123 18:50:11.786633 15709 log.cpp:676] Writer started with ending position 0
I0123 18:50:11.788460 15709 leveldb.cpp:438] Reading position from leveldb took 266087ns
I0123 18:50:11.801141 15709 registrar.cpp:346] Successfully fetched the registry (0B) in 71.491072ms
I0123 18:50:11.801300 15709 registrar.cpp:445] Applied 1 operations in 41795ns; attempting to update the 'registry'
I0123 18:50:11.805186 15707 log.cpp:684] Attempting to append 136 bytes to the log
I0123 18:50:11.805454 15707 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0123 18:50:11.806677 15703 replica.cpp:511] Replica received write request for position 1
I0123 18:50:11.815621 15703 leveldb.cpp:343] Persisting action (155 bytes) to leveldb took 8.89177ms
I0123 18:50:11.815692 15703 replica.cpp:679] Persisted action at 1
I0123 18:50:11.817358 15704 replica.cpp:658] Replica received learned notice for position 1
I0123 18:50:11.825014 15704 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 7.578558ms
I0123 18:50:11.825088 15704 replica.cpp:679] Persisted action at 1
I0123 18:50:11.825124 15704 replica.cpp:664] Replica learned APPEND action at position 1
I0123 18:50:11.827008 15705 registrar.cpp:490] Successfully updated the 'registry' in 25.629952ms
I0123 18:50:11.827143 15705 registrar.cpp:376] Successfully recovered registrar
I0123 18:50:11.827517 15705 master.cpp:1077] Recovered 0 slaves from the Registry (98B) ; allowing 10mins for slaves to re-register
I0123 18:50:11.828515 15704 log.cpp:703] Attempting to truncate the log to 1
I0123 18:50:11.829074 15704 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0123 18:50:11.830546 15709 replica.cpp:511] Replica received write request for position 2
I0123 18:50:11.837752 15709 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.142431ms
I0123 18:50:11.837826 15709 replica.cpp:679] Persisted action at 2
I0123 18:50:11.839334 15709 replica.cpp:658] Replica received learned notice for position 2
I0123 18:50:11.847069 15709 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.116607ms
I0123 18:50:11.847214 15709 leveldb.cpp:401] Deleting ~1 keys from leveldb took 74008ns
I0123 18:50:11.847241 15709 replica.cpp:679] Persisted action at 2
I0123 18:50:11.847295 15709 replica.cpp:664] Replica learned TRUNCATE action at position 2
I0123 18:50:11.870337 15710 slave.cpp:173] Slave started on 94)@127.0.0.1:37526
W0123 18:50:11.870980 15710 slave.cpp:176]
**************************************************
Slave bound to loopback interface! Cannot communicate with remote master(s). You might want to set '--ip' flag to a routable IP address.
**************************************************
I0123 18:50:11.871412 15710 credentials.hpp:84] Loading credential for authentication from '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_TB8Rh3/credential'
I0123 18:50:11.871819 15710 slave.cpp:282] Slave using credential for: test-principal
I0123 18:50:11.873178 15710 slave.cpp:300] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0123 18:50:11.873620 15710 slave.cpp:329] Slave hostname: localhost.localdomain
I0123 18:50:11.873837 15710 slave.cpp:330] Slave checkpoint: false
W0123 18:50:11.874068 15710 slave.cpp:332] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I0123 18:50:11.879103 15705 state.cpp:33] Recovering state from '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_TB8Rh3/meta'
W0123 18:50:11.882972 15688 sched.cpp:1246]
**************************************************
Scheduler driver bound to loopback interface! Cannot communicate with remote master(s). You might want to set 'LIBPROCESS_IP' environment variable to use a routable IP address.
**************************************************
I0123 18:50:11.884106 15709 status_update_manager.cpp:197] Recovering status update manager
I0123 18:50:11.884703 15710 slave.cpp:3519] Finished recovery
I0123 18:50:11.892076 15704 status_update_manager.cpp:171] Pausing sending status updates
I0123 18:50:11.892590 15710 slave.cpp:613] New master detected at master@127.0.0.1:37526
I0123 18:50:11.892937 15710 slave.cpp:676] Authenticating with master master@127.0.0.1:37526
I0123 18:50:11.893165 15710 slave.cpp:681] Using default CRAM-MD5 authenticatee
I0123 18:50:11.893754 15708 authenticatee.hpp:138] Creating new client SASL connection
I0123 18:50:11.894120 15708 master.cpp:4129] Authenticating slave(94)@127.0.0.1:37526
I0123 18:50:11.894153 15708 master.cpp:4140] Using default CRAM-MD5 authenticator
I0123 18:50:11.894628 15708 authenticator.hpp:170] Creating new server SASL connection
I0123 18:50:11.894913 15708 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0123 18:50:11.894942 15708 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0123 18:50:11.895043 15708 authenticator.hpp:276] Received SASL authentication start
I0123 18:50:11.895095 15708 authenticator.hpp:398] Authentication requires more steps
I0123 18:50:11.895165 15708 authenticatee.hpp:275] Received SASL authentication step
I0123 18:50:11.895261 15708 authenticator.hpp:304] Received SASL authentication step
I0123 18:50:11.895292 15708 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0123 18:50:11.895305 15708 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0123 18:50:11.895354 15708 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0123 18:50:11.895881 15710 slave.cpp:649] Detecting new master
I0123 18:50:11.898449 15708 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0123 18:50:11.899024 15708 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0123 18:50:11.899106 15708 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0123 18:50:11.899190 15708 authenticator.hpp:390] Authentication success
I0123 18:50:11.899569 15706 authenticatee.hpp:315] Authentication success
I0123 18:50:11.902299 15706 slave.cpp:747] Successfully authenticated with master master@127.0.0.1:37526
I0123 18:50:11.902847 15706 slave.cpp:1075] Will retry registration in 19.809649ms if necessary
I0123 18:50:11.903264 15705 master.cpp:3214] Queuing up registration request from slave(94)@127.0.0.1:37526 because authentication is still in progress
I0123 18:50:11.903497 15705 master.cpp:4187] Successfully authenticated principal 'test-principal' at slave(94)@127.0.0.1:37526
I0123 18:50:11.903940 15705 master.cpp:3275] Registering slave at slave(94)@127.0.0.1:37526 (localhost.localdomain) with id 20150123-185011-16777343-37526-15688-S0
I0123 18:50:11.904398 15705 registrar.cpp:445] Applied 1 operations in 63679ns; attempting to update the 'registry'
I0123 18:50:11.917883 15688 sched.cpp:151] Version: 0.22.0
I0123 18:50:11.919347 15703 log.cpp:684] Attempting to append 315 bytes to the log
I0123 18:50:11.921039 15703 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0123 18:50:11.919992 15706 sched.cpp:248] New master detected at master@127.0.0.1:37526
I0123 18:50:11.921352 15706 sched.cpp:304] Authenticating with master master@127.0.0.1:37526
I0123 18:50:11.921408 15706 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0123 18:50:11.921773 15706 authenticatee.hpp:138] Creating new client SASL connection
I0123 18:50:11.922266 15706 master.cpp:4129] Authenticating scheduler-2cecb105-ca23-4048-9707-12b1e4422e11@127.0.0.1:37526
I0123 18:50:11.922301 15706 master.cpp:4140] Using default CRAM-MD5 authenticator
I0123 18:50:11.923928 15703 replica.cpp:511] Replica received write request for position 3
I0123 18:50:11.924285 15707 authenticator.hpp:170] Creating new server SASL connection
I0123 18:50:11.925091 15707 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0123 18:50:11.925122 15707 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0123 18:50:11.925194 15707 authenticator.hpp:276] Received SASL authentication start
I0123 18:50:11.925257 15707 authenticator.hpp:398] Authentication requires more steps
I0123 18:50:11.925325 15707 authenticatee.hpp:275] Received SASL authentication step
I0123 18:50:11.925442 15707 authenticator.hpp:304] Received SASL authentication step
I0123 18:50:11.925473 15707 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0123 18:50:11.925487 15707 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0123 18:50:11.925532 15707 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0123 18:50:11.925559 15707 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0123 18:50:11.925571 15707 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0123 18:50:11.925580 15707 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0123 18:50:11.925595 15707 authenticator.hpp:390] Authentication success
I0123 18:50:11.925695 15707 authenticatee.hpp:315] Authentication success
I0123 18:50:11.925792 15707 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-2cecb105-ca23-4048-9707-12b1e4422e11@127.0.0.1:37526
I0123 18:50:11.926127 15707 sched.cpp:392] Successfully authenticated with master master@127.0.0.1:37526
I0123 18:50:11.926154 15707 sched.cpp:515] Sending registration request to master@127.0.0.1:37526
I0123 18:50:11.926215 15707 sched.cpp:548] Will retry registration in 866.81063ms if necessary
I0123 18:50:11.926640 15707 master.cpp:1420] Received registration request for framework 'default' at scheduler-2cecb105-ca23-4048-9707-12b1e4422e11@127.0.0.1:37526
I0123 18:50:11.926960 15707 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0123 18:50:11.927691 15707 master.cpp:1484] Registering framework 20150123-185011-16777343-37526-15688-0000 (default) at scheduler-2cecb105-ca23-4048-9707-12b1e4422e11@127.0.0.1:37526
I0123 18:50:11.928292 15708 hierarchical_allocator_process.hpp:319] Added framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.928326 15708 hierarchical_allocator_process.hpp:839] No resources available to allocate!
I0123 18:50:11.928340 15708 hierarchical_allocator_process.hpp:746] Performed allocation for 0 slaves in 21080ns
I0123 18:50:11.934458 15707 sched.cpp:442] Framework registered with 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.934927 15707 sched.cpp:456] Scheduler::registered took 112885ns
I0123 18:50:11.935747 15709 slave.cpp:1075] Will retry registration in 19.609252ms if necessary
I0123 18:50:11.935981 15709 master.cpp:3263] Ignoring register slave message from slave(94)@127.0.0.1:37526 (localhost.localdomain) as admission is already in progress
I0123 18:50:11.938997 15703 leveldb.cpp:343] Persisting action (334 bytes) to leveldb took 10.171709ms
I0123 18:50:11.939049 15703 replica.cpp:679] Persisted action at 3
I0123 18:50:11.940630 15709 replica.cpp:658] Replica received learned notice for position 3
I0123 18:50:11.945473 15709 leveldb.cpp:343] Persisting action (336 bytes) to leveldb took 4.804742ms
I0123 18:50:11.945521 15709 replica.cpp:679] Persisted action at 3
I0123 18:50:11.945550 15709 replica.cpp:664] Replica learned APPEND action at position 3
I0123 18:50:11.947105 15709 registrar.cpp:490] Successfully updated the 'registry' in 42.637056ms
I0123 18:50:11.948020 15703 master.cpp:3329] Registered slave 20150123-185011-16777343-37526-15688-S0 at slave(94)@127.0.0.1:37526 (localhost.localdomain) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0123 18:50:11.948318 15703 hierarchical_allocator_process.hpp:453] Added slave 20150123-185011-16777343-37526-15688-S0 (localhost.localdomain) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0123 18:50:11.948719 15703 hierarchical_allocator_process.hpp:764] Performed allocation for slave 20150123-185011-16777343-37526-15688-S0 in 355831ns
I0123 18:50:11.948813 15703 slave.cpp:781] Registered with master master@127.0.0.1:37526; given slave ID 20150123-185011-16777343-37526-15688-S0
I0123 18:50:11.948969 15703 slave.cpp:2588] Received ping from slave-observer(92)@127.0.0.1:37526
I0123 18:50:11.949324 15703 master.cpp:4071] Sending 1 offers to framework 20150123-185011-16777343-37526-15688-0000 (default) at scheduler-2cecb105-ca23-4048-9707-12b1e4422e11@127.0.0.1:37526
I0123 18:50:11.949571 15706 status_update_manager.cpp:178] Resuming sending status updates
I0123 18:50:11.950023 15709 log.cpp:703] Attempting to truncate the log to 3
I0123 18:50:11.950810 15705 sched.cpp:605] Scheduler::resourceOffers took 135580ns
I0123 18:50:11.952793 15708 master.cpp:2677] Processing ACCEPT call for offers: [ 20150123-185011-16777343-37526-15688-O0 ] on slave 20150123-185011-16777343-37526-15688-S0 at slave(94)@127.0.0.1:37526 (localhost.localdomain) for framework 20150123-185011-16777343-37526-15688-0000 (default) at scheduler-2cecb105-ca23-4048-9707-12b1e4422e11@127.0.0.1:37526
I0123 18:50:11.952852 15708 master.cpp:2513] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins'
W0123 18:50:11.954649 15708 master.cpp:2130] Executor default for task 1 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W0123 18:50:11.954988 15708 master.cpp:2142] Executor default for task 1 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I0123 18:50:11.955579 15708 master.hpp:782] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150123-185011-16777343-37526-15688-S0 (localhost.localdomain)
I0123 18:50:11.956035 15703 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0123 18:50:11.957592 15704 replica.cpp:511] Replica received write request for position 4
I0123 18:50:11.958485 15708 master.cpp:2885] Launching task 1 of framework 20150123-185011-16777343-37526-15688-0000 (default) at scheduler-2cecb105-ca23-4048-9707-12b1e4422e11@127.0.0.1:37526 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150123-185011-16777343-37526-15688-S0 at slave(94)@127.0.0.1:37526 (localhost.localdomain)
I0123 18:50:11.960578 15706 slave.cpp:1130] Got assigned task 1 for framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.961293 15706 slave.cpp:1245] Launching task 1 for framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.964450 15704 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 6.81421ms
I0123 18:50:11.964496 15704 replica.cpp:679] Persisted action at 4
I0123 18:50:11.966328 15705 replica.cpp:658] Replica received learned notice for position 4
I0123 18:50:11.969648 15706 slave.cpp:3921] Launching executor default of framework 20150123-185011-16777343-37526-15688-0000 in work directory '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_TB8Rh3/slaves/20150123-185011-16777343-37526-15688-S0/frameworks/20150123-185011-16777343-37526-15688-0000/executors/default/runs/02536e4f-fb59-4b75-99aa-611fd7fffcb1'
I0123 18:50:11.976954 15705 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 10.584003ms
I0123 18:50:11.977078 15705 leveldb.cpp:401] Deleting ~2 keys from leveldb took 72466ns
I0123 18:50:11.977104 15705 replica.cpp:679] Persisted action at 4
I0123 18:50:11.977138 15705 replica.cpp:664] Replica learned TRUNCATE action at position 4
I0123 18:50:11.978016 15706 exec.cpp:147] Version: 0.22.0
I0123 18:50:11.978646 15710 exec.cpp:197] Executor started at: executor(50)@127.0.0.1:37526 with pid 15688
I0123 18:50:11.982480 15706 slave.cpp:1368] Queuing task '1' for executor default of framework '20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.982676 15706 slave.cpp:566] Successfully attached file '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_TB8Rh3/slaves/20150123-185011-16777343-37526-15688-S0/frameworks/20150123-185011-16777343-37526-15688-0000/executors/default/runs/02536e4f-fb59-4b75-99aa-611fd7fffcb1'
I0123 18:50:11.982770 15706 slave.cpp:1912] Got registration for executor 'default' of framework 20150123-185011-16777343-37526-15688-0000 from executor(50)@127.0.0.1:37526
I0123 18:50:11.983203 15706 slave.cpp:2031] Flushing queued task 1 for executor 'default' of framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.983505 15706 slave.cpp:2890] Monitoring executor 'default' of framework '20150123-185011-16777343-37526-15688-0000' in container '02536e4f-fb59-4b75-99aa-611fd7fffcb1'
I0123 18:50:11.983749 15706 exec.cpp:221] Executor registered on slave 20150123-185011-16777343-37526-15688-S0
I0123 18:50:11.986131 15706 exec.cpp:233] Executor::registered took 30292ns
I0123 18:50:11.989857 15706 exec.cpp:308] Executor asked to run task '1'
I0123 18:50:11.990216 15706 exec.cpp:317] Executor::launchTask took 83992ns
I0123 18:50:11.992413 15706 exec.cpp:540] Executor sending status update TASK_RUNNING (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.996598 15703 slave.cpp:2265] Handling status update TASK_RUNNING (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000 from executor(50)@127.0.0.1:37526
I0123 18:50:11.996922 15703 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.996960 15703 status_update_manager.cpp:494] Creating StatusUpdate stream for task 1 of framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.997187 15703 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000 to the slave
I0123 18:50:11.997541 15703 slave.cpp:2508] Forwarding the update TASK_RUNNING (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000 to master@127.0.0.1:37526
I0123 18:50:11.997678 15703 slave.cpp:2435] Status update manager successfully handled status update TASK_RUNNING (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.997707 15703 slave.cpp:2441] Sending acknowledgement for status update TASK_RUNNING (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000 to executor(50)@127.0.0.1:37526
I0123 18:50:11.997936 15703 master.cpp:3652] Forwarding status update TASK_RUNNING (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.998054 15703 master.cpp:3624] Status update TASK_RUNNING (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000 from slave 20150123-185011-16777343-37526-15688-S0 at slave(94)@127.0.0.1:37526 (localhost.localdomain)
I0123 18:50:11.998106 15703 master.cpp:4934] Updating the latest state of task 1 of framework 20150123-185011-16777343-37526-15688-0000 to TASK_RUNNING
I0123 18:50:11.998301 15703 sched.cpp:696] Scheduler::statusUpdate took 54363ns
I0123 18:50:11.998615 15707 master.cpp:3125] Forwarding status update acknowledgement 3887f5e3-3349-4d1d-8e18-299be6c3c294 for task 1 of framework 20150123-185011-16777343-37526-15688-0000 (default) at scheduler-2cecb105-ca23-4048-9707-12b1e4422e11@127.0.0.1:37526 to slave 20150123-185011-16777343-37526-15688-S0 at slave(94)@127.0.0.1:37526 (localhost.localdomain)
I0123 18:50:11.998867 15707 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:11.999047 15707 slave.cpp:1852] Status update manager successfully handled status update acknowledgement (UUID: 3887f5e3-3349-4d1d-8e18-299be6c3c294) for task 1 of framework 20150123-185011-16777343-37526-15688-0000
W0123 18:50:12.001930 15688 sched.cpp:1246]
**************************************************
Scheduler driver bound to loopback interface! Cannot communicate with remote master(s). You might want to set 'LIBPROCESS_IP' environment variable to use a routable IP address.
**************************************************
I0123 18:50:12.006674 15706 exec.cpp:354] Executor received status update acknowledgement 3887f5e3-3349-4d1d-8e18-299be6c3c294 for task 1 of framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:12.015889 15688 sched.cpp:151] Version: 0.22.0
I0123 18:50:12.017143 15706 sched.cpp:248] New master detected at master@127.0.0.1:37526
I0123 18:50:12.017241 15706 sched.cpp:304] Authenticating with master master@127.0.0.1:37526
I0123 18:50:12.017264 15706 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0123 18:50:12.017680 15710 authenticatee.hpp:138] Creating new client SASL connection
I0123 18:50:12.018093 15710 master.cpp:4129] Authenticating scheduler-9b22c538-3b80-4309-80bd-e4c06956dd3e@127.0.0.1:37526
I0123 18:50:12.018129 15710 master.cpp:4140] Using default CRAM-MD5 authenticator
I0123 18:50:12.018590 15710 authenticator.hpp:170] Creating new server SASL connection
I0123 18:50:12.018904 15710 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0123 18:50:12.018934 15710 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0123 18:50:12.019039 15710 authenticator.hpp:276] Received SASL authentication start
I0123 18:50:12.019101 15710 authenticator.hpp:398] Authentication requires more steps
I0123 18:50:12.019172 15710 authenticatee.hpp:275] Received SASL authentication step
I0123 18:50:12.019273 15710 authenticator.hpp:304] Received SASL authentication step
I0123 18:50:12.019304 15710 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0123 18:50:12.019316 15710 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0123 18:50:12.019364 15710 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0123 18:50:12.020604 15710 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0123 18:50:12.020859 15710 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0123 18:50:12.021114 15710 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0123 18:50:12.021402 15710 authenticator.hpp:390] Authentication success
I0123 18:50:12.021790 15705 authenticatee.hpp:315] Authentication success
I0123 18:50:12.029628 15705 sched.cpp:392] Successfully authenticated with master master@127.0.0.1:37526
I0123 18:50:12.029682 15705 sched.cpp:515] Sending registration request to master@127.0.0.1:37526
I0123 18:50:12.029784 15705 sched.cpp:548] Will retry registration in 371.903559ms if necessary
I0123 18:50:12.030015 15705 master.cpp:1525] Queuing up re-registration request for framework 20150123-185011-16777343-37526-15688-0000 (default) at scheduler-9b22c538-3b80-4309-80bd-e4c06956dd3e@127.0.0.1:37526 because authentication is still in progress
I0123 18:50:12.030215 15710 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-9b22c538-3b80-4309-80bd-e4c06956dd3e@127.0.0.1:37526
I0123 18:50:12.030539 15710 master.cpp:1557] Received re-registration request from framework 20150123-185011-16777343-37526-15688-0000 (default) at scheduler-9b22c538-3b80-4309-80bd-e4c06956dd3e@127.0.0.1:37526
I0123 18:50:12.030618 15710 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0123 18:50:12.031014 15710 master.cpp:1610] Re-registering framework 20150123-185011-16777343-37526-15688-0000 (default) at scheduler-9b22c538-3b80-4309-80bd-e4c06956dd3e@127.0.0.1:37526
I0123 18:50:12.031060 15710 master.cpp:1639] Framework 20150123-185011-16777343-37526-15688-0000 (default) at scheduler-2cecb105-ca23-4048-9707-12b1e4422e11@127.0.0.1:37526 failed over
I0123 18:50:12.031723 15703 sched.cpp:442] Framework registered with 20150123-185011-16777343-37526-15688-0000
I0123 18:50:12.031841 15703 sched.cpp:456] Scheduler::registered took 54566ns
I0123 18:50:12.032662 15709 slave.cpp:1762] Updating framework 20150123-185011-16777343-37526-15688-0000 pid to scheduler-9b22c538-3b80-4309-80bd-e4c06956dd3e@127.0.0.1:37526
I0123 18:50:12.032924 15709 status_update_manager.cpp:178] Resuming sending status updates
I0123 18:50:12.034113 15703 slave.cpp:2571] Sending message for framework 20150123-185011-16777343-37526-15688-0000 to scheduler-9b22c538-3b80-4309-80bd-e4c06956dd3e@127.0.0.1:37526
I0123 18:50:12.034302 15703 sched.cpp:782] Scheduler::frameworkMessage took 53684ns
I0123 18:50:12.034771 15688 sched.cpp:1471] Asked to stop the driver
I0123 18:50:12.034864 15688 sched.cpp:1471] Asked to stop the driver
I0123 18:50:12.034942 15688 master.cpp:654] Master terminating
W0123 18:50:12.035094 15688 master.cpp:4979] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20150123-185011-16777343-37526-15688-0000 on slave 20150123-185011-16777343-37526-15688-S0 at slave(94)@127.0.0.1:37526 (localhost.localdomain) in non-terminal state TASK_RUNNING
I0123 18:50:12.035724 15688 master.cpp:5022] Removing executor 'default' with resources of framework 20150123-185011-16777343-37526-15688-0000 on slave 20150123-185011-16777343-37526-15688-S0 at slave(94)@127.0.0.1:37526 (localhost.localdomain)
I0123 18:50:12.036705 15709 sched.cpp:808] Stopping framework '20150123-185011-16777343-37526-15688-0000'
I0123 18:50:12.036960 15709 hierarchical_allocator_process.hpp:653] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20150123-185011-16777343-37526-15688-S0 from framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:12.037048 15709 slave.cpp:2673] master@127.0.0.1:37526 exited
W0123 18:50:12.037071 15709 slave.cpp:2676] Master disconnected! Waiting for a new master to be elected
I0123 18:50:12.037359 15710 sched.cpp:788] Ignoring error message because the driver is not running!
I0123 18:50:12.037513 15710 sched.cpp:808] Stopping framework '20150123-185011-16777343-37526-15688-0000'
I0123 18:50:12.076481 15688 slave.cpp:495] Slave terminating
I0123 18:50:12.080759 15688 slave.cpp:1585] Asked to shut down framework 20150123-185011-16777343-37526-15688-0000 by @0.0.0.0:0
I0123 18:50:12.081023 15688 slave.cpp:1610] Shutting down framework 20150123-185011-16777343-37526-15688-0000
I0123 18:50:12.081351 15688 slave.cpp:3198] Shutting down executor 'default' of framework 20150123-185011-16777343-37526-15688-0000
tests/fault_tolerance_tests.cpp:1383: Failure
Actual function call count doesn't match EXPECT_CALL(sched1, error(&driver1, "Framework failed over"))...
Expected: to be called once
Actual: never called - unsatisfied and active
[ FAILED ] FaultToleranceTest.SchedulerFailoverFrameworkMessage (481 ms)
Good Run:
[ RUN ] FaultToleranceTest.SchedulerFailoverFrameworkMessage Using temporary directory '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_hEc3n7' I0122 19:15:01.356081 3518 leveldb.cpp:176] Opened db in 19.797885ms I0122 19:15:01.362119 3518 leveldb.cpp:183] Compacted db in 5.953605ms I0122 19:15:01.362191 3518 leveldb.cpp:198] Created db iterator in 30691ns I0122 19:15:01.362210 3518 leveldb.cpp:204] Seeked to beginning of db in 2240ns I0122 19:15:01.362221 3518 leveldb.cpp:273] Iterated through 0 keys in the db in 517ns I0122 19:15:01.362295 3518 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0122 19:15:01.364575 3534 recover.cpp:449] Starting replica recovery I0122 19:15:01.365314 3534 recover.cpp:475] Replica is in EMPTY status I0122 19:15:01.389731 3534 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request I0122 19:15:01.390005 3534 recover.cpp:195] Received a recover response from a replica in EMPTY status I0122 19:15:01.391346 3538 recover.cpp:566] Updating replica status to STARTING I0122 19:15:01.403445 3538 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 11.806565ms I0122 19:15:01.403795 3538 replica.cpp:323] Persisted replica status to STARTING I0122 19:15:01.406898 3538 recover.cpp:475] Replica is in STARTING status I0122 19:15:01.408671 3537 replica.cpp:641] Replica in STARTING status received a broadcasted recover request I0122 19:15:01.413719 3537 recover.cpp:195] Received a recover response from a replica in STARTING status I0122 19:15:01.419553 3538 recover.cpp:566] Updating replica status to VOTING I0122 19:15:01.426426 3536 master.cpp:262] Master 20150122-191501-16777343-50172-3518 (localhost.localdomain) started on 127.0.0.1:50172 W0122 19:15:01.426473 3536 master.cpp:266] ************************************************** Master bound to loopback interface! Cannot communicate with remote schedulers or slaves. You might want to set '--ip' flag to a routable IP address. ************************************************** I0122 19:15:01.426519 3536 master.cpp:308] Master only allowing authenticated frameworks to register I0122 19:15:01.426532 3536 master.cpp:313] Master only allowing authenticated slaves to register I0122 19:15:01.426564 3536 credentials.hpp:36] Loading credentials for authentication from '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_hEc3n7/credentials' I0122 19:15:01.426841 3536 master.cpp:357] Authorization enabled I0122 19:15:01.428205 3533 hierarchical_allocator_process.hpp:285] Initialized hierarchical allocator process I0122 19:15:01.428627 3534 whitelist_watcher.cpp:65] No whitelist given I0122 19:15:01.429839 3538 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 6.340373ms I0122 19:15:01.429879 3538 replica.cpp:323] Persisted replica status to VOTING I0122 19:15:01.430024 3538 recover.cpp:580] Successfully joined the Paxos group I0122 19:15:01.430233 3538 recover.cpp:464] Recover process terminated I0122 19:15:01.432348 3536 master.cpp:1219] The newly elected leader is master@127.0.0.1:50172 with id 20150122-191501-16777343-50172-3518 I0122 19:15:01.436343 3536 master.cpp:1232] Elected as the leading master! I0122 19:15:01.436738 3536 master.cpp:1050] Recovering from registrar I0122 19:15:01.437191 3535 registrar.cpp:313] Recovering registrar I0122 19:15:01.438340 3535 log.cpp:660] Attempting to start the writer I0122 19:15:01.440163 3533 replica.cpp:477] Replica received implicit promise request with proposal 1 I0122 19:15:01.445287 3533 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 4.550707ms I0122 19:15:01.445327 3533 replica.cpp:345] Persisted promised to 1 I0122 19:15:01.446691 3537 coordinator.cpp:230] Coordinator attemping to fill missing position I0122 19:15:01.448724 3537 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2 I0122 19:15:01.453824 3537 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 4.787009ms I0122 19:15:01.453860 3537 replica.cpp:679] Persisted action at 0 I0122 19:15:01.455684 3533 replica.cpp:511] Replica received write request for position 0 I0122 19:15:01.456087 3533 leveldb.cpp:438] Reading position from leveldb took 37133ns I0122 19:15:01.460862 3533 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 4.458448ms I0122 19:15:01.460897 3533 replica.cpp:679] Persisted action at 0 I0122 19:15:01.461601 3533 replica.cpp:658] Replica received learned notice for position 0 I0122 19:15:01.466660 3533 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.028194ms I0122 19:15:01.466696 3533 replica.cpp:679] Persisted action at 0 I0122 19:15:01.466718 3533 replica.cpp:664] Replica learned NOP action at position 0 I0122 19:15:01.467931 3537 log.cpp:676] Writer started with ending position 0 I0122 19:15:01.469182 3537 leveldb.cpp:438] Reading position from leveldb took 32199ns I0122 19:15:01.479857 3537 registrar.cpp:346] Successfully fetched the registry (0B) in 42.6048ms I0122 19:15:01.480340 3537 registrar.cpp:445] Applied 1 operations in 42179ns; attempting to update the 'registry' I0122 19:15:01.484465 3535 log.cpp:684] Attempting to append 134 bytes to the log I0122 19:15:01.484661 3535 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1 I0122 19:15:01.486250 3535 replica.cpp:511] Replica received write request for position 1 I0122 19:15:01.491243 3535 leveldb.cpp:343] Persisting action (153 bytes) to leveldb took 4.582496ms I0122 19:15:01.491296 3535 replica.cpp:679] Persisted action at 1 I0122 19:15:01.492647 3539 replica.cpp:658] Replica received learned notice for position 1 I0122 19:15:01.497707 3539 leveldb.cpp:343] Persisting action (155 bytes) to leveldb took 5.027112ms I0122 19:15:01.497743 3539 replica.cpp:679] Persisted action at 1 I0122 19:15:01.497767 3539 replica.cpp:664] Replica learned APPEND action at position 1 I0122 19:15:01.499428 3539 registrar.cpp:490] Successfully updated the 'registry' in 18.743808ms I0122 19:15:01.499609 3535 log.cpp:703] Attempting to truncate the log to 1 I0122 19:15:01.500036 3535 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2 I0122 19:15:01.501029 3535 replica.cpp:511] Replica received write request for position 2 I0122 19:15:01.501694 3539 registrar.cpp:376] Successfully recovered registrar I0122 19:15:01.502358 3536 master.cpp:1077] Recovered 0 slaves from the Registry (97B) ; allowing 10mins for slaves to re-register I0122 19:15:01.514142 3535 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 13.074759ms I0122 19:15:01.514189 3535 replica.cpp:679] Persisted action at 2 I0122 19:15:01.515473 3535 replica.cpp:658] Replica received learned notice for position 2 I0122 19:15:01.527171 3535 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 11.064363ms I0122 19:15:01.527456 3535 leveldb.cpp:401] Deleting ~1 keys from leveldb took 118227ns I0122 19:15:01.527495 3535 replica.cpp:679] Persisted action at 2 I0122 19:15:01.527537 3535 replica.cpp:664] Replica learned TRUNCATE action at position 2 I0122 19:15:01.563684 3538 slave.cpp:173] Slave started on 76)@127.0.0.1:50172 W0122 19:15:01.563736 3538 slave.cpp:176] ************************************************** Slave bound to loopback interface! Cannot communicate with remote master(s). You might want to set '--ip' flag to a routable IP address. ************************************************** I0122 19:15:01.563751 3538 credentials.hpp:84] Loading credential for authentication from '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_XZCq6R/credential' I0122 19:15:01.563921 3538 slave.cpp:282] Slave using credential for: test-principal I0122 19:15:01.564209 3538 slave.cpp:300] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0122 19:15:01.564327 3538 slave.cpp:329] Slave hostname: localhost.localdomain I0122 19:15:01.564348 3538 slave.cpp:330] Slave checkpoint: false W0122 19:15:01.564357 3538 slave.cpp:332] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag I0122 19:15:01.566193 3537 state.cpp:33] Recovering state from '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_XZCq6R/meta' I0122 19:15:01.566629 3537 status_update_manager.cpp:197] Recovering status update manager I0122 19:15:01.566962 3537 slave.cpp:3519] Finished recovery I0122 19:15:01.571022 3533 status_update_manager.cpp:171] Pausing sending status updates I0122 19:15:01.571466 3537 slave.cpp:613] New master detected at master@127.0.0.1:50172 I0122 19:15:01.573503 3537 slave.cpp:676] Authenticating with master master@127.0.0.1:50172 I0122 19:15:01.573771 3537 slave.cpp:681] Using default CRAM-MD5 authenticatee I0122 19:15:01.574427 3540 authenticatee.hpp:138] Creating new client SASL connection I0122 19:15:01.574857 3535 master.cpp:4129] Authenticating slave(76)@127.0.0.1:50172 I0122 19:15:01.574893 3535 master.cpp:4140] Using default CRAM-MD5 authenticator W0122 19:15:01.575266 3518 sched.cpp:1246] ************************************************** Scheduler driver bound to loopback interface! Cannot communicate with remote master(s). You might want to set 'LIBPROCESS_IP' environment variable to use a routable IP address. ************************************************** I0122 19:15:01.576125 3535 authenticator.hpp:170] Creating new server SASL connection I0122 19:15:01.576526 3535 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5 I0122 19:15:01.576563 3535 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5' I0122 19:15:01.576671 3535 authenticator.hpp:276] Received SASL authentication start I0122 19:15:01.576740 3535 authenticator.hpp:398] Authentication requires more steps I0122 19:15:01.576812 3535 authenticatee.hpp:275] Received SASL authentication step I0122 19:15:01.576915 3535 authenticator.hpp:304] Received SASL authentication step I0122 19:15:01.576943 3535 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0122 19:15:01.576967 3535 auxprop.cpp:171] Looking up auxiliary property '*userPassword' I0122 19:15:01.577026 3535 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0122 19:15:01.577061 3535 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0122 19:15:01.577076 3535 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0122 19:15:01.577085 3535 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0122 19:15:01.577101 3535 authenticator.hpp:390] Authentication success I0122 19:15:01.577209 3535 authenticatee.hpp:315] Authentication success I0122 19:15:01.577304 3535 master.cpp:4187] Successfully authenticated principal 'test-principal' at slave(76)@127.0.0.1:50172 I0122 19:15:01.577615 3537 slave.cpp:649] Detecting new master I0122 19:15:01.580585 3537 slave.cpp:747] Successfully authenticated with master master@127.0.0.1:50172 I0122 19:15:01.585831 3537 slave.cpp:1075] Will retry registration in 18.23486ms if necessary I0122 19:15:01.588697 3535 master.cpp:3275] Registering slave at slave(76)@127.0.0.1:50172 (localhost.localdomain) with id 20150122-191501-16777343-50172-3518-S0 I0122 19:15:01.589609 3539 registrar.cpp:445] Applied 1 operations in 117629ns; attempting to update the 'registry' I0122 19:15:01.592538 3536 log.cpp:684] Attempting to append 313 bytes to the log I0122 19:15:01.592766 3536 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3 I0122 19:15:01.594276 3536 replica.cpp:511] Replica received write request for position 3 I0122 19:15:01.599052 3518 sched.cpp:151] Version: 0.22.0 I0122 19:15:01.600783 3533 sched.cpp:248] New master detected at master@127.0.0.1:50172 I0122 19:15:01.600873 3533 sched.cpp:304] Authenticating with master master@127.0.0.1:50172 I0122 19:15:01.600896 3533 sched.cpp:311] Using default CRAM-MD5 authenticatee I0122 19:15:01.601238 3533 authenticatee.hpp:138] Creating new client SASL connection I0122 19:15:01.601773 3534 master.cpp:4129] Authenticating scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 I0122 19:15:01.601809 3534 master.cpp:4140] Using default CRAM-MD5 authenticator I0122 19:15:01.602197 3534 authenticator.hpp:170] Creating new server SASL connection I0122 19:15:01.602519 3534 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5 I0122 19:15:01.602548 3534 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5' I0122 19:15:01.602651 3534 authenticator.hpp:276] Received SASL authentication start I0122 19:15:01.602705 3534 authenticator.hpp:398] Authentication requires more steps I0122 19:15:01.602774 3534 authenticatee.hpp:275] Received SASL authentication step I0122 19:15:01.602854 3534 authenticator.hpp:304] Received SASL authentication step I0122 19:15:01.602881 3534 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0122 19:15:01.602895 3534 auxprop.cpp:171] Looking up auxiliary property '*userPassword' I0122 19:15:01.602936 3534 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0122 19:15:01.602960 3534 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0122 19:15:01.602973 3534 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0122 19:15:01.602982 3534 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0122 19:15:01.602996 3534 authenticator.hpp:390] Authentication success I0122 19:15:01.603091 3534 authenticatee.hpp:315] Authentication success I0122 19:15:01.603174 3534 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 I0122 19:15:01.603533 3535 sched.cpp:392] Successfully authenticated with master master@127.0.0.1:50172 I0122 19:15:01.603559 3535 sched.cpp:515] Sending registration request to master@127.0.0.1:50172 I0122 19:15:01.603626 3535 sched.cpp:548] Will retry registration in 64.334563ms if necessary I0122 19:15:01.604531 3534 master.cpp:1420] Received registration request for framework 'default' at scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 I0122 19:15:01.604869 3536 leveldb.cpp:343] Persisting action (332 bytes) to leveldb took 10.363251ms I0122 19:15:01.605108 3536 replica.cpp:679] Persisted action at 3 I0122 19:15:01.606084 3536 replica.cpp:658] Replica received learned notice for position 3 I0122 19:15:01.606972 3534 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*' I0122 19:15:01.607828 3534 master.cpp:1484] Registering framework 20150122-191501-16777343-50172-3518-0000 (default) at scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 I0122 19:15:01.608331 3540 slave.cpp:1075] Will retry registration in 28.084371ms if necessary I0122 19:15:01.610283 3539 hierarchical_allocator_process.hpp:319] Added framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.610349 3539 hierarchical_allocator_process.hpp:839] No resources available to allocate! I0122 19:15:01.610391 3539 hierarchical_allocator_process.hpp:746] Performed allocation for 0 slaves in 54938ns I0122 19:15:01.614012 3536 leveldb.cpp:343] Persisting action (334 bytes) to leveldb took 7.895962ms I0122 19:15:01.614048 3536 replica.cpp:679] Persisted action at 3 I0122 19:15:01.614073 3536 replica.cpp:664] Replica learned APPEND action at position 3 I0122 19:15:01.615972 3536 registrar.cpp:490] Successfully updated the 'registry' in 26.294016ms I0122 19:15:01.616164 3533 log.cpp:703] Attempting to truncate the log to 3 I0122 19:15:01.616703 3533 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4 I0122 19:15:01.617676 3533 replica.cpp:511] Replica received write request for position 4 I0122 19:15:01.625704 3537 sched.cpp:442] Framework registered with 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.625782 3537 sched.cpp:456] Scheduler::registered took 45146ns I0122 19:15:01.626240 3534 master.cpp:3263] Ignoring register slave message from slave(76)@127.0.0.1:50172 (localhost.localdomain) as admission is already in progress I0122 19:15:01.627259 3534 master.cpp:3329] Registered slave 20150122-191501-16777343-50172-3518-S0 at slave(76)@127.0.0.1:50172 (localhost.localdomain) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] I0122 19:15:01.627607 3534 hierarchical_allocator_process.hpp:453] Added slave 20150122-191501-16777343-50172-3518-S0 (localhost.localdomain) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available) I0122 19:15:01.628016 3534 hierarchical_allocator_process.hpp:764] Performed allocation for slave 20150122-191501-16777343-50172-3518-S0 in 361785ns I0122 19:15:01.628105 3534 slave.cpp:781] Registered with master master@127.0.0.1:50172; given slave ID 20150122-191501-16777343-50172-3518-S0 I0122 19:15:01.628268 3534 slave.cpp:2588] Received ping from slave-observer(62)@127.0.0.1:50172 I0122 19:15:01.628720 3535 master.cpp:4071] Sending 1 offers to framework 20150122-191501-16777343-50172-3518-0000 (default) at scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 I0122 19:15:01.628861 3535 status_update_manager.cpp:178] Resuming sending status updates I0122 19:15:01.629256 3535 sched.cpp:605] Scheduler::resourceOffers took 76294ns I0122 19:15:01.629585 3533 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 11.873298ms I0122 19:15:01.629623 3533 replica.cpp:679] Persisted action at 4 I0122 19:15:01.631567 3533 replica.cpp:658] Replica received learned notice for position 4 I0122 19:15:01.633208 3540 master.cpp:2677] Processing ACCEPT call for offers: [ 20150122-191501-16777343-50172-3518-O0 ] on slave 20150122-191501-16777343-50172-3518-S0 at slave(76)@127.0.0.1:50172 (localhost.localdomain) for framework 20150122-191501-16777343-50172-3518-0000 (default) at scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 I0122 19:15:01.633386 3540 master.cpp:2513] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins' W0122 19:15:01.635479 3540 master.cpp:2130] Executor default for task 1 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases. W0122 19:15:01.636101 3540 master.cpp:2142] Executor default for task 1 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases. I0122 19:15:01.636804 3540 master.hpp:782] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150122-191501-16777343-50172-3518-S0 (localhost.localdomain) I0122 19:15:01.638121 3540 master.cpp:2885] Launching task 1 of framework 20150122-191501-16777343-50172-3518-0000 (default) at scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20150122-191501-16777343-50172-3518-S0 at slave(76)@127.0.0.1:50172 (localhost.localdomain) I0122 19:15:01.642609 3536 slave.cpp:1130] Got assigned task 1 for framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.643496 3536 slave.cpp:1245] Launching task 1 for framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.644604 3533 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 13.001968ms I0122 19:15:01.644726 3533 leveldb.cpp:401] Deleting ~2 keys from leveldb took 61434ns I0122 19:15:01.644752 3533 replica.cpp:679] Persisted action at 4 I0122 19:15:01.644778 3533 replica.cpp:664] Replica learned TRUNCATE action at position 4 I0122 19:15:01.648011 3536 slave.cpp:3921] Launching executor default of framework 20150122-191501-16777343-50172-3518-0000 in work directory '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_XZCq6R/slaves/20150122-191501-16777343-50172-3518-S0/frameworks/20150122-191501-16777343-50172-3518-0000/executors/default/runs/c386f98d-3df4-4aee-b3ad-9e9c1ec7cc15' I0122 19:15:01.657420 3536 exec.cpp:147] Version: 0.22.0 I0122 19:15:01.661609 3534 exec.cpp:197] Executor started at: executor(14)@127.0.0.1:50172 with pid 3518 I0122 19:15:01.662360 3536 slave.cpp:1368] Queuing task '1' for executor default of framework '20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.663007 3536 slave.cpp:566] Successfully attached file '/tmp/FaultToleranceTest_SchedulerFailoverFrameworkMessage_XZCq6R/slaves/20150122-191501-16777343-50172-3518-S0/frameworks/20150122-191501-16777343-50172-3518-0000/executors/default/runs/c386f98d-3df4-4aee-b3ad-9e9c1ec7cc15' I0122 19:15:01.665674 3536 slave.cpp:1912] Got registration for executor 'default' of framework 20150122-191501-16777343-50172-3518-0000 from executor(14)@127.0.0.1:50172 I0122 19:15:01.666738 3539 exec.cpp:221] Executor registered on slave 20150122-191501-16777343-50172-3518-S0 I0122 19:15:01.668758 3539 exec.cpp:233] Executor::registered took 76393ns I0122 19:15:01.669208 3536 slave.cpp:2031] Flushing queued task 1 for executor 'default' of framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.670045 3533 exec.cpp:308] Executor asked to run task '1' I0122 19:15:01.670194 3533 exec.cpp:317] Executor::launchTask took 118431ns I0122 19:15:01.670605 3536 slave.cpp:2890] Monitoring executor 'default' of framework '20150122-191501-16777343-50172-3518-0000' in container 'c386f98d-3df4-4aee-b3ad-9e9c1ec7cc15' I0122 19:15:01.673183 3533 exec.cpp:540] Executor sending status update TASK_RUNNING (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.675230 3534 slave.cpp:2265] Handling status update TASK_RUNNING (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 from executor(14)@127.0.0.1:50172 I0122 19:15:01.675647 3534 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.675689 3534 status_update_manager.cpp:494] Creating StatusUpdate stream for task 1 of framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.675981 3534 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 to the slave I0122 19:15:01.676338 3534 slave.cpp:2508] Forwarding the update TASK_RUNNING (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 to master@127.0.0.1:50172 I0122 19:15:01.676910 3538 master.cpp:3652] Forwarding status update TASK_RUNNING (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.677034 3538 master.cpp:3624] Status update TASK_RUNNING (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 from slave 20150122-191501-16777343-50172-3518-S0 at slave(76)@127.0.0.1:50172 (localhost.localdomain) I0122 19:15:01.677098 3538 master.cpp:4934] Updating the latest state of task 1 of framework 20150122-191501-16777343-50172-3518-0000 to TASK_RUNNING I0122 19:15:01.677338 3538 sched.cpp:696] Scheduler::statusUpdate took 71579ns I0122 19:15:01.677701 3538 master.cpp:3125] Forwarding status update acknowledgement 2150029d-e89c-40a6-998f-c0295d72d964 for task 1 of framework 20150122-191501-16777343-50172-3518-0000 (default) at scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 to slave 20150122-191501-16777343-50172-3518-S0 at slave(76)@127.0.0.1:50172 (localhost.localdomain) W0122 19:15:01.680450 3518 sched.cpp:1246] ************************************************** Scheduler driver bound to loopback interface! Cannot communicate with remote master(s). You might want to set 'LIBPROCESS_IP' environment variable to use a routable IP address. ************************************************** I0122 19:15:01.684923 3534 slave.cpp:2435] Status update manager successfully handled status update TASK_RUNNING (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.685042 3534 slave.cpp:2441] Sending acknowledgement for status update TASK_RUNNING (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 to executor(14)@127.0.0.1:50172 I0122 19:15:01.687777 3534 exec.cpp:354] Executor received status update acknowledgement 2150029d-e89c-40a6-998f-c0295d72d964 for task 1 of framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.687896 3537 status_update_manager.cpp:389] Received status update acknowledgement (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.688174 3537 slave.cpp:1852] Status update manager successfully handled status update acknowledgement (UUID: 2150029d-e89c-40a6-998f-c0295d72d964) for task 1 of framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.707738 3518 sched.cpp:151] Version: 0.22.0 I0122 19:15:01.708892 3540 sched.cpp:248] New master detected at master@127.0.0.1:50172 I0122 19:15:01.708973 3540 sched.cpp:304] Authenticating with master master@127.0.0.1:50172 I0122 19:15:01.708997 3540 sched.cpp:311] Using default CRAM-MD5 authenticatee I0122 19:15:01.709345 3540 authenticatee.hpp:138] Creating new client SASL connection I0122 19:15:01.710389 3534 master.cpp:4129] Authenticating scheduler-ece17f18-6f5c-4807-8204-35771496dd9f@127.0.0.1:50172 I0122 19:15:01.710440 3534 master.cpp:4140] Using default CRAM-MD5 authenticator I0122 19:15:01.710844 3534 authenticator.hpp:170] Creating new server SASL connection I0122 19:15:01.711359 3540 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5 I0122 19:15:01.711762 3540 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5' I0122 19:15:01.712133 3540 authenticator.hpp:276] Received SASL authentication start I0122 19:15:01.712434 3540 authenticator.hpp:398] Authentication requires more steps I0122 19:15:01.712754 3540 authenticatee.hpp:275] Received SASL authentication step I0122 19:15:01.713156 3536 authenticator.hpp:304] Received SASL authentication step I0122 19:15:01.713191 3536 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0122 19:15:01.713204 3536 auxprop.cpp:171] Looking up auxiliary property '*userPassword' I0122 19:15:01.713263 3536 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0122 19:15:01.713290 3536 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'localhost.localdomain' server FQDN: 'localhost.localdomain' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0122 19:15:01.713304 3536 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0122 19:15:01.713311 3536 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0122 19:15:01.713326 3536 authenticator.hpp:390] Authentication success I0122 19:15:01.713470 3536 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-ece17f18-6f5c-4807-8204-35771496dd9f@127.0.0.1:50172 I0122 19:15:01.716526 3540 authenticatee.hpp:315] Authentication success I0122 19:15:01.720747 3540 sched.cpp:392] Successfully authenticated with master master@127.0.0.1:50172 I0122 19:15:01.720780 3540 sched.cpp:515] Sending registration request to master@127.0.0.1:50172 I0122 19:15:01.720852 3540 sched.cpp:548] Will retry registration in 1.20284193secs if necessary I0122 19:15:01.721050 3540 master.cpp:1557] Received re-registration request from framework 20150122-191501-16777343-50172-3518-0000 (default) at scheduler-ece17f18-6f5c-4807-8204-35771496dd9f@127.0.0.1:50172 I0122 19:15:01.721143 3540 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*' I0122 19:15:01.721583 3540 master.cpp:1610] Re-registering framework 20150122-191501-16777343-50172-3518-0000 (default) at scheduler-ece17f18-6f5c-4807-8204-35771496dd9f@127.0.0.1:50172 I0122 19:15:01.721629 3540 master.cpp:1639] Framework 20150122-191501-16777343-50172-3518-0000 (default) at scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 failed over I0122 19:15:01.721943 3540 sched.cpp:792] Got error 'Framework failed over' I0122 19:15:01.721972 3540 sched.cpp:1505] Asked to abort the driver I0122 19:15:01.722039 3540 sched.cpp:803] Scheduler::error took 26469ns I0122 19:15:01.722084 3540 sched.cpp:833] Aborting framework '20150122-191501-16777343-50172-3518-0000' I0122 19:15:01.722196 3540 sched.cpp:442] Framework registered with 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.722262 3540 sched.cpp:456] Scheduler::registered took 40517ns W0122 19:15:01.722734 3538 master.cpp:1775] Ignoring deactivate framework message for framework 20150122-191501-16777343-50172-3518-0000 (default) at scheduler-ece17f18-6f5c-4807-8204-35771496dd9f@127.0.0.1:50172 because it is not expected from scheduler-1491b8db-aae5-47fb-b234-d44c2f509ec0@127.0.0.1:50172 I0122 19:15:01.724819 3540 slave.cpp:1762] Updating framework 20150122-191501-16777343-50172-3518-0000 pid to scheduler-ece17f18-6f5c-4807-8204-35771496dd9f@127.0.0.1:50172 I0122 19:15:01.725316 3533 status_update_manager.cpp:178] Resuming sending status updates I0122 19:15:01.726033 3540 slave.cpp:2571] Sending message for framework 20150122-191501-16777343-50172-3518-0000 to scheduler-ece17f18-6f5c-4807-8204-35771496dd9f@127.0.0.1:50172 I0122 19:15:01.727016 3534 sched.cpp:782] Scheduler::frameworkMessage took 57233ns I0122 19:15:01.727601 3518 sched.cpp:1471] Asked to stop the driver I0122 19:15:01.727665 3518 sched.cpp:1471] Asked to stop the driver I0122 19:15:01.727743 3518 master.cpp:654] Master terminating W0122 19:15:01.727893 3518 master.cpp:4979] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20150122-191501-16777343-50172-3518-0000 on slave 20150122-191501-16777343-50172-3518-S0 at slave(76)@127.0.0.1:50172 (localhost.localdomain) in non-terminal state TASK_RUNNING I0122 19:15:01.728521 3518 master.cpp:5022] Removing executor 'default' with resources of framework 20150122-191501-16777343-50172-3518-0000 on slave 20150122-191501-16777343-50172-3518-S0 at slave(76)@127.0.0.1:50172 (localhost.localdomain) I0122 19:15:01.729651 3534 sched.cpp:808] Stopping framework '20150122-191501-16777343-50172-3518-0000' I0122 19:15:01.729786 3534 sched.cpp:808] Stopping framework '20150122-191501-16777343-50172-3518-0000' I0122 19:15:01.730036 3534 hierarchical_allocator_process.hpp:653] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20150122-191501-16777343-50172-3518-S0 from framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.730134 3534 slave.cpp:2673] master@127.0.0.1:50172 exited W0122 19:15:01.730156 3534 slave.cpp:2676] Master disconnected! Waiting for a new master to be elected I0122 19:15:01.782312 3518 slave.cpp:495] Slave terminating I0122 19:15:01.786846 3518 slave.cpp:1585] Asked to shut down framework 20150122-191501-16777343-50172-3518-0000 by @0.0.0.0:0 I0122 19:15:01.787127 3518 slave.cpp:1610] Shutting down framework 20150122-191501-16777343-50172-3518-0000 I0122 19:15:01.787394 3518 slave.cpp:3198] Shutting down executor 'default' of framework 20150122-191501-16777343-50172-3518-0000 [ OK ] FaultToleranceTest.SchedulerFailoverFrameworkMessage (495 ms)