[MESOS-2306] MasterAuthorizationTest.FrameworkRemovedBeforeReregistration is flaky. - ASF JIRA

Attach files

Attach Screenshot

Voters

Watch issue

Watchers

Link

Clone

Update Comment Author

Replace String in Comment

Update Comment Visibility

Delete Comments

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 0.22.0
Component/s: test
Labels:
- flaky-test
- twitter

Sprint:
Twitter Mesos Q1 Sprint 1
Story Points:
1

Description

Good run:

[ RUN      ] MasterAuthorizationTest.FrameworkRemovedBeforeReregistration
Using temporary directory '/tmp/MasterAuthorizationTest_FrameworkRemovedBeforeReregistration_ZU7oaD'
I0122 19:23:06.481690 17483 leveldb.cpp:176] Opened db in 21.058723ms
I0122 19:23:06.488590 17483 leveldb.cpp:183] Compacted db in 6.6715ms
I0122 19:23:06.488816 17483 leveldb.cpp:198] Created db iterator in 30034ns
I0122 19:23:06.489053 17483 leveldb.cpp:204] Seeked to beginning of db in 2908ns
I0122 19:23:06.489073 17483 leveldb.cpp:273] Iterated through 0 keys in the db in 492ns
I0122 19:23:06.489148 17483 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0122 19:23:06.490272 17504 recover.cpp:449] Starting replica recovery
I0122 19:23:06.490900 17504 recover.cpp:475] Replica is in EMPTY status
I0122 19:23:06.492422 17504 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
I0122 19:23:06.492694 17504 recover.cpp:195] Received a recover response from a replica in EMPTY status
I0122 19:23:06.493185 17504 recover.cpp:566] Updating replica status to STARTING
I0122 19:23:06.514881 17504 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 21.459963ms
I0122 19:23:06.514920 17504 replica.cpp:323] Persisted replica status to STARTING
I0122 19:23:06.515861 17501 master.cpp:262] Master 20150122-192306-16842879-46283-17483 (lucid) started on 127.0.1.1:46283
I0122 19:23:06.515910 17501 master.cpp:308] Master only allowing authenticated frameworks to register
I0122 19:23:06.515923 17501 master.cpp:313] Master only allowing authenticated slaves to register
I0122 19:23:06.515946 17501 credentials.hpp:36] Loading credentials for authentication from '/tmp/MasterAuthorizationTest_FrameworkRemovedBeforeReregistration_ZU7oaD/credentials'
I0122 19:23:06.516150 17501 master.cpp:357] Authorization enabled
I0122 19:23:06.517511 17501 hierarchical_allocator_process.hpp:285] Initialized hierarchical allocator process
I0122 19:23:06.517607 17501 whitelist_watcher.cpp:65] No whitelist given
I0122 19:23:06.518066 17498 master.cpp:1219] The newly elected leader is master@127.0.1.1:46283 with id 20150122-192306-16842879-46283-17483
I0122 19:23:06.518095 17498 master.cpp:1232] Elected as the leading master!
I0122 19:23:06.518121 17498 master.cpp:1050] Recovering from registrar
I0122 19:23:06.518333 17498 registrar.cpp:313] Recovering registrar
I0122 19:23:06.523987 17504 recover.cpp:475] Replica is in STARTING status
I0122 19:23:06.525090 17504 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
I0122 19:23:06.525337 17504 recover.cpp:195] Received a recover response from a replica in STARTING status
I0122 19:23:06.525693 17504 recover.cpp:566] Updating replica status to VOTING
I0122 19:23:06.532680 17504 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 6.810884ms
I0122 19:23:06.532714 17504 replica.cpp:323] Persisted replica status to VOTING
I0122 19:23:06.532835 17504 recover.cpp:580] Successfully joined the Paxos group
I0122 19:23:06.533004 17504 recover.cpp:464] Recover process terminated
I0122 19:23:06.533833 17500 log.cpp:660] Attempting to start the writer
I0122 19:23:06.535225 17500 replica.cpp:477] Replica received implicit promise request with proposal 1
I0122 19:23:06.540340 17500 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 5.086139ms
I0122 19:23:06.540371 17500 replica.cpp:345] Persisted promised to 1
I0122 19:23:06.541502 17504 coordinator.cpp:230] Coordinator attemping to fill missing position
I0122 19:23:06.543021 17504 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0122 19:23:06.548140 17504 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 5.083443ms
I0122 19:23:06.548171 17504 replica.cpp:679] Persisted action at 0
I0122 19:23:06.549746 17500 replica.cpp:511] Replica received write request for position 0
I0122 19:23:06.549926 17500 leveldb.cpp:438] Reading position from leveldb took 31962ns
I0122 19:23:06.555033 17500 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 5.065823ms
I0122 19:23:06.555064 17500 replica.cpp:679] Persisted action at 0
I0122 19:23:06.556094 17504 replica.cpp:658] Replica received learned notice for position 0
I0122 19:23:06.558815 17504 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 2.688382ms
I0122 19:23:06.558847 17504 replica.cpp:679] Persisted action at 0
I0122 19:23:06.558868 17504 replica.cpp:664] Replica learned NOP action at position 0
I0122 19:23:06.559917 17500 log.cpp:676] Writer started with ending position 0
I0122 19:23:06.560995 17500 leveldb.cpp:438] Reading position from leveldb took 27742ns
I0122 19:23:06.563467 17500 registrar.cpp:346] Successfully fetched the registry (0B) in 45.095936ms
I0122 19:23:06.563551 17500 registrar.cpp:445] Applied 1 operations in 19686ns; attempting to update the 'registry'
I0122 19:23:06.566107 17500 log.cpp:684] Attempting to append 118 bytes to the log
I0122 19:23:06.566267 17500 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0122 19:23:06.567126 17500 replica.cpp:511] Replica received write request for position 1
I0122 19:23:06.582588 17500 leveldb.cpp:343] Persisting action (135 bytes) to leveldb took 15.425511ms
I0122 19:23:06.582631 17500 replica.cpp:679] Persisted action at 1
I0122 19:23:06.583425 17500 replica.cpp:658] Replica received learned notice for position 1
I0122 19:23:06.589001 17500 leveldb.cpp:343] Persisting action (137 bytes) to leveldb took 5.549486ms
I0122 19:23:06.589200 17500 replica.cpp:679] Persisted action at 1
I0122 19:23:06.589416 17500 replica.cpp:664] Replica learned APPEND action at position 1
I0122 19:23:06.596420 17500 registrar.cpp:490] Successfully updated the 'registry' in 32.815104ms
I0122 19:23:06.596551 17500 registrar.cpp:376] Successfully recovered registrar
I0122 19:23:06.596923 17500 master.cpp:1077] Recovered 0 slaves from the Registry (82B) ; allowing 10mins for slaves to re-register
I0122 19:23:06.597007 17500 log.cpp:703] Attempting to truncate the log to 1
I0122 19:23:06.597239 17500 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0122 19:23:06.598464 17501 replica.cpp:511] Replica received write request for position 2
I0122 19:23:06.604038 17501 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.536264ms
I0122 19:23:06.604084 17501 replica.cpp:679] Persisted action at 2
I0122 19:23:06.608747 17503 replica.cpp:658] Replica received learned notice for position 2
I0122 19:23:06.614094 17503 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 5.315347ms
I0122 19:23:06.614171 17503 leveldb.cpp:401] Deleting ~1 keys from leveldb took 33021ns
I0122 19:23:06.614188 17503 replica.cpp:679] Persisted action at 2
I0122 19:23:06.614208 17503 replica.cpp:664] Replica learned TRUNCATE action at position 2
I0122 19:23:06.628820 17483 sched.cpp:151] Version: 0.22.0
I0122 19:23:06.629879 17505 sched.cpp:248] New master detected at master@127.0.1.1:46283
I0122 19:23:06.629973 17505 sched.cpp:304] Authenticating with master master@127.0.1.1:46283
I0122 19:23:06.629995 17505 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0122 19:23:06.630314 17505 authenticatee.hpp:138] Creating new client SASL connection
I0122 19:23:06.630722 17505 master.cpp:4129] Authenticating scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.630750 17505 master.cpp:4140] Using default CRAM-MD5 authenticator
I0122 19:23:06.631115 17505 authenticator.hpp:170] Creating new server SASL connection
I0122 19:23:06.631423 17505 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0122 19:23:06.631459 17505 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0122 19:23:06.631563 17505 authenticator.hpp:276] Received SASL authentication start
I0122 19:23:06.631605 17505 authenticator.hpp:398] Authentication requires more steps
I0122 19:23:06.631671 17505 authenticatee.hpp:275] Received SASL authentication step
I0122 19:23:06.631748 17505 authenticator.hpp:304] Received SASL authentication step
I0122 19:23:06.631774 17505 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0122 19:23:06.631784 17505 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0122 19:23:06.631822 17505 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0122 19:23:06.631856 17505 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0122 19:23:06.631870 17505 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0122 19:23:06.631877 17505 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0122 19:23:06.631892 17505 authenticator.hpp:390] Authentication success
I0122 19:23:06.631988 17505 authenticatee.hpp:315] Authentication success
I0122 19:23:06.632066 17505 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.632359 17505 sched.cpp:392] Successfully authenticated with master master@127.0.1.1:46283
I0122 19:23:06.632382 17505 sched.cpp:515] Sending registration request to master@127.0.1.1:46283
I0122 19:23:06.632432 17505 sched.cpp:548] Will retry registration in 598.155756ms if necessary
I0122 19:23:06.632575 17505 master.cpp:1420] Received registration request for framework 'default' at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.632639 17505 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0122 19:23:06.632912 17505 master.cpp:1484] Registering framework 20150122-192306-16842879-46283-17483-0000 (default) at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.633421 17505 hierarchical_allocator_process.hpp:319] Added framework 20150122-192306-16842879-46283-17483-0000
I0122 19:23:06.633448 17505 hierarchical_allocator_process.hpp:839] No resources available to allocate!
I0122 19:23:06.633458 17505 hierarchical_allocator_process.hpp:746] Performed allocation for 0 slaves in 17704ns
I0122 19:23:06.633919 17505 sched.cpp:442] Framework registered with 20150122-192306-16842879-46283-17483-0000
I0122 19:23:06.633980 17505 sched.cpp:456] Scheduler::registered took 37063ns
I0122 19:23:06.636554 17500 sched.cpp:242] Scheduler::disconnected took 14843ns
I0122 19:23:06.636579 17500 sched.cpp:248] New master detected at master@127.0.1.1:46283
I0122 19:23:06.636625 17500 sched.cpp:304] Authenticating with master master@127.0.1.1:46283
I0122 19:23:06.636641 17500 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0122 19:23:06.636914 17500 authenticatee.hpp:138] Creating new client SASL connection
I0122 19:23:06.637313 17500 master.cpp:4129] Authenticating scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.637341 17500 master.cpp:4140] Using default CRAM-MD5 authenticator
I0122 19:23:06.637675 17500 authenticator.hpp:170] Creating new server SASL connection
I0122 19:23:06.638056 17501 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0122 19:23:06.638083 17501 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0122 19:23:06.638182 17501 authenticator.hpp:276] Received SASL authentication start
I0122 19:23:06.638221 17501 authenticator.hpp:398] Authentication requires more steps
I0122 19:23:06.638286 17501 authenticatee.hpp:275] Received SASL authentication step
I0122 19:23:06.638360 17501 authenticator.hpp:304] Received SASL authentication step
I0122 19:23:06.638383 17501 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0122 19:23:06.638393 17501 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0122 19:23:06.638422 17501 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0122 19:23:06.638447 17501 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0122 19:23:06.638458 17501 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0122 19:23:06.638464 17501 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0122 19:23:06.638478 17501 authenticator.hpp:390] Authentication success
I0122 19:23:06.638566 17501 authenticatee.hpp:315] Authentication success
I0122 19:23:06.638643 17501 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.638919 17501 sched.cpp:392] Successfully authenticated with master master@127.0.1.1:46283
I0122 19:23:06.638942 17501 sched.cpp:515] Sending registration request to master@127.0.1.1:46283
I0122 19:23:06.638994 17501 sched.cpp:548] Will retry registration in 489.304713ms if necessary
I0122 19:23:06.639169 17501 master.cpp:1557] Received re-registration request from framework 20150122-192306-16842879-46283-17483-0000 (default) at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.639242 17501 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0122 19:23:06.639839 17483 sched.cpp:1471] Asked to stop the driver
I0122 19:23:06.640379 17499 sched.cpp:808] Stopping framework '20150122-192306-16842879-46283-17483-0000'
I0122 19:23:06.640697 17499 master.cpp:745] Framework 20150122-192306-16842879-46283-17483-0000 (default) at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283 disconnected
I0122 19:23:06.640723 17499 master.cpp:1789] Disconnecting framework 20150122-192306-16842879-46283-17483-0000 (default) at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.640744 17499 master.cpp:1805] Deactivating framework 20150122-192306-16842879-46283-17483-0000 (default) at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.640806 17499 master.cpp:767] Giving framework 20150122-192306-16842879-46283-17483-0000 (default) at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283 0ns to failover
I0122 19:23:06.640951 17499 hierarchical_allocator_process.hpp:398] Deactivated framework 20150122-192306-16842879-46283-17483-0000
I0122 19:23:06.646342 17498 master.cpp:1604] Dropping re-registration request of framework 20150122-192306-16842879-46283-17483-0000 (default)  at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283 because it is not authenticated
I0122 19:23:06.648844 17498 master.cpp:3941] Framework failover timeout, removing framework 20150122-192306-16842879-46283-17483-0000 (default) at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.648871 17498 master.cpp:4499] Removing framework 20150122-192306-16842879-46283-17483-0000 (default) at scheduler-4156eae6-8d7f-423a-920a-02b11b7bd1ba@127.0.1.1:46283
I0122 19:23:06.649624 17498 hierarchical_allocator_process.hpp:352] Removed framework 20150122-192306-16842879-46283-17483-0000
I0122 19:23:06.656532 17483 master.cpp:654] Master terminating
[       OK ] MasterAuthorizationTest.FrameworkRemovedBeforeReregistration (216 ms)

Bad run:

[ RUN      ] MasterAuthorizationTest.FrameworkRemovedBeforeReregistration
Using temporary directory '/tmp/MasterAuthorizationTest_FrameworkRemovedBeforeReregistration_JDM2sm'
I0126 19:19:55.517570  2381 leveldb.cpp:176] Opened db in 34.341401ms
I0126 19:19:55.529630  2381 leveldb.cpp:183] Compacted db in 11.824435ms
I0126 19:19:55.529878  2381 leveldb.cpp:198] Created db iterator in 26176ns
I0126 19:19:55.530200  2381 leveldb.cpp:204] Seeked to beginning of db in 3457ns
I0126 19:19:55.530455  2381 leveldb.cpp:273] Iterated through 0 keys in the db in 902ns
I0126 19:19:55.530658  2381 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0126 19:19:55.531492  2397 recover.cpp:449] Starting replica recovery
I0126 19:19:55.531793  2397 recover.cpp:475] Replica is in EMPTY status
I0126 19:19:55.533327  2397 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
I0126 19:19:55.533608  2397 recover.cpp:195] Received a recover response from a replica in EMPTY status
I0126 19:19:55.534101  2397 recover.cpp:566] Updating replica status to STARTING
I0126 19:19:55.550417  2397 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 16.106821ms
I0126 19:19:55.550472  2397 replica.cpp:323] Persisted replica status to STARTING
I0126 19:19:55.551434  2397 recover.cpp:475] Replica is in STARTING status
I0126 19:19:55.552846  2397 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
I0126 19:19:55.553099  2397 recover.cpp:195] Received a recover response from a replica in STARTING status
I0126 19:19:55.553565  2397 recover.cpp:566] Updating replica status to VOTING
I0126 19:19:55.564590  2397 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 10.719218ms
I0126 19:19:55.564919  2397 replica.cpp:323] Persisted replica status to VOTING
I0126 19:19:55.565982  2397 recover.cpp:580] Successfully joined the Paxos group
I0126 19:19:55.566231  2397 recover.cpp:464] Recover process terminated
I0126 19:19:55.567878  2401 master.cpp:262] Master 20150126-191955-16842879-51862-2381 (lucid) started on 127.0.1.1:51862
I0126 19:19:55.567927  2401 master.cpp:308] Master only allowing authenticated frameworks to register
I0126 19:19:55.567950  2401 master.cpp:313] Master only allowing authenticated slaves to register
I0126 19:19:55.567978  2401 credentials.hpp:36] Loading credentials for authentication from '/tmp/MasterAuthorizationTest_FrameworkRemovedBeforeReregistration_JDM2sm/credentials'
I0126 19:19:55.568220  2401 master.cpp:357] Authorization enabled
I0126 19:19:55.569890  2401 hierarchical_allocator_process.hpp:285] Initialized hierarchical allocator process
I0126 19:19:55.569999  2401 whitelist_watcher.cpp:65] No whitelist given
I0126 19:19:55.570694  2401 master.cpp:1219] The newly elected leader is master@127.0.1.1:51862 with id 20150126-191955-16842879-51862-2381
I0126 19:19:55.570721  2401 master.cpp:1232] Elected as the leading master!
I0126 19:19:55.570742  2401 master.cpp:1050] Recovering from registrar
I0126 19:19:55.570977  2401 registrar.cpp:313] Recovering registrar
I0126 19:19:55.571959  2401 log.cpp:660] Attempting to start the writer
I0126 19:19:55.573441  2401 replica.cpp:477] Replica received implicit promise request with proposal 1
I0126 19:19:55.590724  2401 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 17.243964ms
I0126 19:19:55.590785  2401 replica.cpp:345] Persisted promised to 1
I0126 19:19:55.592140  2396 coordinator.cpp:230] Coordinator attemping to fill missing position
I0126 19:19:55.593834  2396 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0126 19:19:55.603837  2396 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 9.955824ms
I0126 19:19:55.603902  2396 replica.cpp:679] Persisted action at 0
I0126 19:19:55.606082  2401 replica.cpp:511] Replica received write request for position 0
I0126 19:19:55.606331  2401 leveldb.cpp:438] Reading position from leveldb took 44524ns
I0126 19:19:55.612546  2401 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 5.870411ms
I0126 19:19:55.612597  2401 replica.cpp:679] Persisted action at 0
I0126 19:19:55.613416  2401 replica.cpp:658] Replica received learned notice for position 0
I0126 19:19:55.616269  2401 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 2.82145ms
I0126 19:19:55.616305  2401 replica.cpp:679] Persisted action at 0
I0126 19:19:55.616328  2401 replica.cpp:664] Replica learned NOP action at position 0
I0126 19:19:55.628062  2399 log.cpp:676] Writer started with ending position 0
I0126 19:19:55.629328  2399 leveldb.cpp:438] Reading position from leveldb took 57003ns
I0126 19:19:55.631995  2399 registrar.cpp:346] Successfully fetched the registry (0B) in 60.973824ms
I0126 19:19:55.632109  2399 registrar.cpp:445] Applied 1 operations in 35531ns; attempting to update the 'registry'
I0126 19:19:55.634799  2399 log.cpp:684] Attempting to append 117 bytes to the log
I0126 19:19:55.634996  2399 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0126 19:19:55.636651  2397 replica.cpp:511] Replica received write request for position 1
I0126 19:19:55.642165  2397 leveldb.cpp:343] Persisting action (134 bytes) to leveldb took 5.474306ms
I0126 19:19:55.642215  2397 replica.cpp:679] Persisted action at 1
I0126 19:19:55.643226  2397 replica.cpp:658] Replica received learned notice for position 1
I0126 19:19:55.648574  2397 leveldb.cpp:343] Persisting action (136 bytes) to leveldb took 5.317891ms
I0126 19:19:55.648808  2397 replica.cpp:679] Persisted action at 1
I0126 19:19:55.649158  2397 replica.cpp:664] Replica learned APPEND action at position 1
I0126 19:19:55.663101  2397 registrar.cpp:490] Successfully updated the 'registry' in 30.918144ms
I0126 19:19:55.663267  2397 registrar.cpp:376] Successfully recovered registrar
I0126 19:19:55.663699  2397 master.cpp:1077] Recovered 0 slaves from the Registry (81B) ; allowing 10mins for slaves to re-register
I0126 19:19:55.663795  2397 log.cpp:703] Attempting to truncate the log to 1
I0126 19:19:55.664083  2397 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0126 19:19:55.665573  2403 replica.cpp:511] Replica received write request for position 2
I0126 19:19:55.671500  2403 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 5.883759ms
I0126 19:19:55.671547  2403 replica.cpp:679] Persisted action at 2
I0126 19:19:55.672780  2403 replica.cpp:658] Replica received learned notice for position 2
I0126 19:19:55.685999  2403 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 12.808643ms
I0126 19:19:55.686099  2403 leveldb.cpp:401] Deleting ~1 keys from leveldb took 49867ns
I0126 19:19:55.686121  2403 replica.cpp:679] Persisted action at 2
I0126 19:19:55.686149  2403 replica.cpp:664] Replica learned TRUNCATE action at position 2
I0126 19:19:55.722545  2381 sched.cpp:151] Version: 0.22.0
I0126 19:19:55.723795  2401 sched.cpp:248] New master detected at master@127.0.1.1:51862
I0126 19:19:55.723891  2401 sched.cpp:304] Authenticating with master master@127.0.1.1:51862
I0126 19:19:55.723914  2401 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0126 19:19:55.724244  2401 authenticatee.hpp:138] Creating new client SASL connection
I0126 19:19:55.724694  2401 master.cpp:4129] Authenticating scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.724725  2401 master.cpp:4140] Using default CRAM-MD5 authenticator
I0126 19:19:55.725108  2401 authenticator.hpp:170] Creating new server SASL connection
I0126 19:19:55.725390  2401 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0126 19:19:55.725415  2401 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0126 19:19:55.725515  2401 authenticator.hpp:276] Received SASL authentication start
I0126 19:19:55.725566  2401 authenticator.hpp:398] Authentication requires more steps
I0126 19:19:55.725632  2401 authenticatee.hpp:275] Received SASL authentication step
I0126 19:19:55.725710  2401 authenticator.hpp:304] Received SASL authentication step
I0126 19:19:55.725744  2401 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0126 19:19:55.725757  2401 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0126 19:19:55.725808  2401 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0126 19:19:55.725834  2401 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0126 19:19:55.725847  2401 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0126 19:19:55.725853  2401 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0126 19:19:55.725867  2401 authenticator.hpp:390] Authentication success
I0126 19:19:55.728629  2399 authenticatee.hpp:315] Authentication success
I0126 19:19:55.729228  2399 sched.cpp:392] Successfully authenticated with master master@127.0.1.1:51862
I0126 19:19:55.729277  2399 sched.cpp:515] Sending registration request to master@127.0.1.1:51862
I0126 19:19:55.729365  2399 sched.cpp:548] Will retry registration in 3.855403ms if necessary
I0126 19:19:55.729671  2399 master.cpp:1411] Queuing up registration request for framework 'default' at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862 because authentication is still in progress
I0126 19:19:55.733487  2400 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.734094  2400 master.cpp:1420] Received registration request for framework 'default' at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.734177  2400 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0126 19:19:55.734724  2400 master.cpp:1484] Registering framework 20150126-191955-16842879-51862-2381-0000 (default) at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.735335  2402 hierarchical_allocator_process.hpp:319] Added framework 20150126-191955-16842879-51862-2381-0000
I0126 19:19:55.735376  2402 hierarchical_allocator_process.hpp:831] No resources available to allocate!
I0126 19:19:55.735389  2402 hierarchical_allocator_process.hpp:738] Performed allocation for 0 slaves in 22978ns
I0126 19:19:55.741891  2398 sched.cpp:515] Sending registration request to master@127.0.1.1:51862
I0126 19:19:55.744575  2398 sched.cpp:548] Will retry registration in 3.86742709secs if necessary
I0126 19:19:55.744742  2398 sched.cpp:442] Framework registered with 20150126-191955-16842879-51862-2381-0000
I0126 19:19:55.744827  2398 sched.cpp:456] Scheduler::registered took 60111ns
I0126 19:19:55.744956  2398 master.cpp:1420] Received registration request for framework 'default' at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.745020  2398 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0126 19:19:55.749315  2401 sched.cpp:242] Scheduler::disconnected took 19450ns
I0126 19:19:55.749343  2401 sched.cpp:248] New master detected at master@127.0.1.1:51862
I0126 19:19:55.749394  2401 sched.cpp:304] Authenticating with master master@127.0.1.1:51862
I0126 19:19:55.749411  2401 sched.cpp:311] Using default CRAM-MD5 authenticatee
I0126 19:19:55.749743  2401 authenticatee.hpp:138] Creating new client SASL connection
I0126 19:19:55.750208  2401 master.cpp:4129] Authenticating scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.750238  2401 master.cpp:4140] Using default CRAM-MD5 authenticator
I0126 19:19:55.750629  2401 authenticator.hpp:170] Creating new server SASL connection
I0126 19:19:55.750938  2401 authenticatee.hpp:229] Received SASL authentication mechanisms: CRAM-MD5
I0126 19:19:55.750963  2401 authenticatee.hpp:255] Attempting to authenticate with mechanism 'CRAM-MD5'
I0126 19:19:55.751063  2401 authenticator.hpp:276] Received SASL authentication start
I0126 19:19:55.751109  2401 authenticator.hpp:398] Authentication requires more steps
I0126 19:19:55.751175  2401 authenticatee.hpp:275] Received SASL authentication step
I0126 19:19:55.751269  2401 authenticator.hpp:304] Received SASL authentication step
I0126 19:19:55.751296  2401 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0126 19:19:55.751307  2401 auxprop.cpp:171] Looking up auxiliary property '*userPassword'
I0126 19:19:55.751358  2401 auxprop.cpp:171] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0126 19:19:55.751392  2401 auxprop.cpp:99] Request to lookup properties for user: 'test-principal' realm: 'lucid' server FQDN: 'lucid' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0126 19:19:55.751405  2401 auxprop.cpp:121] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0126 19:19:55.751413  2401 auxprop.cpp:121] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0126 19:19:55.751427  2401 authenticator.hpp:390] Authentication success
I0126 19:19:55.751524  2401 authenticatee.hpp:315] Authentication success
I0126 19:19:55.751605  2401 master.cpp:4187] Successfully authenticated principal 'test-principal' at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.751898  2401 sched.cpp:392] Successfully authenticated with master master@127.0.1.1:51862
I0126 19:19:55.751922  2401 sched.cpp:515] Sending registration request to master@127.0.1.1:51862
I0126 19:19:55.751996  2401 sched.cpp:548] Will retry registration in 1.511226315secs if necessary
I0126 19:19:55.752174  2401 master.cpp:1557] Received re-registration request from framework 20150126-191955-16842879-51862-2381-0000 (default) at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.752256  2401 master.cpp:1298] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0126 19:19:55.752485  2401 master.cpp:1610] Re-registering framework 20150126-191955-16842879-51862-2381-0000 (default)  at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.752527  2401 master.cpp:1650] Allowing framework 20150126-191955-16842879-51862-2381-0000 (default) at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862 to re-register with an already used id
I0126 19:19:55.752689  2401 sched.cpp:484] Framework re-registered with 20150126-191955-16842879-51862-2381-0000
tests/master_authorization_tests.cpp:980: Failure
Mock function called more times than expected - returning directly.
    Function call: reregistered(0x7fff5cef57e0, @0x56077d0 id: "20150126-191955-16842879-51862-2381"
ip: 16842879
port: 51862
pid: "master@127.0.1.1:51862"
hostname: "lucid"
)
         Expected: to be never called
           Actual: called once - over-saturated and active
I0126 19:19:55.753191  2401 sched.cpp:498] Scheduler::reregistered took 478798ns
I0126 19:19:55.753600  2381 sched.cpp:1471] Asked to stop the driver
I0126 19:19:55.754518  2402 sched.cpp:808] Stopping framework '20150126-191955-16842879-51862-2381-0000'
I0126 19:19:55.755089  2402 master.cpp:1744] Asked to unregister framework 20150126-191955-16842879-51862-2381-0000
I0126 19:19:55.755302  2402 master.cpp:4499] Removing framework 20150126-191955-16842879-51862-2381-0000 (default) at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862
I0126 19:19:55.759419  2402 hierarchical_allocator_process.hpp:398] Deactivated framework 20150126-191955-16842879-51862-2381-0000
I0126 19:19:55.759850  2402 hierarchical_allocator_process.hpp:352] Removed framework 20150126-191955-16842879-51862-2381-0000
I0126 19:19:55.761160  2400 master.cpp:1462] Dropping registration request for framework 'default' at scheduler-80465e3f-73a3-4bd0-ba66-4dca62e9cdee@127.0.1.1:51862 because it is not authenticated
I0126 19:19:55.771309  2381 master.cpp:654] Master terminating
[  FAILED  ] MasterAuthorizationTest.FrameworkRemovedBeforeReregistration	 (312 ms)

Attachments

Activity

Comment

This comment will be Viewable by All Users Viewable by All Users

Cancel

People

Assignee:: Benjamin Mahler

Reporter:: Benjamin Mahler

Shepherd:: Vinod Kone

Votes:: 0 Vote for this issue

Watchers:: 1 Start watching this issue

Dates

Created:: 29/Jan/15 22:58

Updated:: 30/Jan/15 01:29

Resolved:: 30/Jan/15 01:29

Agile

Completed Sprint:: Twitter Mesos Q1 Sprint 1 ended 02/Feb/15

View on Board

MasterAuthorizationTest.FrameworkRemovedBeforeReregistration is flaky.

Details

Description

Attachments

Attachments

Activity

People

Dates

Agile

Slack

Issue deployment