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/09/10 21:45:33 UTC
[jira] [Commented] (MESOS-1766)
MasterAuthorizationTest.DuplicateRegistration test is flaky
[ https://issues.apache.org/jira/browse/MESOS-1766?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14128986#comment-14128986 ]
Vinod Kone commented on MESOS-1766:
-----------------------------------
The bug here is that the authorizer might get more than the expected registration authorization requests because of registration retries by the scheduler driver.
The fix is simple, authorizer should allow all subsequent authorization requests.
> MasterAuthorizationTest.DuplicateRegistration test is flaky
> -----------------------------------------------------------
>
> Key: MESOS-1766
> URL: https://issues.apache.org/jira/browse/MESOS-1766
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Vinod Kone
> Assignee: Vinod Kone
>
> {code}
> [ RUN ] MasterAuthorizationTest.DuplicateRegistration
> Using temporary directory '/tmp/MasterAuthorizationTest_DuplicateRegistration_pVJg7m'
> I0905 15:53:16.398993 25769 leveldb.cpp:176] Opened db in 2.601036ms
> I0905 15:53:16.399566 25769 leveldb.cpp:183] Compacted db in 546216ns
> I0905 15:53:16.399590 25769 leveldb.cpp:198] Created db iterator in 2787ns
> I0905 15:53:16.399605 25769 leveldb.cpp:204] Seeked to beginning of db in 500ns
> I0905 15:53:16.399617 25769 leveldb.cpp:273] Iterated through 0 keys in the db in 185ns
> I0905 15:53:16.399633 25769 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0905 15:53:16.399817 25786 recover.cpp:425] Starting replica recovery
> I0905 15:53:16.399952 25793 recover.cpp:451] Replica is in EMPTY status
> I0905 15:53:16.400683 25795 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0905 15:53:16.400795 25787 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0905 15:53:16.401005 25783 recover.cpp:542] Updating replica status to STARTING
> I0905 15:53:16.401470 25786 master.cpp:286] Master 20140905-155316-3125920579-49188-25769 (penates.apache.org) started on 67.195.81.186:49188
> I0905 15:53:16.401521 25786 master.cpp:332] Master only allowing authenticated frameworks to register
> I0905 15:53:16.401533 25786 master.cpp:337] Master only allowing authenticated slaves to register
> I0905 15:53:16.401543 25786 credentials.hpp:36] Loading credentials for authentication from '/tmp/MasterAuthorizationTest_DuplicateRegistration_pVJg7m/credentials'
> I0905 15:53:16.401558 25793 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 474683ns
> I0905 15:53:16.401582 25793 replica.cpp:320] Persisted replica status to STARTING
> I0905 15:53:16.401667 25793 recover.cpp:451] Replica is in STARTING status
> I0905 15:53:16.401669 25786 master.cpp:366] Authorization enabled
> I0905 15:53:16.401898 25795 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0905 15:53:16.401936 25796 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.186:49188
> I0905 15:53:16.402160 25784 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0905 15:53:16.402333 25790 master.cpp:1205] The newly elected leader is master@67.195.81.186:49188 with id 20140905-155316-3125920579-49188-25769
> I0905 15:53:16.402359 25790 master.cpp:1218] Elected as the leading master!
> I0905 15:53:16.402371 25790 master.cpp:1036] Recovering from registrar
> I0905 15:53:16.402472 25798 registrar.cpp:313] Recovering registrar
> I0905 15:53:16.402529 25791 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0905 15:53:16.402782 25788 recover.cpp:542] Updating replica status to VOTING
> I0905 15:53:16.403002 25795 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 116403ns
> I0905 15:53:16.403020 25795 replica.cpp:320] Persisted replica status to VOTING
> I0905 15:53:16.403081 25791 recover.cpp:556] Successfully joined the Paxos group
> I0905 15:53:16.403197 25791 recover.cpp:440] Recover process terminated
> I0905 15:53:16.403388 25796 log.cpp:656] Attempting to start the writer
> I0905 15:53:16.403993 25784 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0905 15:53:16.404147 25784 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 132156ns
> I0905 15:53:16.404167 25784 replica.cpp:342] Persisted promised to 1
> I0905 15:53:16.404542 25795 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0905 15:53:16.405498 25787 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0905 15:53:16.405868 25787 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 347231ns
> I0905 15:53:16.405886 25787 replica.cpp:676] Persisted action at 0
> I0905 15:53:16.406553 25788 replica.cpp:508] Replica received write request for position 0
> I0905 15:53:16.406582 25788 leveldb.cpp:438] Reading position from leveldb took 11402ns
> I0905 15:53:16.529067 25788 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 535803ns
> I0905 15:53:16.529088 25788 replica.cpp:676] Persisted action at 0
> I0905 15:53:16.529355 25784 replica.cpp:655] Replica received learned notice for position 0
> I0905 15:53:16.529784 25784 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 406036ns
> I0905 15:53:16.529806 25784 replica.cpp:676] Persisted action at 0
> I0905 15:53:16.529817 25784 replica.cpp:661] Replica learned NOP action at position 0
> I0905 15:53:16.530108 25783 log.cpp:672] Writer started with ending position 0
> I0905 15:53:16.530597 25792 leveldb.cpp:438] Reading position from leveldb took 14594ns
> I0905 15:53:16.532060 25787 registrar.cpp:346] Successfully fetched the registry (0B)
> I0905 15:53:16.532091 25787 registrar.cpp:422] Attempting to update the 'registry'
> I0905 15:53:16.533537 25785 log.cpp:680] Attempting to append 140 bytes to the log
> I0905 15:53:16.533596 25785 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0905 15:53:16.533998 25798 replica.cpp:508] Replica received write request for position 1
> I0905 15:53:16.534397 25798 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 372452ns
> I0905 15:53:16.534416 25798 replica.cpp:676] Persisted action at 1
> I0905 15:53:16.534808 25793 replica.cpp:655] Replica received learned notice for position 1
> I0905 15:53:16.534996 25793 leveldb.cpp:343] Persisting action (161 bytes) to leveldb took 164609ns
> I0905 15:53:16.535014 25793 replica.cpp:676] Persisted action at 1
> I0905 15:53:16.535025 25793 replica.cpp:661] Replica learned APPEND action at position 1
> I0905 15:53:16.535368 25784 registrar.cpp:479] Successfully updated 'registry'
> I0905 15:53:16.535419 25784 registrar.cpp:372] Successfully recovered registrar
> I0905 15:53:16.535452 25785 log.cpp:699] Attempting to truncate the log to 1
> I0905 15:53:16.535555 25791 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0905 15:53:16.535553 25792 master.cpp:1063] Recovered 0 slaves from the Registry (102B) ; allowing 10mins for slaves to re-register
> I0905 15:53:16.536038 25784 replica.cpp:508] Replica received write request for position 2
> I0905 15:53:16.536166 25784 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 101619ns
> I0905 15:53:16.536185 25784 replica.cpp:676] Persisted action at 2
> I0905 15:53:16.536497 25791 replica.cpp:655] Replica received learned notice for position 2
> I0905 15:53:16.536633 25791 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 109281ns
> I0905 15:53:16.536664 25791 leveldb.cpp:401] Deleting ~1 keys from leveldb took 14164ns
> I0905 15:53:16.536677 25791 replica.cpp:676] Persisted action at 2
> I0905 15:53:16.536689 25791 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0905 15:53:16.548408 25769 sched.cpp:137] Version: 0.21.0
> I0905 15:53:16.548627 25792 sched.cpp:233] New master detected at master@67.195.81.186:49188
> I0905 15:53:16.548653 25792 sched.cpp:283] Authenticating with master master@67.195.81.186:49188
> I0905 15:53:16.548857 25797 authenticatee.hpp:128] Creating new client SASL connection
> I0905 15:53:16.548950 25797 master.cpp:3637] Authenticating scheduler-33430370-6af5-4c7b-bbd8-f6a43269ecf5@67.195.81.186:49188
> I0905 15:53:16.549041 25797 authenticator.hpp:156] Creating new server SASL connection
> I0905 15:53:16.549120 25797 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0905 15:53:16.549141 25797 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0905 15:53:16.549180 25797 authenticator.hpp:262] Received SASL authentication start
> I0905 15:53:16.549229 25797 authenticator.hpp:384] Authentication requires more steps
> I0905 15:53:16.549268 25797 authenticatee.hpp:265] Received SASL authentication step
> I0905 15:53:16.549351 25787 authenticator.hpp:290] Received SASL authentication step
> I0905 15:53:16.549378 25787 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0905 15:53:16.549391 25787 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0905 15:53:16.549403 25787 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0905 15:53:16.549415 25787 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0905 15:53:16.549424 25787 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0905 15:53:16.549432 25787 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0905 15:53:16.549448 25787 authenticator.hpp:376] Authentication success
> I0905 15:53:16.549489 25787 authenticatee.hpp:305] Authentication success
> I0905 15:53:16.549525 25787 master.cpp:3677] Successfully authenticated principal 'test-principal' at scheduler-33430370-6af5-4c7b-bbd8-f6a43269ecf5@67.195.81.186:49188
> I0905 15:53:16.549669 25783 sched.cpp:357] Successfully authenticated with master master@67.195.81.186:49188
> I0905 15:53:16.549690 25783 sched.cpp:476] Sending registration request to master@67.195.81.186:49188
> I0905 15:53:16.549751 25787 master.cpp:1324] Received registration request from scheduler-33430370-6af5-4c7b-bbd8-f6a43269ecf5@67.195.81.186:49188
> I0905 15:53:16.549782 25787 master.cpp:1284] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0905 15:53:16.551250 25791 sched.cpp:233] New master detected at master@67.195.81.186:49188
> I0905 15:53:16.551273 25791 sched.cpp:283] Authenticating with master master@67.195.81.186:49188
> I0905 15:53:16.551357 25788 authenticatee.hpp:128] Creating new client SASL connection
> I0905 15:53:16.551456 25791 master.cpp:3637] Authenticating scheduler-33430370-6af5-4c7b-bbd8-f6a43269ecf5@67.195.81.186:49188
> I0905 15:53:16.551553 25788 authenticator.hpp:156] Creating new server SASL connection
> I0905 15:53:16.551673 25786 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0905 15:53:16.551697 25786 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0905 15:53:16.551755 25792 authenticator.hpp:262] Received SASL authentication start
> I0905 15:53:16.551808 25792 authenticator.hpp:384] Authentication requires more steps
> I0905 15:53:16.551856 25792 authenticatee.hpp:265] Received SASL authentication step
> I0905 15:53:16.551920 25786 authenticator.hpp:290] Received SASL authentication step
> I0905 15:53:16.551949 25786 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0905 15:53:16.551966 25786 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0905 15:53:16.551985 25786 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0905 15:53:16.551997 25786 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'penates.apache.org' server FQDN: 'penates.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0905 15:53:16.552006 25786 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0905 15:53:16.552014 25786 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0905 15:53:16.552031 25786 authenticator.hpp:376] Authentication success
> I0905 15:53:16.552081 25792 authenticatee.hpp:305] Authentication success
> I0905 15:53:16.552100 25786 master.cpp:3677] Successfully authenticated principal 'test-principal' at scheduler-33430370-6af5-4c7b-bbd8-f6a43269ecf5@67.195.81.186:49188
> I0905 15:53:16.552249 25792 sched.cpp:357] Successfully authenticated with master master@67.195.81.186:49188
> I0905 15:53:17.402861 25793 hierarchical_allocator_process.hpp:697] No resources available to allocate!
> I0905 15:53:18.874348 25792 sched.cpp:476] Sending registration request to master@67.195.81.186:49188
> I0905 15:53:18.874364 25793 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 1.471501003secs
> I0905 15:53:18.874420 25792 sched.cpp:476] Sending registration request to master@67.195.81.186:49188
> I0905 15:53:18.874451 25793 master.cpp:1324] Received registration request from scheduler-33430370-6af5-4c7b-bbd8-f6a43269ecf5@67.195.81.186:49188
> I0905 15:53:18.874480 25793 master.cpp:1284] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0905 15:53:18.874565 25793 master.cpp:1324] Received registration request from scheduler-33430370-6af5-4c7b-bbd8-f6a43269ecf5@67.195.81.186:49188
> I0905 15:53:18.874588 25793 master.cpp:1284] Authorizing framework principal 'test-principal' to receive offers for role '*'
> : Failure
> Mock function called more times than expected - returning default value.
> Function call: authorize(@0x2b9ed7fe9350 40-byte object <90-BA B4-D4 9E-2B 00-00 00-00 00-00 00-00 00-00 A0-FA 06-F4 9E-2B 00-00 80-17 09-F4 9E-2B 00-00 00-00 00-00 03-00 00-00>)
> The mock function has no default action set, and its return type has no default value set.
> *** Aborted at 1409932398 (unix time) try "date -d @1409932398" if you are using GNU date ***
> PC: @ 0x2b9ed6233f79 (unknown)
> *** SIGABRT (@0x95c000064a9) received by PID 25769 (TID 0x2b9ed7fea700) from PID 25769; stack trace: ***
> @ 0x2b9ed5fef340 (unknown)
> @ 0x2b9ed6233f79 (unknown)
> @ 0x2b9ed6237388 (unknown)
> @ 0x93a5ec testing::internal::GoogleTestFailureReporter::ReportFailure()
> @ 0x7296c5 testing::internal::FunctionMockerBase<>::UntypedPerformDefaultAction()
> @ 0x933094 testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith()
> @ 0x71fbde mesos::internal::tests::MockAuthorizer::authorize()
> @ 0x2b9ed4038caf mesos::internal::master::Master::validate()
> @ 0x2b9ed4039763 mesos::internal::master::Master::registerFramework()
> @ 0x2b9ed40a0c0f ProtobufProcess<>::handler1<>()
> @ 0x2b9ed4050c57 std::_Function_handler<>::_M_invoke()
> @ 0x2b9ed407d202 ProtobufProcess<>::visit()
> @ 0x2b9ed402af1a mesos::internal::master::Master::_visit()
> @ 0x2b9ed4037eb8 mesos::internal::master::Master::visit()
> @ 0x2b9ed44cb792 process::ProcessManager::resume()
> @ 0x2b9ed44cba9c process::schedule()
> @ 0x2b9ed5fe7182 start_thread
> @ 0x2b9ed62f830d (unknown)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)