[
https://issues.apache.org/jira/browse/MESOS-2225?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14280820#comment-14280820
]
Vinod Kone commented on MESOS-2225:
-----------------------------------
The bug here is that at the very end of the test, driver.stop() is called as
soon as FrameworkRegistered message is enqueued at the driver. It is possible
that the 'running' variable of the scheduler driver process is set to false by
driver.stop() *before* the registered message is *processed* by the driver.
This causes the driver to drop the FrameworkRegistered message and hence the
'registered' expectation to fail.
> 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
> master@192.168.122.135: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
> master@192.168.122.135: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
> master@192.168.122.135: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
> master@192.168.122.135:57018
> I0114 18:50:51.707523 4736 sched.cpp:304] Authenticating with master
> master@192.168.122.135: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 master@192.168.122.135:57018
> I0114 18:50:51.709723 4737 master.cpp:4130] Authenticating
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135:57018
> I0114 18:50:51.719012 4740 sched.cpp:392] Successfully authenticated with
> master master@192.168.122.135:57018
> I0114 18:50:51.719364 4740 sched.cpp:515] Sending registration request to
> master@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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
> master@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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
> master@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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] master@192.168.122.135: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
> master@192.168.122.135: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
> master@192.168.122.135:57018
> I0114 18:50:51.998111 4740 slave.cpp:676] Authenticating with master
> master@192.168.122.135: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 master@192.168.122.135: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
> master@192.168.122.135: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
> master@192.168.122.135: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
> master@192.168.122.135:57018
> I0114 18:50:52.072935 4736 sched.cpp:304] Authenticating with master
> master@192.168.122.135: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 master@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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 master@192.168.122.135:57018
> I0114 18:50:52.088899 4741 sched.cpp:515] Sending registration request to
> master@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135:57018 because
> authentication is still in progress
> I0114 18:50:52.095142 4739 master.cpp:4188] Successfully authenticated
> principal 'test-principal' at
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135:57018
> I0114 18:50:52.108275 4739 master.cpp:1554] Received re-registration request
> from framework 20150114-185051-2272962752-57018-4720-0000 (default) at
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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 master@192.168.122.135: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
> scheduler-092fbbec-0938-4355-8187-fb92e5174c64@192.168.122.135: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] master@192.168.122.135: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)
