You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Vinod Kone (JIRA)" <ji...@apache.org> on 2014/08/08 18:47:11 UTC
[jira] [Created] (MESOS-1687) AuthenticationTest.LeaderElection is
flaky
Vinod Kone created MESOS-1687:
---------------------------------
Summary: AuthenticationTest.LeaderElection is flaky
Key: MESOS-1687
URL: https://issues.apache.org/jira/browse/MESOS-1687
Project: Mesos
Issue Type: Bug
Components: test
Affects Versions: 0.20.0
Reporter: Vinod Kone
{code}
[ RUN ] AuthenticationTest.LeaderElection
Using temporary directory '/tmp/AuthenticationTest_LeaderElection_lvaNFb'
I0808 07:46:53.104270 13998 leveldb.cpp:176] Opened db in 62.063015ms
I0808 07:46:53.120640 13998 leveldb.cpp:183] Compacted db in 16.27577ms
I0808 07:46:53.120725 13998 leveldb.cpp:198] Created db iterator in 3591ns
I0808 07:46:53.120798 13998 leveldb.cpp:204] Seeked to beginning of db in 660ns
I0808 07:46:53.120870 13998 leveldb.cpp:273] Iterated through 0 keys in the db in 387ns
I0808 07:46:53.120949 13998 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0808 07:46:53.122022 14270 master.cpp:286] Master 20140808-074653-453759884-54672-13998 (hemera.apache.org) started on 140.211.11.27:54672
I0808 07:46:53.122122 14270 master.cpp:323] Master only allowing authenticated frameworks to register
I0808 07:46:53.122174 14270 master.cpp:328] Master only allowing authenticated slaves to register
I0808 07:46:53.122225 14270 credentials.hpp:36] Loading credentials for authentication from '/tmp/AuthenticationTest_LeaderElection_lvaNFb/credentials'
I0808 07:46:53.122385 14270 master.cpp:357] Authorization enabled
I0808 07:46:53.122843 14270 recover.cpp:425] Starting replica recovery
I0808 07:46:53.122998 14270 hierarchical_allocator_process.hpp:296] Initializing hierarchical allocator process with master : master@140.211.11.27:54672
I0808 07:46:53.123085 14270 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0808 07:46:53.123169 14249 master.cpp:1196] The newly elected leader is master@140.211.11.27:54672 with id 20140808-074653-453759884-54672-13998
I0808 07:46:53.123249 14249 master.cpp:1209] Elected as the leading master!
I0808 07:46:53.123317 14249 master.cpp:1027] Recovering from registrar
I0808 07:46:53.123420 14270 recover.cpp:451] Replica is in EMPTY status
I0808 07:46:53.123450 14249 registrar.cpp:313] Recovering registrar
I0808 07:46:53.123941 14229 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0808 07:46:53.124125 14229 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0808 07:46:53.124230 14229 recover.cpp:542] Updating replica status to STARTING
I0808 07:46:53.136932 14229 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 12.644687ms
I0808 07:46:53.136952 14229 replica.cpp:320] Persisted replica status to STARTING
I0808 07:46:53.137022 14229 recover.cpp:451] Replica is in STARTING status
I0808 07:46:53.137315 14229 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0808 07:46:53.137367 14229 recover.cpp:188] Received a recover response from a replica in STARTING status
I0808 07:46:53.137465 14229 recover.cpp:542] Updating replica status to VOTING
I0808 07:46:53.149039 14229 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 11.525049ms
I0808 07:46:53.149060 14229 replica.cpp:320] Persisted replica status to VOTING
I0808 07:46:53.149099 14229 recover.cpp:556] Successfully joined the Paxos group
I0808 07:46:53.149150 14229 recover.cpp:440] Recover process terminated
I0808 07:46:53.149257 14229 log.cpp:656] Attempting to start the writer
I0808 07:46:53.149548 14229 replica.cpp:474] Replica received implicit promise request with proposal 1
I0808 07:46:53.161147 14229 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 11.585169ms
I0808 07:46:53.161166 14229 replica.cpp:342] Persisted promised to 1
I0808 07:46:53.161339 14229 coordinator.cpp:230] Coordinator attemping to fill missing position
I0808 07:46:53.161700 14232 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0808 07:46:53.173651 14232 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 11.931532ms
I0808 07:46:53.173673 14232 replica.cpp:676] Persisted action at 0
I0808 07:46:53.181856 14237 replica.cpp:508] Replica received write request for position 0
I0808 07:46:53.181907 14237 leveldb.cpp:438] Reading position from leveldb took 19925ns
I0808 07:46:53.197366 14237 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 15.439669ms
I0808 07:46:53.197399 14237 replica.cpp:676] Persisted action at 0
I0808 07:46:53.197592 14237 replica.cpp:655] Replica received learned notice for position 0
I0808 07:46:53.209485 14237 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 11.873446ms
I0808 07:46:53.209516 14237 replica.cpp:676] Persisted action at 0
I0808 07:46:53.209525 14237 replica.cpp:661] Replica learned NOP action at position 0
I0808 07:46:53.209792 14237 log.cpp:672] Writer started with ending position 0
I0808 07:46:53.210057 14237 leveldb.cpp:438] Reading position from leveldb took 12695ns
I0808 07:46:53.211536 14237 registrar.cpp:346] Successfully fetched the registry (0B)
I0808 07:46:53.211557 14237 registrar.cpp:422] Attempting to update the 'registry'
I0808 07:46:53.213075 14237 log.cpp:680] Attempting to append 138 bytes to the log
I0808 07:46:53.213124 14237 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0808 07:46:53.213345 14237 replica.cpp:508] Replica received write request for position 1
I0808 07:46:53.229657 14237 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 16.298804ms
I0808 07:46:53.229679 14237 replica.cpp:676] Persisted action at 1
I0808 07:46:53.229868 14237 replica.cpp:655] Replica received learned notice for position 1
I0808 07:46:53.241647 14237 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 11.763652ms
I0808 07:46:53.241667 14237 replica.cpp:676] Persisted action at 1
I0808 07:46:53.241674 14237 replica.cpp:661] Replica learned APPEND action at position 1
I0808 07:46:53.241966 14259 registrar.cpp:479] Successfully updated 'registry'
I0808 07:46:53.242002 14259 registrar.cpp:372] Successfully recovered registrar
I0808 07:46:53.242041 14259 log.cpp:699] Attempting to truncate the log to 1
I0808 07:46:53.242108 14259 master.cpp:1054] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register
I0808 07:46:53.242147 14259 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0808 07:46:53.242384 14259 replica.cpp:508] Replica received write request for position 2
I0808 07:46:53.257652 14259 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.252385ms
I0808 07:46:53.257673 14259 replica.cpp:676] Persisted action at 2
I0808 07:46:53.257845 14259 replica.cpp:655] Replica received learned notice for position 2
I0808 07:46:53.273197 14259 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 15.339363ms
I0808 07:46:53.273234 14259 leveldb.cpp:401] Deleting ~1 keys from leveldb took 15148ns
I0808 07:46:53.273244 14259 replica.cpp:676] Persisted action at 2
I0808 07:46:53.273252 14259 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0808 07:46:53.280594 13998 sched.cpp:139] Version: 0.20.0
I0808 07:46:53.281882 14229 sched.cpp:235] New master detected at master@140.211.11.27:54672
I0808 07:46:53.281903 14229 sched.cpp:285] Authenticating with master master@140.211.11.27:54672
I0808 07:46:53.281987 14229 authenticatee.hpp:128] Creating new client SASL connection
I0808 07:46:53.282109 14229 master.cpp:3615] Authenticating scheduler-692bec63-4102-4b1f-a457-b8674869c463@140.211.11.27:54672
I0808 07:46:53.282183 14229 authenticator.hpp:156] Creating new server SASL connection
I0808 07:46:53.282268 14229 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0808 07:46:53.282290 14229 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0808 07:46:53.282315 14229 authenticator.hpp:262] Received SASL authentication start
I0808 07:46:53.282343 14229 authenticator.hpp:384] Authentication requires more steps
I0808 07:46:53.283896 14232 sched.cpp:235] New master detected at master@140.211.11.27:54672
I0808 07:46:53.284133 14271 sched.cpp:340] Failed to authenticate with master master@140.211.11.27:54672: master changed
I0808 07:46:53.284164 14271 sched.cpp:285] Authenticating with master master@140.211.11.27:54672
I0808 07:46:53.284221 14271 authenticatee.hpp:128] Creating new client SASL connection
I0808 07:46:53.284314 14271 master.cpp:3601] Queuing up authentication request from scheduler-692bec63-4102-4b1f-a457-b8674869c463@140.211.11.27:54672 because authentication is still in progress
I0808 07:46:54.123903 14242 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:46:54.123927 14242 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 55036ns
I0808 07:46:55.124964 14242 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:46:55.124989 14242 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 33799ns
I0808 07:46:56.125212 14242 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:46:56.125237 14242 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 32128ns
I0808 07:46:57.125905 14241 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:46:57.125929 14241 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 49999ns
W0808 07:46:57.989686 14262 master.cpp:3673] Authentication timed out
I0808 07:46:58.129690 14241 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0808 07:46:58.129741 14241 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:46:58.129748 14241 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 9368ns
W0808 07:46:58.289706 14241 sched.cpp:380] Authentication timed out
W0808 07:46:58.289746 14241 master.cpp:3673] Authentication timed out
I0808 07:46:58.289821 14241 sched.cpp:340] Failed to authenticate with master master@140.211.11.27:54672: Authentication discarded
I0808 07:46:58.289850 14241 sched.cpp:285] Authenticating with master master@140.211.11.27:54672
I0808 07:46:58.289923 14241 authenticatee.hpp:128] Creating new client SASL connection
I0808 07:46:58.290071 14241 master.cpp:3601] Queuing up authentication request from scheduler-692bec63-4102-4b1f-a457-b8674869c463@140.211.11.27:54672 because authentication is still in progress
I0808 07:46:59.130661 14241 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:46:59.130689 14241 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 35829ns
I0808 07:47:00.137707 14241 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:47:00.137732 14241 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 32287ns
I0808 07:47:01.138751 14223 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:47:01.138773 14223 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 68211ns
I0808 07:47:02.141672 14223 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:47:02.141685 14223 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 15940ns
I0808 07:47:03.130631 14223 master.cpp:120] No whitelist given. Advertising offers for all slaves
I0808 07:47:03.149703 14223 hierarchical_allocator_process.hpp:688] No resources available to allocate!
I0808 07:47:03.149716 14223 hierarchical_allocator_process.hpp:650] Performed allocation for 0 slaves in 16735ns
../../src/tests/authentication_tests.cpp:653: Failure
Failed to wait 10secs for registered
../../src/tests/authentication_tests.cpp:646: Failure
Actual function call count doesn't match EXPECT_CALL(sched, registered(&driver, _, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I0808 07:47:03.296547 13998 master.cpp:634] Master terminating
[ FAILED ] AuthenticationTest.LeaderElection (10276 ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.2#6252)