You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Yan Xu (JIRA)" <ji...@apache.org> on 2015/02/05 06:13:34 UTC
[jira] [Created] (MESOS-2320)
MasterAllocatorTest/0.OutOfOrderDispatch is flaky
Yan Xu created MESOS-2320:
-----------------------------
Summary: MasterAllocatorTest/0.OutOfOrderDispatch is flaky
Key: MESOS-2320
URL: https://issues.apache.org/jira/browse/MESOS-2320
Project: Mesos
Issue Type: Bug
Components: test
Affects Versions: 0.22.0
Reporter: Yan Xu
{noformat:title=}
[ RUN ] MasterAllocatorTest/0.OutOfOrderDispatch
Using temporary directory '/tmp/MasterAllocatorTest_0_OutOfOrderDispatch_S6agTr'
I0204 18:47:59.514755 26581 leveldb.cpp:176] Opened db in 825552ns
I0204 18:47:59.515467 26581 leveldb.cpp:183] Compacted db in 439669ns
I0204 18:47:59.515713 26581 leveldb.cpp:198] Created db iterator in 23979ns
I0204 18:47:59.516114 26581 leveldb.cpp:204] Seeked to beginning of db in 3085ns
I0204 18:47:59.516324 26581 leveldb.cpp:273] Iterated through 0 keys in the db in 968ns
I0204 18:47:59.516752 26581 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0204 18:47:59.517593 26597 recover.cpp:449] Starting replica recovery
I0204 18:47:59.518324 26597 recover.cpp:475] Replica is in EMPTY status
I0204 18:47:59.520246 26596 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
I0204 18:47:59.521339 26600 recover.cpp:195] Received a recover response from a replica in EMPTY status
I0204 18:47:59.524446 26600 recover.cpp:566] Updating replica status to STARTING
I0204 18:47:59.525295 26595 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 89800ns
I0204 18:47:59.525662 26595 replica.cpp:323] Persisted replica status to STARTING
I0204 18:47:59.526208 26600 recover.cpp:475] Replica is in STARTING status
I0204 18:47:59.527653 26595 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
I0204 18:47:59.531107 26598 recover.cpp:195] Received a recover response from a replica in STARTING status
I0204 18:47:59.534873 26598 recover.cpp:566] Updating replica status to VOTING
I0204 18:47:59.537209 26598 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 55173ns
I0204 18:47:59.537436 26598 replica.cpp:323] Persisted replica status to VOTING
I0204 18:47:59.537914 26598 recover.cpp:580] Successfully joined the Paxos group
I0204 18:47:59.538418 26598 recover.cpp:464] Recover process terminated
I0204 18:47:59.567250 26598 master.cpp:345] Master 20150204-184759-2759502016-53958-26581 (fedora-20) started on 192.168.122.164:53958
I0204 18:47:59.567728 26598 master.cpp:391] Master only allowing authenticated frameworks to register
I0204 18:47:59.568039 26598 master.cpp:396] Master only allowing authenticated slaves to register
I0204 18:47:59.568289 26598 credentials.hpp:36] Loading credentials for authentication from '/tmp/MasterAllocatorTest_0_OutOfOrderDispatch_S6agTr/credentials'
I0204 18:47:59.568848 26598 master.cpp:440] Authorization enabled
I0204 18:47:59.572664 26599 hierarchical_allocator_process.hpp:285] Initialized hierarchical allocator process
I0204 18:47:59.573318 26596 whitelist_watcher.cpp:65] No whitelist given
I0204 18:47:59.579397 26598 master.cpp:1351] The newly elected leader is master@192.168.122.164:53958 with id 20150204-184759-2759502016-53958-26581
I0204 18:47:59.579794 26598 master.cpp:1364] Elected as the leading master!
I0204 18:47:59.580081 26598 master.cpp:1182] Recovering from registrar
I0204 18:47:59.580508 26601 registrar.cpp:313] Recovering registrar
I0204 18:47:59.582082 26601 log.cpp:660] Attempting to start the writer
I0204 18:47:59.584192 26595 replica.cpp:477] Replica received implicit promise request with proposal 1
I0204 18:47:59.584724 26595 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 92468ns
I0204 18:47:59.585114 26595 replica.cpp:345] Persisted promised to 1
I0204 18:47:59.586300 26595 coordinator.cpp:230] Coordinator attemping to fill missing position
I0204 18:47:59.588454 26599 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0204 18:47:59.588979 26599 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 50767ns
I0204 18:47:59.589223 26599 replica.cpp:679] Persisted action at 0
I0204 18:47:59.594172 26600 replica.cpp:511] Replica received write request for position 0
I0204 18:47:59.594626 26600 leveldb.cpp:438] Reading position from leveldb took 224641ns
I0204 18:47:59.594972 26600 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 49277ns
I0204 18:47:59.595221 26600 replica.cpp:679] Persisted action at 0
I0204 18:47:59.596159 26600 replica.cpp:658] Replica received learned notice for position 0
I0204 18:47:59.596787 26600 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 78485ns
I0204 18:47:59.597054 26600 replica.cpp:679] Persisted action at 0
I0204 18:47:59.597321 26600 replica.cpp:664] Replica learned NOP action at position 0
I0204 18:47:59.598345 26600 log.cpp:676] Writer started with ending position 0
I0204 18:47:59.600194 26602 leveldb.cpp:438] Reading position from leveldb took 29422ns
I0204 18:47:59.614223 26600 registrar.cpp:346] Successfully fetched the registry (0B) in 33.328128ms
I0204 18:47:59.614759 26600 registrar.cpp:445] Applied 1 operations in 27052ns; attempting to update the 'registry'
I0204 18:47:59.617269 26595 log.cpp:684] Attempting to append 131 bytes to the log
I0204 18:47:59.617738 26595 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0204 18:47:59.619072 26601 replica.cpp:511] Replica received write request for position 1
I0204 18:47:59.619421 26601 leveldb.cpp:343] Persisting action (150 bytes) to leveldb took 84865ns
I0204 18:47:59.619678 26601 replica.cpp:679] Persisted action at 1
I0204 18:47:59.624454 26597 replica.cpp:658] Replica received learned notice for position 1
I0204 18:47:59.625006 26597 leveldb.cpp:343] Persisting action (152 bytes) to leveldb took 57318ns
I0204 18:47:59.625274 26597 replica.cpp:679] Persisted action at 1
I0204 18:47:59.625558 26597 replica.cpp:664] Replica learned APPEND action at position 1
I0204 18:47:59.626710 26597 log.cpp:703] Attempting to truncate the log to 1
I0204 18:47:59.627297 26596 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0204 18:47:59.628429 26596 replica.cpp:511] Replica received write request for position 2
I0204 18:47:59.628767 26596 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 48689ns
I0204 18:47:59.629065 26596 replica.cpp:679] Persisted action at 2
I0204 18:47:59.631611 26601 replica.cpp:658] Replica received learned notice for position 2
I0204 18:47:59.631934 26601 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 82589ns
I0204 18:47:59.632216 26601 leveldb.cpp:401] Deleting ~1 keys from leveldb took 62129ns
I0204 18:47:59.632457 26601 replica.cpp:679] Persisted action at 2
I0204 18:47:59.632755 26601 replica.cpp:664] Replica learned TRUNCATE action at position 2
I0204 18:47:59.633903 26600 registrar.cpp:490] Successfully updated the 'registry' in 18.744832ms
I0204 18:47:59.634533 26600 registrar.cpp:376] Successfully recovered registrar
I0204 18:47:59.635082 26600 master.cpp:1209] Recovered 0 slaves from the Registry (95B) ; allowing 10mins for slaves to re-register
I0204 18:47:59.647220 26581 containerizer.cpp:103] Using isolation: posix/cpu,posix/mem
I0204 18:47:59.668190 26596 slave.cpp:173] Slave started on 15)@192.168.122.164:53958
I0204 18:47:59.671438 26596 credentials.hpp:84] Loading credential for authentication from '/tmp/MasterAllocatorTest_0_OutOfOrderDispatch_jdqcw3/credential'
I0204 18:47:59.672761 26596 slave.cpp:282] Slave using credential for: test-principal
I0204 18:47:59.673413 26596 slave.cpp:300] Slave resources: cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000]
I0204 18:47:59.674691 26596 slave.cpp:329] Slave hostname: fedora-20
I0204 18:47:59.675029 26596 slave.cpp:330] Slave checkpoint: false
W0204 18:47:59.675426 26596 slave.cpp:332] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I0204 18:47:59.677371 26599 state.cpp:33] Recovering state from '/tmp/MasterAllocatorTest_0_OutOfOrderDispatch_jdqcw3/meta'
I0204 18:47:59.684636 26600 status_update_manager.cpp:197] Recovering status update manager
I0204 18:47:59.685315 26598 containerizer.cpp:300] Recovering containerizer
I0204 18:47:59.686841 26596 slave.cpp:3527] Finished recovery
I0204 18:47:59.688189 26595 status_update_manager.cpp:171] Pausing sending status updates
I0204 18:47:59.688478 26596 slave.cpp:621] New master detected at master@192.168.122.164:53958
I0204 18:47:59.688928 26596 slave.cpp:684] Authenticating with master master@192.168.122.164:53958
I0204 18:47:59.689216 26596 slave.cpp:689] Using default CRAM-MD5 authenticatee
I0204 18:47:59.701113 26596 slave.cpp:657] Detecting new master
I0204 18:47:59.701354 26601 authenticatee.hpp:138] Creating new client SASL connection
I0204 18:47:59.703546 26601 master.cpp:3789] Authenticating slave(15)@192.168.122.164:53958
I0204 18:47:59.704032 26601 master.cpp:3800] Using default CRAM-MD5 authenticator
I0204 18:47:59.704958 26601 authenticator.hpp:170] Creating new server SASL connection
I0204 18:47:59.707063 26602 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0204 18:47:59.707531 26602 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0204 18:47:59.707964 26601 authenticator.hpp:276] Received SASL authentication start
I0204 18:47:59.708277 26601 authenticator.hpp:398] Authentication requires more steps
I0204 18:47:59.708675 26597 authenticatee.hpp:275] Received SASL authentication step
I0204 18:47:59.709085 26601 authenticator.hpp:304] Received SASL authentication step
I0204 18:47:59.709556 26601 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0204 18:47:59.709795 26601 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0204 18:47:59.710168 26601 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0204 18:47:59.710463 26601 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0204 18:47:59.710708 26601 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0204 18:47:59.710958 26601 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0204 18:47:59.711228 26601 authenticator.hpp:390] Authentication success
I0204 18:47:59.711594 26600 authenticatee.hpp:315] Authentication success
I0204 18:47:59.715297 26600 slave.cpp:755] Successfully authenticated with master master@192.168.122.164:53958
I0204 18:47:59.715795 26602 master.cpp:3847] Successfully authenticated principal 'test-principal' at slave(15)@192.168.122.164:53958
I0204 18:47:59.721117 26581 sched.cpp:151] Version: 0.22.0
I0204 18:47:59.721992 26597 sched.cpp:248] New master detected at master@192.168.122.164:53958
I0204 18:47:59.722280 26597 sched.cpp:304] Authenticating with master master@192.168.122.164:53958
I0204 18:47:59.722566 26597 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0204 18:47:59.723279 26597 authenticatee.hpp:138] Creating new client SASL connection
I0204 18:47:59.724243 26597 master.cpp:3789] Authenticating scheduler-e12dae03-db7f-4cc5-9f1c-5927d5dcb76c@192.168.122.164:53958
I0204 18:47:59.724665 26597 master.cpp:3800] Using default CRAM-MD5 authenticator
I0204 18:47:59.725280 26597 authenticator.hpp:170] Creating new server SASL connection
I0204 18:47:59.726336 26597 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0204 18:47:59.726744 26597 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0204 18:47:59.727108 26597 authenticator.hpp:276] Received SASL authentication start
I0204 18:47:59.727417 26597 authenticator.hpp:398] Authentication requires more steps
I0204 18:47:59.727764 26597 authenticatee.hpp:275] Received SASL authentication step
I0204 18:47:59.728307 26596 authenticator.hpp:304] Received SASL authentication step
I0204 18:47:59.728566 26596 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0204 18:47:59.728909 26596 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0204 18:47:59.729207 26596 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0204 18:47:59.729568 26596 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0204 18:47:59.729894 26596 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0204 18:47:59.730129 26596 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0204 18:47:59.730438 26596 authenticator.hpp:390] Authentication success
I0204 18:47:59.730803 26596 master.cpp:3847] Successfully authenticated principal 'test-principal' at scheduler-e12dae03-db7f-4cc5-9f1c-5927d5dcb76c@192.168.122.164:53958
I0204 18:47:59.733500 26597 authenticatee.hpp:315] Authentication success
I0204 18:47:59.734197 26599 sched.cpp:392] Successfully authenticated with master master@192.168.122.164:53958
I0204 18:47:59.734482 26599 sched.cpp:515] Sending registration request to master@192.168.122.164:53958
I0204 18:47:59.734910 26599 sched.cpp:548] Will retry registration in 896.975932ms if necessary
I0204 18:47:59.735364 26600 slave.cpp:1083] Will retry registration in 3.754235ms if necessary
I0204 18:47:59.735913 26596 master.cpp:1569] Received registration request for framework 'framework1' at scheduler-e12dae03-db7f-4cc5-9f1c-5927d5dcb76c@192.168.122.164:53958
I0204 18:47:59.739542 26596 master.cpp:1430] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0204 18:47:59.740365 26596 master.cpp:2914] Registering slave at slave(15)@192.168.122.164:53958 (fedora-20) with id 20150204-184759-2759502016-53958-26581-S0
I0204 18:47:59.741523 26600 registrar.cpp:445] Applied 1 operations in 77378ns; attempting to update the 'registry'
I0204 18:47:59.743669 26596 master.cpp:1633] Registering framework 20150204-184759-2759502016-53958-26581-0000 (framework1) at scheduler-e12dae03-db7f-4cc5-9f1c-5927d5dcb76c@192.168.122.164:53958
I0204 18:47:59.745133 26595 sched.cpp:442] Framework registered with 20150204-184759-2759502016-53958-26581-0000
I0204 18:47:59.745640 26598 hierarchical_allocator_process.hpp:319] Added framework 20150204-184759-2759502016-53958-26581-0000
I0204 18:47:59.746192 26598 hierarchical_allocator_process.hpp:831] No resources available to allocate!
I0204 18:47:59.746546 26598 hierarchical_allocator_process.hpp:738] Performed allocation for 0 slaves in 366647ns
I0204 18:47:59.746399 26595 sched.cpp:456] Scheduler::registered took 601719ns
I0204 18:47:59.747870 26597 log.cpp:684] Attempting to append 302 bytes to the log
I0204 18:47:59.748373 26597 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0204 18:47:59.749816 26599 replica.cpp:511] Replica received write request for position 3
I0204 18:47:59.750427 26599 leveldb.cpp:343] Persisting action (321 bytes) to leveldb took 92776ns
I0204 18:47:59.750677 26599 replica.cpp:679] Persisted action at 3
I0204 18:47:59.754539 26599 replica.cpp:658] Replica received learned notice for position 3
I0204 18:47:59.755106 26599 leveldb.cpp:343] Persisting action (323 bytes) to leveldb took 64980ns
I0204 18:47:59.755360 26599 replica.cpp:679] Persisted action at 3
I0204 18:47:59.755717 26599 replica.cpp:664] Replica learned APPEND action at position 3
I0204 18:47:59.757392 26599 registrar.cpp:490] Successfully updated the 'registry' in 15.557888ms
I0204 18:47:59.757757 26602 log.cpp:703] Attempting to truncate the log to 3
I0204 18:47:59.758653 26602 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0204 18:47:59.759938 26602 replica.cpp:511] Replica received write request for position 4
I0204 18:47:59.760243 26602 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 56683ns
I0204 18:47:59.760519 26602 replica.cpp:679] Persisted action at 4
I0204 18:47:59.761616 26602 replica.cpp:658] Replica received learned notice for position 4
I0204 18:47:59.762056 26602 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 52601ns
I0204 18:47:59.762480 26602 leveldb.cpp:401] Deleting ~2 keys from leveldb took 67679ns
I0204 18:47:59.762740 26602 replica.cpp:679] Persisted action at 4
I0204 18:47:59.763041 26602 replica.cpp:664] Replica learned TRUNCATE action at position 4
I0204 18:47:59.767012 26601 slave.cpp:1083] Will retry registration in 19.303167ms if necessary
I0204 18:47:59.768196 26597 master.cpp:2971] Registered slave 20150204-184759-2759502016-53958-26581-S0 at slave(15)@192.168.122.164:53958 (fedora-20) with cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000]
I0204 18:47:59.771967 26597 master.cpp:2890] Slave 20150204-184759-2759502016-53958-26581-S0 at slave(15)@192.168.122.164:53958 (fedora-20) already registered, resending acknowledgement
I0204 18:47:59.769016 26596 hierarchical_allocator_process.hpp:453] Added slave 20150204-184759-2759502016-53958-26581-S0 (fedora-20) with cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] available)
I0204 18:47:59.768851 26595 slave.cpp:789] Registered with master master@192.168.122.164:53958; given slave ID 20150204-184759-2759502016-53958-26581-S0
I0204 18:47:59.773975 26595 slave.cpp:2596] Received ping from slave-observer(16)@192.168.122.164:53958
W0204 18:47:59.774577 26595 slave.cpp:829] Already registered with master master@192.168.122.164:53958
I0204 18:47:59.774246 26600 status_update_manager.cpp:178] Resuming sending status updates
I0204 18:47:59.774811 26596 hierarchical_allocator_process.hpp:756] Performed allocation for slave 20150204-184759-2759502016-53958-26581-S0 in 1.935589ms
I0204 18:47:59.775210 26599 master.cpp:3731] Sending 1 offers to framework 20150204-184759-2759502016-53958-26581-0000 (framework1) at scheduler-e12dae03-db7f-4cc5-9f1c-5927d5dcb76c@192.168.122.164:53958
I0204 18:47:59.776628 26599 sched.cpp:605] Scheduler::resourceOffers took 65121ns
I0204 18:47:59.777226 26581 sched.cpp:1471] Asked to stop the driver
I0204 18:47:59.778133 26599 sched.cpp:808] Stopping framework '20150204-184759-2759502016-53958-26581-0000'
I0204 18:47:59.778867 26599 master.cpp:1893] Asked to unregister framework 20150204-184759-2759502016-53958-26581-0000
I0204 18:47:59.779162 26599 master.cpp:4159] Removing framework 20150204-184759-2759502016-53958-26581-0000 (framework1) at scheduler-e12dae03-db7f-4cc5-9f1c-5927d5dcb76c@192.168.122.164:53958
I0204 18:47:59.779661 26598 hierarchical_allocator_process.hpp:398] Deactivated framework 20150204-184759-2759502016-53958-26581-0000
I0204 18:47:59.780345 26598 slave.cpp:1593] Asked to shut down framework 20150204-184759-2759502016-53958-26581-0000 by master@192.168.122.164:53958
W0204 18:47:59.780767 26598 slave.cpp:1608] Cannot shut down unknown framework 20150204-184759-2759502016-53958-26581-0000
I0204 18:47:59.791601 26596 hierarchical_allocator_process.hpp:352] Removed framework 20150204-184759-2759502016-53958-26581-0000
I0204 18:47:59.794189 26596 hierarchical_allocator_process.hpp:645] Recovered cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000]) on slave 20150204-184759-2759502016-53958-26581-S0 from framework 20150204-184759-2759502016-53958-26581-0000
I0204 18:47:59.808313 26581 sched.cpp:151] Version: 0.22.0
I0204 18:47:59.810009 26595 sched.cpp:248] New master detected at master@192.168.122.164:53958
I0204 18:47:59.810339 26595 sched.cpp:304] Authenticating with master master@192.168.122.164:53958
I0204 18:47:59.810617 26595 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0204 18:47:59.811206 26595 authenticatee.hpp:138] Creating new client SASL connection
I0204 18:47:59.812635 26598 master.cpp:3789] Authenticating scheduler-c0edb41a-629f-4ccc-a267-c767fceb6ecc@192.168.122.164:53958
I0204 18:47:59.813122 26598 master.cpp:3800] Using default CRAM-MD5 authenticator
I0204 18:47:59.813680 26601 authenticator.hpp:170] Creating new server SASL connection
I0204 18:47:59.814815 26601 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0204 18:47:59.815335 26601 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0204 18:47:59.815739 26601 authenticator.hpp:276] Received SASL authentication start
I0204 18:47:59.816079 26601 authenticator.hpp:398] Authentication requires more steps
I0204 18:47:59.816398 26601 authenticatee.hpp:275] Received SASL authentication step
I0204 18:47:59.816773 26601 authenticator.hpp:304] Received SASL authentication step
I0204 18:47:59.817100 26601 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0204 18:47:59.817364 26601 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0204 18:47:59.817659 26601 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0204 18:47:59.817967 26601 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'fedora-20' server FQDN: 'fedora-20' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0204 18:47:59.818238 26601 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0204 18:47:59.818495 26601 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0204 18:47:59.818763 26601 authenticator.hpp:390] Authentication success
I0204 18:47:59.819151 26601 authenticatee.hpp:315] Authentication success
I0204 18:47:59.819321 26598 master.cpp:3847] Successfully authenticated principal 'test-principal' at scheduler-c0edb41a-629f-4ccc-a267-c767fceb6ecc@192.168.122.164:53958
I0204 18:47:59.820214 26602 sched.cpp:392] Successfully authenticated with master master@192.168.122.164:53958
I0204 18:47:59.820495 26602 sched.cpp:515] Sending registration request to master@192.168.122.164:53958
I0204 18:47:59.820866 26602 sched.cpp:548] Will retry registration in 1.515133954secs if necessary
I0204 18:47:59.821141 26599 master.cpp:1569] Received registration request for framework 'framework2' at scheduler-c0edb41a-629f-4ccc-a267-c767fceb6ecc@192.168.122.164:53958
I0204 18:47:59.821701 26599 master.cpp:1430] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0204 18:47:59.822593 26599 master.cpp:1633] Registering framework 20150204-184759-2759502016-53958-26581-0001 (framework2) at scheduler-c0edb41a-629f-4ccc-a267-c767fceb6ecc@192.168.122.164:53958
I0204 18:47:59.823783 26598 sched.cpp:442] Framework registered with 20150204-184759-2759502016-53958-26581-0001
I0204 18:47:59.824360 26598 sched.cpp:456] Scheduler::registered took 23096ns
I0204 18:47:59.824178 26600 hierarchical_allocator_process.hpp:319] Added framework 20150204-184759-2759502016-53958-26581-0001
I0204 18:47:59.825656 26600 hierarchical_allocator_process.hpp:738] Performed allocation for 1 slaves in 553347ns
I0204 18:47:59.826241 26596 master.cpp:3731] Sending 1 offers to framework 20150204-184759-2759502016-53958-26581-0001 (framework2) at scheduler-c0edb41a-629f-4ccc-a267-c767fceb6ecc@192.168.122.164:53958
I0204 18:47:59.827359 26596 sched.cpp:605] Scheduler::resourceOffers took 44205ns
I0204 18:47:59.827863 26581 sched.cpp:1471] Asked to stop the driver
I0204 18:47:59.828512 26598 sched.cpp:808] Stopping framework '20150204-184759-2759502016-53958-26581-0001'
I0204 18:47:59.829151 26598 master.cpp:1893] Asked to unregister framework 20150204-184759-2759502016-53958-26581-0001
I0204 18:47:59.829535 26598 master.cpp:4159] Removing framework 20150204-184759-2759502016-53958-26581-0001 (framework2) at scheduler-c0edb41a-629f-4ccc-a267-c767fceb6ecc@192.168.122.164:53958
I0204 18:47:59.830560 26600 slave.cpp:1593] Asked to shut down framework 20150204-184759-2759502016-53958-26581-0001 by master@192.168.122.164:53958
W0204 18:47:59.830936 26600 slave.cpp:1608] Cannot shut down unknown framework 20150204-184759-2759502016-53958-26581-0001
tests/master_allocator_tests.cpp:301: Failure
Mock function called more times than expected - taking default action specified at:
./tests/mesos.hpp:714:
Function call: deactivateFramework(@0x7fadb80065d0 20150204-184759-2759502016-53958-26581-0001)
Expected: to be called once
I0204 18:47:59.831709 26600 hierarchical_allocator_process.hpp:398] Deactivated framework 20150204-184759-2759502016-53958-26581-0001
Actual: called twice - over-saturated and active
tests/master_allocator_tests.cpp:313: Failure
Mock function called more times than expected - taking default action specified at:
./tests/mesos.hpp:754:
Function call: recoverResources(@0x7fadb800ac30 20150204-184759-2759502016-53958-26581-0001, @0x7fadb800ac50 20150204-184759-2759502016-53958-26581-S0, @0x7fadb800ac70 { cpus(*):2, mem(*):1024, disk(*):752, ports(*):[31000-32000] }, @0x7fadb800ac88 16-byte object <01-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00>)
Expected: to be called once
Actual: called twice - over-saturated and active
I0204 18:47:59.835649 26599 hierarchical_allocator_process.hpp:645] Recovered cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):752; ports(*):[31000-32000]) on slave 20150204-184759-2759502016-53958-26581-S0 from framework 20150204-184759-2759502016-53958-26581-0001
I0204 18:47:59.836026 26598 master.cpp:782] Master terminating
I0204 18:47:59.838093 26597 slave.cpp:2681] master@192.168.122.164:53958 exited
W0204 18:47:59.838125 26597 slave.cpp:2684] Master disconnected! Waiting for a new master to be elected
I0204 18:47:59.838619 26595 hierarchical_allocator_process.hpp:352] Removed framework 20150204-184759-2759502016-53958-26581-0001
I0204 18:47:59.872130 26595 slave.cpp:503] Slave terminating
[ FAILED ] MasterAllocatorTest/0.OutOfOrderDispatch, where TypeParam = mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter> (400 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)