You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Benjamin Mahler (JIRA)" <ji...@apache.org> on 2015/01/29 20:44:34 UTC
[jira] [Assigned] (MESOS-2302)
FaultToleranceTest.SchedulerFailoverFrameworkMessage is flaky.
[ https://issues.apache.org/jira/browse/MESOS-2302?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Benjamin Mahler reassigned MESOS-2302:
--------------------------------------
Assignee: Benjamin Mahler
Comparing the runs, you can see that there's a race in which the driver gets stopped before the error reaches it:
Bad run:
{noformat}
I0123 18:50:12.034864 15688 sched.cpp:1471] Asked to stop the driver
...
I0123 18:50:12.037359 15710 sched.cpp:788] Ignoring error message because the driver is not running!
{noformat}
Good run:
{noformat}
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.727665 3518 sched.cpp:1471] Asked to stop the driver
{noformat}
> FaultToleranceTest.SchedulerFailoverFrameworkMessage is flaky.
> --------------------------------------------------------------
>
> Key: MESOS-2302
> URL: https://issues.apache.org/jira/browse/MESOS-2302
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Benjamin Mahler
> Assignee: Benjamin Mahler
> Labels: flaky-test, twitter
>
> Bad Run:
> {noformat}
> [ 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)
> {noformat}
> Good Run:
> {noformat}
> [ 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)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)