[
https://issues.apache.org/jira/browse/MESOS-2225?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Dominic Hamon updated MESOS-2225:
---------------------------------
Story Points: 2
> FaultToleranceTest.ReregisterFrameworkExitedExecutor is flaky
> -------------------------------------------------------------
>
> Key: MESOS-2225
> URL: https://issues.apache.org/jira/browse/MESOS-2225
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 0.21.0
> Environment: Fedora 19 w/ Clang
> Reporter: Vinod Kone
> Assignee: Vinod Kone
>
> Observed this on internal CI.
> {code}
> [ RUN ] FaultToleranceTest.ReregisterFrameworkExitedExecutor
> Using temporary directory
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_yNprKi'
> I0114 18:50:51.461186 4720 leveldb.cpp:176] Opened db in 4.866948ms
> I0114 18:50:51.462057 4720 leveldb.cpp:183] Compacted db in 472256ns
> I0114 18:50:51.462514 4720 leveldb.cpp:198] Created db iterator in 42905ns
> I0114 18:50:51.462784 4720 leveldb.cpp:204] Seeked to beginning of db in
> 21630ns
> I0114 18:50:51.463068 4720 leveldb.cpp:273] Iterated through 0 keys in the
> db in 19967ns
> I0114 18:50:51.463485 4720 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0114 18:50:51.464555 4737 recover.cpp:449] Starting replica recovery
> I0114 18:50:51.465188 4737 recover.cpp:475] Replica is in EMPTY status
> I0114 18:50:51.467324 4741 replica.cpp:641] Replica in EMPTY status received
> a broadcasted recover request
> I0114 18:50:51.470118 4736 recover.cpp:195] Received a recover response from
> a replica in EMPTY status
> I0114 18:50:51.475424 4739 recover.cpp:566] Updating replica status to
> STARTING
> I0114 18:50:51.476553 4739 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 107545ns
> I0114 18:50:51.476862 4739 replica.cpp:323] Persisted replica status to
> STARTING
> I0114 18:50:51.477309 4739 recover.cpp:475] Replica is in STARTING status
> I0114 18:50:51.479109 4734 replica.cpp:641] Replica in STARTING status
> received a broadcasted recover request
> I0114 18:50:51.481274 4738 recover.cpp:195] Received a recover response from
> a replica in STARTING status
> I0114 18:50:51.482324 4738 recover.cpp:566] Updating replica status to VOTING
> I0114 18:50:51.482913 4738 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 66011ns
> I0114 18:50:51.483186 4738 replica.cpp:323] Persisted replica status to
> VOTING
> I0114 18:50:51.483608 4738 recover.cpp:580] Successfully joined the Paxos
> group
> I0114 18:50:51.484031 4738 recover.cpp:464] Recover process terminated
> I0114 18:50:51.554949 4734 master.cpp:262] Master
> 20150114-185051-2272962752-57018-4720 (fedora-19) started on
> 192.168.122.135:57018
> I0114 18:50:51.555785 4734 master.cpp:308] Master only allowing
> authenticated frameworks to register
> I0114 18:50:51.556046 4734 master.cpp:313] Master only allowing
> authenticated slaves to register
> I0114 18:50:51.556426 4734 credentials.hpp:36] Loading credentials for
> authentication from
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_yNprKi/credentials'
> I0114 18:50:51.557003 4734 master.cpp:357] Authorization enabled
> I0114 18:50:51.558007 4737 hierarchical_allocator_process.hpp:285]
> Initialized hierarchical allocator process
> I0114 18:50:51.558521 4741 whitelist_watcher.cpp:65] No whitelist given
> I0114 18:50:51.562185 4734 master.cpp:1219] The newly elected leader is
> [email protected]:57018 with id 20150114-185051-2272962752-57018-4720
> I0114 18:50:51.562680 4734 master.cpp:1232] Elected as the leading master!
> I0114 18:50:51.562950 4734 master.cpp:1050] Recovering from registrar
> I0114 18:50:51.564506 4736 registrar.cpp:313] Recovering registrar
> I0114 18:50:51.566162 4737 log.cpp:660] Attempting to start the writer
> I0114 18:50:51.568691 4741 replica.cpp:477] Replica received implicit
> promise request with proposal 1
> I0114 18:50:51.569154 4741 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 106885ns
> I0114 18:50:51.569504 4741 replica.cpp:345] Persisted promised to 1
> I0114 18:50:51.573277 4740 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0114 18:50:51.575623 4739 replica.cpp:378] Replica received explicit
> promise request for position 0 with proposal 2
> I0114 18:50:51.576133 4739 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 86360ns
> I0114 18:50:51.576449 4739 replica.cpp:679] Persisted action at 0
> I0114 18:50:51.586966 4736 replica.cpp:511] Replica received write request
> for position 0
> I0114 18:50:51.587666 4736 leveldb.cpp:438] Reading position from leveldb
> took 60621ns
> I0114 18:50:51.588043 4736 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 81094ns
> I0114 18:50:51.588374 4736 replica.cpp:679] Persisted action at 0
> I0114 18:50:51.589418 4736 replica.cpp:658] Replica received learned notice
> for position 0
> I0114 18:50:51.590428 4736 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 106648ns
> I0114 18:50:51.590840 4736 replica.cpp:679] Persisted action at 0
> I0114 18:50:51.591104 4736 replica.cpp:664] Replica learned NOP action at
> position 0
> I0114 18:50:51.592260 4734 log.cpp:676] Writer started with ending position 0
> I0114 18:50:51.594172 4739 leveldb.cpp:438] Reading position from leveldb
> took 52163ns
> I0114 18:50:51.600744 4736 registrar.cpp:346] Successfully fetched the
> registry (0B) in 35968us
> I0114 18:50:51.601646 4736 registrar.cpp:445] Applied 1 operations in
> 184502ns; attempting to update the 'registry'
> I0114 18:50:51.604329 4737 log.cpp:684] Attempting to append 130 bytes to
> the log
> I0114 18:50:51.604966 4737 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0114 18:50:51.606449 4737 replica.cpp:511] Replica received write request
> for position 1
> I0114 18:50:51.606937 4737 leveldb.cpp:343] Persisting action (149 bytes) to
> leveldb took 84877ns
> I0114 18:50:51.607199 4737 replica.cpp:679] Persisted action at 1
> I0114 18:50:51.611934 4741 replica.cpp:658] Replica received learned notice
> for position 1
> I0114 18:50:51.612423 4741 leveldb.cpp:343] Persisting action (151 bytes) to
> leveldb took 113059ns
> I0114 18:50:51.612794 4741 replica.cpp:679] Persisted action at 1
> I0114 18:50:51.613056 4741 replica.cpp:664] Replica learned APPEND action at
> position 1
> I0114 18:50:51.614598 4741 log.cpp:703] Attempting to truncate the log to 1
> I0114 18:50:51.615157 4741 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0114 18:50:51.616458 4737 replica.cpp:511] Replica received write request
> for position 2
> I0114 18:50:51.616902 4737 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 71716ns
> I0114 18:50:51.617168 4737 replica.cpp:679] Persisted action at 2
> I0114 18:50:51.618505 4740 replica.cpp:658] Replica received learned notice
> for position 2
> I0114 18:50:51.619031 4740 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 78481ns
> I0114 18:50:51.619567 4740 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 59638ns
> I0114 18:50:51.619832 4740 replica.cpp:679] Persisted action at 2
> I0114 18:50:51.620101 4740 replica.cpp:664] Replica learned TRUNCATE action
> at position 2
> I0114 18:50:51.621757 4736 registrar.cpp:490] Successfully updated the
> 'registry' in 19.78496ms
> I0114 18:50:51.622658 4736 registrar.cpp:376] Successfully recovered
> registrar
> I0114 18:50:51.623261 4736 master.cpp:1077] Recovered 0 slaves from the
> Registry (94B) ; allowing 10mins for slaves to re-register
> I0114 18:50:51.670349 4739 slave.cpp:173] Slave started on
> 115)@192.168.122.135:57018
> I0114 18:50:51.671133 4739 credentials.hpp:84] Loading credential for
> authentication from
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_ONrVug/credential'
> I0114 18:50:51.671685 4739 slave.cpp:282] Slave using credential for:
> test-principal
> I0114 18:50:51.672245 4739 slave.cpp:300] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0114 18:50:51.673360 4739 slave.cpp:329] Slave hostname: fedora-19
> I0114 18:50:51.673660 4739 slave.cpp:330] Slave checkpoint: false
> W0114 18:50:51.674052 4739 slave.cpp:332] Disabling checkpointing is
> deprecated and the --checkpoint flag will be removed in a future release.
> Please avoid using this flag
> I0114 18:50:51.677234 4737 state.cpp:33] Recovering state from
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_ONrVug/meta'
> I0114 18:50:51.684973 4739 status_update_manager.cpp:197] Recovering status
> update manager
> I0114 18:50:51.687644 4739 slave.cpp:3519] Finished recovery
> I0114 18:50:51.688698 4737 slave.cpp:613] New master detected at
> [email protected]:57018
> I0114 18:50:51.688902 4734 status_update_manager.cpp:171] Pausing sending
> status updates
> I0114 18:50:51.689482 4737 slave.cpp:676] Authenticating with master
> [email protected]:57018
> I0114 18:50:51.689910 4737 slave.cpp:681] Using default CRAM-MD5
> authenticatee
> I0114 18:50:51.690577 4741 authenticatee.hpp:138] Creating new client SASL
> connection
> I0114 18:50:51.691453 4737 slave.cpp:649] Detecting new master
> I0114 18:50:51.691864 4741 master.cpp:4130] Authenticating
> slave(115)@192.168.122.135:57018
> I0114 18:50:51.692369 4741 master.cpp:4141] Using default CRAM-MD5
> authenticator
> I0114 18:50:51.693208 4741 authenticator.hpp:170] Creating new server SASL
> connection
> I0114 18:50:51.694598 4738 authenticatee.hpp:229] Received SASL
> authentication mechanisms: CRAM-MD5
> I0114 18:50:51.694893 4738 authenticatee.hpp:255] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0114 18:50:51.695329 4741 authenticator.hpp:276] Received SASL
> authentication start
> I0114 18:50:51.695641 4741 authenticator.hpp:398] Authentication requires
> more steps
> I0114 18:50:51.696028 4736 authenticatee.hpp:275] Received SASL
> authentication step
> I0114 18:50:51.696486 4741 authenticator.hpp:304] Received SASL
> authentication step
> I0114 18:50:51.696753 4741 auxprop.cpp:99] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0114 18:50:51.697041 4741 auxprop.cpp:171] Looking up auxiliary property
> '*userPassword'
> I0114 18:50:51.697343 4741 auxprop.cpp:171] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0114 18:50:51.697685 4741 auxprop.cpp:99] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0114 18:50:51.697998 4741 auxprop.cpp:121] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0114 18:50:51.698251 4741 auxprop.cpp:121] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0114 18:50:51.698580 4741 authenticator.hpp:390] Authentication success
> I0114 18:50:51.698927 4735 authenticatee.hpp:315] Authentication success
> I0114 18:50:51.705123 4741 master.cpp:4188] Successfully authenticated
> principal 'test-principal' at slave(115)@192.168.122.135:57018
> I0114 18:50:51.705847 4720 sched.cpp:151] Version: 0.22.0
> I0114 18:50:51.707159 4736 sched.cpp:248] New master detected at
> [email protected]:57018
> I0114 18:50:51.707523 4736 sched.cpp:304] Authenticating with master
> [email protected]:57018
> I0114 18:50:51.707792 4736 sched.cpp:311] Using default CRAM-MD5
> authenticatee
> I0114 18:50:51.708412 4736 authenticatee.hpp:138] Creating new client SASL
> connection
> I0114 18:50:51.709316 4735 slave.cpp:747] Successfully authenticated with
> master [email protected]:57018
> I0114 18:50:51.709723 4737 master.cpp:4130] Authenticating
> [email protected]:57018
> I0114 18:50:51.710274 4737 master.cpp:4141] Using default CRAM-MD5
> authenticator
> I0114 18:50:51.710739 4735 slave.cpp:1075] Will retry registration in
> 17.028024ms if necessary
> I0114 18:50:51.711304 4737 master.cpp:3276] Registering slave at
> slave(115)@192.168.122.135:57018 (fedora-19) with id
> 20150114-185051-2272962752-57018-4720-S0
> I0114 18:50:51.711459 4738 authenticator.hpp:170] Creating new server SASL
> connection
> I0114 18:50:51.713142 4739 registrar.cpp:445] Applied 1 operations in
> 100530ns; attempting to update the 'registry'
> I0114 18:50:51.713465 4738 authenticatee.hpp:229] Received SASL
> authentication mechanisms: CRAM-MD5
> I0114 18:50:51.715435 4738 authenticatee.hpp:255] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0114 18:50:51.715963 4740 authenticator.hpp:276] Received SASL
> authentication start
> I0114 18:50:51.716258 4740 authenticator.hpp:398] Authentication requires
> more steps
> I0114 18:50:51.716524 4740 authenticatee.hpp:275] Received SASL
> authentication step
> I0114 18:50:51.716784 4740 authenticator.hpp:304] Received SASL
> authentication step
> I0114 18:50:51.716979 4740 auxprop.cpp:99] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0114 18:50:51.717139 4740 auxprop.cpp:171] Looking up auxiliary property
> '*userPassword'
> I0114 18:50:51.717315 4740 auxprop.cpp:171] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0114 18:50:51.717542 4740 auxprop.cpp:99] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0114 18:50:51.717703 4740 auxprop.cpp:121] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0114 18:50:51.717864 4740 auxprop.cpp:121] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0114 18:50:51.718040 4740 authenticator.hpp:390] Authentication success
> I0114 18:50:51.718292 4740 authenticatee.hpp:315] Authentication success
> I0114 18:50:51.718454 4738 master.cpp:4188] Successfully authenticated
> principal 'test-principal' at
> [email protected]:57018
> I0114 18:50:51.719012 4740 sched.cpp:392] Successfully authenticated with
> master [email protected]:57018
> I0114 18:50:51.719364 4740 sched.cpp:515] Sending registration request to
> [email protected]:57018
> I0114 18:50:51.719702 4740 sched.cpp:548] Will retry registration in
> 746.539282ms if necessary
> I0114 18:50:51.719902 4735 master.cpp:1417] Received registration request
> for framework 'default' at
> [email protected]:57018
> I0114 18:50:51.720232 4735 master.cpp:1298] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0114 18:50:51.722206 4735 master.cpp:1481] Registering framework
> 20150114-185051-2272962752-57018-4720-0000 (default) at
> [email protected]:57018
> I0114 18:50:51.720927 4737 log.cpp:684] Attempting to append 300 bytes to
> the log
> I0114 18:50:51.722924 4737 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0114 18:50:51.724269 4737 replica.cpp:511] Replica received write request
> for position 3
> I0114 18:50:51.724817 4737 leveldb.cpp:343] Persisting action (319 bytes) to
> leveldb took 116638ns
> I0114 18:50:51.728560 4737 replica.cpp:679] Persisted action at 3
> I0114 18:50:51.726066 4736 sched.cpp:442] Framework registered with
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.728879 4736 sched.cpp:456] Scheduler::registered took 34885ns
> I0114 18:50:51.725520 4735 hierarchical_allocator_process.hpp:319] Added
> framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.731864 4735 hierarchical_allocator_process.hpp:839] No
> resources available to allocate!
> I0114 18:50:51.732038 4735 hierarchical_allocator_process.hpp:746] Performed
> allocation for 0 slaves in 214728ns
> I0114 18:50:51.733106 4738 replica.cpp:658] Replica received learned notice
> for position 3
> I0114 18:50:51.733340 4738 leveldb.cpp:343] Persisting action (321 bytes) to
> leveldb took 83165ns
> I0114 18:50:51.733538 4738 replica.cpp:679] Persisted action at 3
> I0114 18:50:51.733705 4738 replica.cpp:664] Replica learned APPEND action at
> position 3
> I0114 18:50:51.735610 4738 registrar.cpp:490] Successfully updated the
> 'registry' in 21.936128ms
> I0114 18:50:51.735805 4739 log.cpp:703] Attempting to truncate the log to 3
> I0114 18:50:51.736445 4739 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0114 18:50:51.737664 4739 replica.cpp:511] Replica received write request
> for position 4
> I0114 18:50:51.738013 4739 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 72906ns
> I0114 18:50:51.738255 4739 replica.cpp:679] Persisted action at 4
> I0114 18:50:51.743397 4734 replica.cpp:658] Replica received learned notice
> for position 4
> I0114 18:50:51.743628 4734 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 78832ns
> I0114 18:50:51.743837 4734 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 63991ns
> I0114 18:50:51.744004 4734 replica.cpp:679] Persisted action at 4
> I0114 18:50:51.744168 4734 replica.cpp:664] Replica learned TRUNCATE action
> at position 4
> I0114 18:50:51.745537 4738 master.cpp:3330] Registered slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0114 18:50:51.745968 4734 hierarchical_allocator_process.hpp:453] Added
> slave 20150114-185051-2272962752-57018-4720-S0 (fedora-19) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
> I0114 18:50:51.746070 4735 slave.cpp:781] Registered with master
> [email protected]:57018; given slave ID
> 20150114-185051-2272962752-57018-4720-S0
> I0114 18:50:51.751437 4741 status_update_manager.cpp:178] Resuming sending
> status updates
> I0114 18:50:51.752428 4740 master.cpp:4072] Sending 1 offers to framework
> 20150114-185051-2272962752-57018-4720-0000 (default) at
> [email protected]:57018
> I0114 18:50:51.753764 4740 sched.cpp:605] Scheduler::resourceOffers took
> 751714ns
> I0114 18:50:51.754812 4740 master.cpp:2541] Processing reply for offers: [
> 20150114-185051-2272962752-57018-4720-O0 ] on slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19) for framework 20150114-185051-2272962752-57018-4720-0000
> (default) at
> [email protected]:57018
> I0114 18:50:51.755040 4740 master.cpp:2647] Authorizing framework principal
> 'test-principal' to launch task 0 as user 'jenkins'
> W0114 18:50:51.756431 4741 master.cpp:2124] Executor default for task 0 uses
> less CPUs (None) than the minimum required (0.01). Please update your
> executor, as this will be mandatory in future releases.
> W0114 18:50:51.756652 4741 master.cpp:2136] Executor default for task 0 uses
> less memory (None) than the minimum required (32MB). Please update your
> executor, as this will be mandatory in future releases.
> I0114 18:50:51.757284 4741 master.hpp:766] Adding task 0 with resources
> cpus(*):1; mem(*):16 on slave 20150114-185051-2272962752-57018-4720-S0
> (fedora-19)
> I0114 18:50:51.757733 4734 hierarchical_allocator_process.hpp:764] Performed
> allocation for slave 20150114-185051-2272962752-57018-4720-S0 in 9.535066ms
> I0114 18:50:51.758117 4735 slave.cpp:2588] Received ping from
> slave-observer(95)@192.168.122.135:57018
> I0114 18:50:51.758630 4741 master.cpp:2897] Launching task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000 (default) at
> [email protected]:57018 with
> resources cpus(*):1; mem(*):16 on slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19)
> I0114 18:50:51.759526 4741 hierarchical_allocator_process.hpp:610] Updated
> allocation of framework 20150114-185051-2272962752-57018-4720-0000 on slave
> 20150114-185051-2272962752-57018-4720-S0 from cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000] to cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0114 18:50:51.759796 4737 slave.cpp:1130] Got assigned task 0 for framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.761184 4737 slave.cpp:1245] Launching task 0 for framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.763586 4741 hierarchical_allocator_process.hpp:653] Recovered
> cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000] (total
> allocatable: cpus(*):1; mem(*):1008; disk(*):1024; ports(*):[31000-32000]) on
> slave 20150114-185051-2272962752-57018-4720-S0 from framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.764034 4741 hierarchical_allocator_process.hpp:689] Framework
> 20150114-185051-2272962752-57018-4720-0000 filtered slave
> 20150114-185051-2272962752-57018-4720-S0 for 5secs
> I0114 18:50:51.764984 4737 slave.cpp:3921] Launching executor default of
> framework 20150114-185051-2272962752-57018-4720-0000 in work directory
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_ONrVug/slaves/20150114-185051-2272962752-57018-4720-S0/frameworks/20150114-185051-2272962752-57018-4720-0000/executors/default/runs/dd104b76-b838-431e-ada9-ff7a2b07e694'
> I0114 18:50:51.775048 4737 exec.cpp:147] Version: 0.22.0
> I0114 18:50:51.778069 4736 exec.cpp:197] Executor started at:
> executor(29)@192.168.122.135:57018 with pid 4720
> I0114 18:50:51.778722 4737 slave.cpp:1368] Queuing task '0' for executor
> default of framework '20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.779103 4737 slave.cpp:566] Successfully attached file
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_ONrVug/slaves/20150114-185051-2272962752-57018-4720-S0/frameworks/20150114-185051-2272962752-57018-4720-0000/executors/default/runs/dd104b76-b838-431e-ada9-ff7a2b07e694'
> I0114 18:50:51.779470 4737 slave.cpp:1912] Got registration for executor
> 'default' of framework 20150114-185051-2272962752-57018-4720-0000 from
> executor(29)@192.168.122.135:57018
> I0114 18:50:51.780288 4740 exec.cpp:221] Executor registered on slave
> 20150114-185051-2272962752-57018-4720-S0
> I0114 18:50:51.782098 4740 exec.cpp:233] Executor::registered took 61371ns
> I0114 18:50:51.782616 4737 slave.cpp:2031] Flushing queued task 0 for
> executor 'default' of framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.783262 4741 exec.cpp:308] Executor asked to run task '0'
> I0114 18:50:51.783614 4741 exec.cpp:317] Executor::launchTask took 97020ns
> I0114 18:50:51.785373 4741 exec.cpp:540] Executor sending status update
> TASK_RUNNING (UUID: 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.785995 4737 slave.cpp:2890] Monitoring executor 'default' of
> framework '20150114-185051-2272962752-57018-4720-0000' in container
> 'dd104b76-b838-431e-ada9-ff7a2b07e694'
> I0114 18:50:51.789064 4737 slave.cpp:2265] Handling status update
> TASK_RUNNING (UUID: 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000 from
> executor(29)@192.168.122.135:57018
> I0114 18:50:51.789553 4735 status_update_manager.cpp:317] Received status
> update TASK_RUNNING (UUID: 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task 0
> of framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.789827 4735 status_update_manager.cpp:494] Creating
> StatusUpdate stream for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.790329 4735 status_update_manager.cpp:371] Forwarding update
> TASK_RUNNING (UUID: 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000 to the slave
> I0114 18:50:51.790875 4737 slave.cpp:2508] Forwarding the update
> TASK_RUNNING (UUID: 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000 to
> [email protected]:57018
> I0114 18:50:51.791442 4736 master.cpp:3653] Forwarding status update
> TASK_RUNNING (UUID: 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.791813 4736 master.cpp:3625] Status update TASK_RUNNING
> (UUID: 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000 from slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19)
> I0114 18:50:51.792140 4736 master.cpp:4935] Updating the latest state of
> task 0 of framework 20150114-185051-2272962752-57018-4720-0000 to TASK_RUNNING
> I0114 18:50:51.792690 4736 sched.cpp:696] Scheduler::statusUpdate took
> 70266ns
> I0114 18:50:51.793184 4739 master.cpp:3126] Forwarding status update
> acknowledgement 3f6824a3-8a23-4029-8505-8eb5f72e472b for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000 (default) at
> [email protected]:57018 to slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19)
> I0114 18:50:51.794311 4720 master.cpp:654] Master terminating
> W0114 18:50:51.794908 4720 master.cpp:4980] Removing task 0 with resources
> cpus(*):1; mem(*):16 of framework 20150114-185051-2272962752-57018-4720-0000
> on slave 20150114-185051-2272962752-57018-4720-S0 at
> slave(115)@192.168.122.135:57018 (fedora-19) in non-terminal state
> TASK_RUNNING
> I0114 18:50:51.795251 4739 slave.cpp:2435] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.795881 4739 slave.cpp:2441] Sending acknowledgement for
> status update TASK_RUNNING (UUID: 3f6824a3-8a23-4029-8505-8eb5f72e472b) for
> task 0 of framework 20150114-185051-2272962752-57018-4720-0000 to
> executor(29)@192.168.122.135:57018
> I0114 18:50:51.796308 4739 exec.cpp:354] Executor received status update
> acknowledgement 3f6824a3-8a23-4029-8505-8eb5f72e472b for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.795326 4741 status_update_manager.cpp:389] Received status
> update acknowledgement (UUID: 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task
> 0 of framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.797854 4741 slave.cpp:1852] Status update manager
> successfully handled status update acknowledgement (UUID:
> 3f6824a3-8a23-4029-8505-8eb5f72e472b) for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.797144 4720 master.cpp:5023] Removing executor 'default' with
> resources of framework 20150114-185051-2272962752-57018-4720-0000 on slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19)
> I0114 18:50:51.796748 4734 hierarchical_allocator_process.hpp:653] Recovered
> cpus(*):1; mem(*):16 (total allocatable: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000]) on slave
> 20150114-185051-2272962752-57018-4720-S0 from framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:51.802438 4739 slave.cpp:2673] [email protected]:57018
> exited
> W0114 18:50:51.802707 4739 slave.cpp:2676] Master disconnected! Waiting for
> a new master to be elected
> I0114 18:50:51.849522 4720 leveldb.cpp:176] Opened db in 1.773376ms
> I0114 18:50:51.860327 4720 leveldb.cpp:183] Compacted db in 1.475626ms
> I0114 18:50:51.860661 4720 leveldb.cpp:198] Created db iterator in 58499ns
> I0114 18:50:51.861027 4720 leveldb.cpp:204] Seeked to beginning of db in
> 53681ns
> I0114 18:50:51.861476 4720 leveldb.cpp:273] Iterated through 3 keys in the
> db in 195975ns
> I0114 18:50:51.861803 4720 replica.cpp:744] Replica recovered with log
> positions 3 -> 4 with 0 holes and 0 unlearned
> I0114 18:50:51.862931 4737 recover.cpp:449] Starting replica recovery
> I0114 18:50:51.863837 4737 recover.cpp:475] Replica is in VOTING status
> I0114 18:50:51.864320 4737 recover.cpp:464] Recover process terminated
> I0114 18:50:51.912767 4734 master.cpp:262] Master
> 20150114-185051-2272962752-57018-4720 (fedora-19) started on
> 192.168.122.135:57018
> I0114 18:50:51.913460 4734 master.cpp:308] Master only allowing
> authenticated frameworks to register
> I0114 18:50:51.913712 4734 master.cpp:313] Master only allowing
> authenticated slaves to register
> I0114 18:50:51.914023 4734 credentials.hpp:36] Loading credentials for
> authentication from
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_yNprKi/credentials'
> I0114 18:50:51.914626 4734 master.cpp:357] Authorization enabled
> I0114 18:50:51.915576 4739 hierarchical_allocator_process.hpp:285]
> Initialized hierarchical allocator process
> I0114 18:50:51.916064 4735 whitelist_watcher.cpp:65] No whitelist given
> I0114 18:50:51.919319 4734 master.cpp:1219] The newly elected leader is
> [email protected]:57018 with id 20150114-185051-2272962752-57018-4720
> I0114 18:50:51.921718 4734 master.cpp:1232] Elected as the leading master!
> I0114 18:50:51.921975 4734 master.cpp:1050] Recovering from registrar
> I0114 18:50:51.922523 4738 registrar.cpp:313] Recovering registrar
> I0114 18:50:51.924142 4738 log.cpp:660] Attempting to start the writer
> I0114 18:50:51.926363 4739 replica.cpp:477] Replica received implicit
> promise request with proposal 2
> I0114 18:50:51.927110 4739 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 147268ns
> I0114 18:50:51.927486 4739 replica.cpp:345] Persisted promised to 2
> I0114 18:50:51.935008 4741 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0114 18:50:51.935816 4741 log.cpp:676] Writer started with ending position 4
> I0114 18:50:51.937769 4739 leveldb.cpp:438] Reading position from leveldb
> took 108522ns
> I0114 18:50:51.938480 4739 leveldb.cpp:438] Reading position from leveldb
> took 171418ns
> I0114 18:50:51.942811 4740 registrar.cpp:346] Successfully fetched the
> registry (261B) in 19.91296ms
> I0114 18:50:51.943493 4740 registrar.cpp:445] Applied 1 operations in
> 96988ns; attempting to update the 'registry'
> I0114 18:50:51.946138 4737 log.cpp:684] Attempting to append 300 bytes to
> the log
> I0114 18:50:51.950773 4737 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 5
> I0114 18:50:51.954259 4739 replica.cpp:511] Replica received write request
> for position 5
> I0114 18:50:51.958901 4739 leveldb.cpp:343] Persisting action (319 bytes) to
> leveldb took 351525ns
> I0114 18:50:51.959277 4739 replica.cpp:679] Persisted action at 5
> I0114 18:50:51.966125 4736 replica.cpp:658] Replica received learned notice
> for position 5
> I0114 18:50:51.966882 4736 leveldb.cpp:343] Persisting action (321 bytes) to
> leveldb took 114790ns
> I0114 18:50:51.967159 4736 replica.cpp:679] Persisted action at 5
> I0114 18:50:51.967515 4736 replica.cpp:664] Replica learned APPEND action at
> position 5
> I0114 18:50:51.971989 4739 registrar.cpp:490] Successfully updated the
> 'registry' in 28.18304ms
> I0114 18:50:51.972854 4739 registrar.cpp:376] Successfully recovered
> registrar
> I0114 18:50:51.973675 4737 master.cpp:1077] Recovered 1 slaves from the
> Registry (261B) ; allowing 10mins for slaves to re-register
> I0114 18:50:51.974957 4737 log.cpp:703] Attempting to truncate the log to 5
> I0114 18:50:51.975620 4740 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 6
> I0114 18:50:51.977298 4740 replica.cpp:511] Replica received write request
> for position 6
> I0114 18:50:51.978060 4740 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 108071ns
> I0114 18:50:51.978374 4740 replica.cpp:679] Persisted action at 6
> I0114 18:50:51.982532 4737 replica.cpp:658] Replica received learned notice
> for position 6
> I0114 18:50:51.983160 4737 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 89982ns
> I0114 18:50:51.983505 4737 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 64662ns
> I0114 18:50:51.983806 4737 replica.cpp:679] Persisted action at 6
> I0114 18:50:51.984136 4737 replica.cpp:664] Replica learned TRUNCATE action
> at position 6
> I0114 18:50:51.997160 4740 slave.cpp:613] New master detected at
> [email protected]:57018
> I0114 18:50:51.998111 4740 slave.cpp:676] Authenticating with master
> [email protected]:57018
> I0114 18:50:51.998437 4740 slave.cpp:681] Using default CRAM-MD5
> authenticatee
> I0114 18:50:51.999161 4734 authenticatee.hpp:138] Creating new client SASL
> connection
> I0114 18:50:51.997766 4735 status_update_manager.cpp:171] Pausing sending
> status updates
> I0114 18:50:52.000628 4740 slave.cpp:649] Detecting new master
> I0114 18:50:52.001258 4734 master.cpp:4130] Authenticating
> slave(115)@192.168.122.135:57018
> I0114 18:50:52.002085 4734 master.cpp:4141] Using default CRAM-MD5
> authenticator
> I0114 18:50:52.003057 4734 authenticator.hpp:170] Creating new server SASL
> connection
> I0114 18:50:52.004458 4735 authenticatee.hpp:229] Received SASL
> authentication mechanisms: CRAM-MD5
> I0114 18:50:52.004762 4735 authenticatee.hpp:255] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0114 18:50:52.005210 4734 authenticator.hpp:276] Received SASL
> authentication start
> I0114 18:50:52.005544 4734 authenticator.hpp:398] Authentication requires
> more steps
> I0114 18:50:52.006116 4736 authenticatee.hpp:275] Received SASL
> authentication step
> I0114 18:50:52.006676 4734 authenticator.hpp:304] Received SASL
> authentication step
> I0114 18:50:52.007045 4734 auxprop.cpp:99] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0114 18:50:52.007340 4734 auxprop.cpp:171] Looking up auxiliary property
> '*userPassword'
> I0114 18:50:52.007733 4734 auxprop.cpp:171] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0114 18:50:52.008149 4734 auxprop.cpp:99] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0114 18:50:52.008437 4734 auxprop.cpp:121] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0114 18:50:52.008714 4734 auxprop.cpp:121] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0114 18:50:52.009009 4734 authenticator.hpp:390] Authentication success
> I0114 18:50:52.009459 4741 authenticatee.hpp:315] Authentication success
> I0114 18:50:52.018327 4738 master.cpp:4188] Successfully authenticated
> principal 'test-principal' at slave(115)@192.168.122.135:57018
> I0114 18:50:52.018959 4741 slave.cpp:747] Successfully authenticated with
> master [email protected]:57018
> I0114 18:50:52.020071 4739 master.cpp:3453] Re-registering slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19)
> I0114 18:50:52.021256 4739 registrar.cpp:445] Applied 1 operations in
> 109203ns; attempting to update the 'registry'
> I0114 18:50:52.023926 4737 log.cpp:684] Attempting to append 300 bytes to
> the log
> I0114 18:50:52.024710 4735 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 7
> I0114 18:50:52.026480 4734 replica.cpp:511] Replica received write request
> for position 7
> I0114 18:50:52.027065 4734 leveldb.cpp:343] Persisting action (319 bytes) to
> leveldb took 109150ns
> I0114 18:50:52.027524 4734 replica.cpp:679] Persisted action at 7
> I0114 18:50:52.028818 4738 replica.cpp:658] Replica received learned notice
> for position 7
> I0114 18:50:52.029525 4738 leveldb.cpp:343] Persisting action (321 bytes) to
> leveldb took 185197ns
> I0114 18:50:52.029930 4738 replica.cpp:679] Persisted action at 7
> I0114 18:50:52.030205 4738 replica.cpp:664] Replica learned APPEND action at
> position 7
> I0114 18:50:52.031692 4735 log.cpp:703] Attempting to truncate the log to 7
> I0114 18:50:52.032083 4740 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 8
> I0114 18:50:52.033411 4740 replica.cpp:511] Replica received write request
> for position 8
> I0114 18:50:52.033768 4740 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 78202ns
> I0114 18:50:52.034054 4740 replica.cpp:679] Persisted action at 8
> I0114 18:50:52.035274 4740 replica.cpp:658] Replica received learned notice
> for position 8
> I0114 18:50:52.035912 4740 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 80144ns
> I0114 18:50:52.036262 4740 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 93273ns
> I0114 18:50:52.036558 4740 replica.cpp:679] Persisted action at 8
> I0114 18:50:52.036883 4740 replica.cpp:664] Replica learned TRUNCATE action
> at position 8
> I0114 18:50:52.038254 4741 slave.cpp:1075] Will retry registration in
> 5.240065ms if necessary
> I0114 18:50:52.044471 4739 registrar.cpp:490] Successfully updated the
> 'registry' in 22.825984ms
> I0114 18:50:52.045918 4740 master.hpp:766] Adding task 0 with resources
> cpus(*):1; mem(*):16 on slave 20150114-185051-2272962752-57018-4720-S0
> (fedora-19)
> W0114 18:50:52.052153 4740 master.cpp:4697] Possibly orphaned task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000 running on slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19)
> I0114 18:50:52.053467 4738 hierarchical_allocator_process.hpp:453] Added
> slave 20150114-185051-2272962752-57018-4720-S0 (fedora-19) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):1;
> mem(*):1008; disk(*):1024; ports(*):[31000-32000] available)
> I0114 18:50:52.054124 4738 hierarchical_allocator_process.hpp:839] No
> resources available to allocate!
> I0114 18:50:52.054733 4738 hierarchical_allocator_process.hpp:764] Performed
> allocation for slave 20150114-185051-2272962752-57018-4720-S0 in 795150ns
> I0114 18:50:52.055675 4736 slave.cpp:1075] Will retry registration in
> 4.9981ms if necessary
> I0114 18:50:52.056367 4736 slave.cpp:2588] Received ping from
> slave-observer(96)@192.168.122.135:57018
> I0114 18:50:52.056958 4740 master.cpp:3521] Re-registered slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0114 18:50:52.057782 4740 master.cpp:3402] Re-registering slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19)
> I0114 18:50:52.058290 4734 slave.cpp:849] Re-registered with master
> [email protected]:57018
> I0114 18:50:52.061352 4734 slave.cpp:2948] Executor 'default' of framework
> 20150114-185051-2272962752-57018-4720-0000 exited with status 0
> I0114 18:50:52.061640 4737 status_update_manager.cpp:178] Resuming sending
> status updates
> I0114 18:50:52.064230 4734 slave.cpp:2265] Handling status update TASK_LOST
> (UUID: 9b52bc70-76aa-4923-be0e-f14669185255) for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000 from @0.0.0.0:0
> I0114 18:50:52.064846 4734 slave.cpp:4229] Terminating task 0
> W0114 18:50:52.065830 4734 slave.cpp:856] Already re-registered with master
> [email protected]:57018
> I0114 18:50:52.067150 4739 master.cpp:3705] Executor default of framework
> 20150114-185051-2272962752-57018-4720-0000 on slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19) exited with status 0
> I0114 18:50:52.070163 4737 status_update_manager.cpp:317] Received status
> update TASK_LOST (UUID: 9b52bc70-76aa-4923-be0e-f14669185255) for task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.070940 4737 status_update_manager.cpp:371] Forwarding update
> TASK_LOST (UUID: 9b52bc70-76aa-4923-be0e-f14669185255) for task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000 to the slave
> I0114 18:50:52.071951 4736 sched.cpp:242] Scheduler::disconnected took
> 43823ns
> I0114 18:50:52.072419 4736 sched.cpp:248] New master detected at
> [email protected]:57018
> I0114 18:50:52.072935 4736 sched.cpp:304] Authenticating with master
> [email protected]:57018
> I0114 18:50:52.073321 4736 sched.cpp:311] Using default CRAM-MD5
> authenticatee
> I0114 18:50:52.074064 4736 authenticatee.hpp:138] Creating new client SASL
> connection
> I0114 18:50:52.076202 4734 slave.cpp:2508] Forwarding the update TASK_LOST
> (UUID: 9b52bc70-76aa-4923-be0e-f14669185255) for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000 to [email protected]:57018
> I0114 18:50:52.077155 4734 slave.cpp:2435] Status update manager
> successfully handled status update TASK_LOST (UUID:
> 9b52bc70-76aa-4923-be0e-f14669185255) for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.076659 4739 master.cpp:5023] Removing executor 'default' with
> resources of framework 20150114-185051-2272962752-57018-4720-0000 on slave
> 20150114-185051-2272962752-57018-4720-S0 at slave(115)@192.168.122.135:57018
> (fedora-19)
> I0114 18:50:52.080638 4739 master.cpp:4130] Authenticating
> [email protected]:57018
> I0114 18:50:52.081056 4739 master.cpp:4141] Using default CRAM-MD5
> authenticator
> I0114 18:50:52.081892 4741 authenticator.hpp:170] Creating new server SASL
> connection
> I0114 18:50:52.083005 4741 authenticatee.hpp:229] Received SASL
> authentication mechanisms: CRAM-MD5
> I0114 18:50:52.083470 4741 authenticatee.hpp:255] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0114 18:50:52.083953 4741 authenticator.hpp:276] Received SASL
> authentication start
> I0114 18:50:52.084355 4741 authenticator.hpp:398] Authentication requires
> more steps
> I0114 18:50:52.084794 4741 authenticatee.hpp:275] Received SASL
> authentication step
> I0114 18:50:52.085310 4737 authenticator.hpp:304] Received SASL
> authentication step
> I0114 18:50:52.085654 4737 auxprop.cpp:99] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0114 18:50:52.085969 4737 auxprop.cpp:171] Looking up auxiliary property
> '*userPassword'
> I0114 18:50:52.086297 4737 auxprop.cpp:171] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0114 18:50:52.086642 4737 auxprop.cpp:99] Request to lookup properties for
> user: 'test-principal' realm: 'fedora-19' server FQDN: 'fedora-19'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0114 18:50:52.086942 4737 auxprop.cpp:121] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0114 18:50:52.087226 4737 auxprop.cpp:121] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0114 18:50:52.087550 4737 authenticator.hpp:390] Authentication success
> I0114 18:50:52.087934 4741 authenticatee.hpp:315] Authentication success
> I0114 18:50:52.088513 4741 sched.cpp:392] Successfully authenticated with
> master [email protected]:57018
> I0114 18:50:52.088899 4741 sched.cpp:515] Sending registration request to
> [email protected]:57018
> I0114 18:50:52.089360 4741 sched.cpp:548] Will retry registration in
> 1.858884079secs if necessary
> I0114 18:50:52.090150 4739 master.cpp:1522] Queuing up re-registration
> request for framework 20150114-185051-2272962752-57018-4720-0000 (default) at
> [email protected]:57018 because
> authentication is still in progress
> I0114 18:50:52.095142 4739 master.cpp:4188] Successfully authenticated
> principal 'test-principal' at
> [email protected]:57018
> I0114 18:50:52.108275 4739 master.cpp:1554] Received re-registration request
> from framework 20150114-185051-2272962752-57018-4720-0000 (default) at
> [email protected]:57018
> I0114 18:50:52.108742 4739 master.cpp:1298] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0114 18:50:52.109735 4739 master.cpp:1607] Re-registering framework
> 20150114-185051-2272962752-57018-4720-0000 (default) at
> [email protected]:57018
> I0114 18:50:52.110985 4735 hierarchical_allocator_process.hpp:319] Added
> framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.120640 4735 hierarchical_allocator_process.hpp:746] Performed
> allocation for 1 slaves in 9.254989ms
> I0114 18:50:52.121709 4734 slave.cpp:1762] Updating framework
> 20150114-185051-2272962752-57018-4720-0000 pid to
> [email protected]:57018
> I0114 18:50:52.122190 4734 status_update_manager.cpp:178] Resuming sending
> status updates
> W0114 18:50:52.122694 4734 status_update_manager.cpp:185] Resending status
> update TASK_LOST (UUID: 9b52bc70-76aa-4923-be0e-f14669185255) for task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.123072 4734 status_update_manager.cpp:371] Forwarding update
> TASK_LOST (UUID: 9b52bc70-76aa-4923-be0e-f14669185255) for task 0 of
> framework 20150114-185051-2272962752-57018-4720-0000 to the slave
> I0114 18:50:52.123733 4734 slave.cpp:2508] Forwarding the update TASK_LOST
> (UUID: 9b52bc70-76aa-4923-be0e-f14669185255) for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000 to [email protected]:57018
> I0114 18:50:52.124590 4720 sched.cpp:1471] Asked to stop the driver
> I0114 18:50:52.125461 4739 master.cpp:4072] Sending 1 offers to framework
> 20150114-185051-2272962752-57018-4720-0000 (default) at
> [email protected]:57018
> I0114 18:50:52.126096 4739 master.cpp:654] Master terminating
> W0114 18:50:52.126626 4739 master.cpp:4980] Removing task 0 with resources
> cpus(*):1; mem(*):16 of framework 20150114-185051-2272962752-57018-4720-0000
> on slave 20150114-185051-2272962752-57018-4720-S0 at
> slave(115)@192.168.122.135:57018 (fedora-19) in non-terminal state
> TASK_RUNNING
> I0114 18:50:52.125669 4735 sched.cpp:423] Ignoring framework registered
> message because the driver is not running!
> I0114 18:50:52.127410 4735 sched.cpp:808] Stopping framework
> '20150114-185051-2272962752-57018-4720-0000'
> I0114 18:50:52.128592 4735 hierarchical_allocator_process.hpp:653] Recovered
> cpus(*):1; mem(*):16 (total allocatable: cpus(*):1; mem(*):16) on slave
> 20150114-185051-2272962752-57018-4720-S0 from framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.132880 4740 slave.cpp:2673] [email protected]:57018
> exited
> W0114 18:50:52.133318 4740 slave.cpp:2676] Master disconnected! Waiting for
> a new master to be elected
> I0114 18:50:52.173943 4720 slave.cpp:495] Slave terminating
> I0114 18:50:52.174928 4720 slave.cpp:1585] Asked to shut down framework
> 20150114-185051-2272962752-57018-4720-0000 by @0.0.0.0:0
> I0114 18:50:52.175448 4720 slave.cpp:1610] Shutting down framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.175858 4720 slave.cpp:3057] Cleaning up executor 'default' of
> framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.176615 4740 gc.cpp:56] Scheduling
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_ONrVug/slaves/20150114-185051-2272962752-57018-4720-S0/frameworks/20150114-185051-2272962752-57018-4720-0000/executors/default/runs/dd104b76-b838-431e-ada9-ff7a2b07e694'
> for gc 6.99999795726815days in the future
> I0114 18:50:52.177549 4734 gc.cpp:56] Scheduling
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_ONrVug/slaves/20150114-185051-2272962752-57018-4720-S0/frameworks/20150114-185051-2272962752-57018-4720-0000/executors/default'
> for gc 6.99999794655111days in the future
> I0114 18:50:52.178169 4720 slave.cpp:3136] Cleaning up framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.178683 4741 status_update_manager.cpp:279] Closing status
> update streams for framework 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.179054 4741 status_update_manager.cpp:525] Cleaning up status
> update stream for task 0 of framework
> 20150114-185051-2272962752-57018-4720-0000
> I0114 18:50:52.179730 4737 gc.cpp:56] Scheduling
> '/tmp/FaultToleranceTest_ReregisterFrameworkExitedExecutor_ONrVug/slaves/20150114-185051-2272962752-57018-4720-S0/frameworks/20150114-185051-2272962752-57018-4720-0000'
> for gc 6.9999979210637days in the future
> tests/fault_tolerance_tests.cpp:1213: Failure
> Actual function call count doesn't match EXPECT_CALL(sched,
> registered(&driver, _, _))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] FaultToleranceTest.ReregisterFrameworkExitedExecutor (776 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
