[
https://issues.apache.org/jira/browse/MESOS-1766?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Bhuvan Arumugam updated MESOS-1766:
-----------------------------------
Target Version/s: 0.20.1
> 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
> Fix For: 0.20.1
>
>
> {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 :
> [email protected]: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
> [email protected]: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
> [email protected]:49188
> I0905 15:53:16.548653 25792 sched.cpp:283] Authenticating with master
> [email protected]: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
> [email protected]: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
> [email protected]:49188
> I0905 15:53:16.549669 25783 sched.cpp:357] Successfully authenticated with
> master [email protected]:49188
> I0905 15:53:16.549690 25783 sched.cpp:476] Sending registration request to
> [email protected]:49188
> I0905 15:53:16.549751 25787 master.cpp:1324] Received registration request
> from [email protected]: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
> [email protected]:49188
> I0905 15:53:16.551273 25791 sched.cpp:283] Authenticating with master
> [email protected]: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
> [email protected]: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
> [email protected]:49188
> I0905 15:53:16.552249 25792 sched.cpp:357] Successfully authenticated with
> master [email protected]: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
> [email protected]: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
> [email protected]:49188
> I0905 15:53:18.874451 25793 master.cpp:1324] Received registration request
> from [email protected]: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 [email protected]: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)
