You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Benjamin Mahler (JIRA)" <ji...@apache.org> on 2015/01/30 00:02:34 UTC
[jira] [Commented] (MESOS-2306)
MasterAuthorizationTest.FrameworkRemovedBeforeReregistration is flaky.
[ https://issues.apache.org/jira/browse/MESOS-2306?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14297856#comment-14297856 ]
Benjamin Mahler commented on MESOS-2306:
----------------------------------------
Comparing the two outputs, there is a race here where the scheduler retries registration an extra time in the failing test. This then messes up the mock expectations:
{code}
// Return a pending future from authorizer after first attempt.
Future<Nothing> authorize2;
Promise<bool> promise2;
EXPECT_CALL(authorizer, authorize(An<const mesos::ACL::RegisterFramework&>()))
.WillOnce(Return(true))
.WillOnce(DoAll(FutureSatisfy(&authorize2),
Return(promise2.future())))
.WillRepeatedly(Return(true)); // Authorize subsequent registration retries.
{code}
We want to simulate a master detection and capture the authorization, but when there is a spurious retry, our simulated retry falls into the WillRepeatedly case and is authorized immediately.
> MasterAuthorizationTest.FrameworkRemovedBeforeReregistration is flaky.
> ----------------------------------------------------------------------
>
> Key: MESOS-2306
> URL: https://issues.apache.org/jira/browse/MESOS-2306
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Benjamin Mahler
> Labels: flaky-test, twitter
>
> Good run:
> {noformat}
> [ 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)
> {noformat}
> Bad run:
> {noformat}
> [ 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)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)