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:41:33 UTC
[jira] [Updated] (MESOS-1760)
MasterAuthorizationTest.FrameworkRemovedBeforeReregistration is flaky
[ https://issues.apache.org/jira/browse/MESOS-1760?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Vinod Kone updated MESOS-1760:
------------------------------
Sprint: Mesos Q3 Sprint 5
Assignee: Vinod Kone
Story Points: 1
This is due to the same issue as seen in MESOS-1766, duplicate registration retries.
> MasterAuthorizationTest.FrameworkRemovedBeforeReregistration is flaky
> ---------------------------------------------------------------------
>
> Key: MESOS-1760
> URL: https://issues.apache.org/jira/browse/MESOS-1760
> Project: Mesos
> Issue Type: Bug
> Components: test
> Reporter: Vinod Kone
> Assignee: Vinod Kone
>
> Observed this on Apache CI: https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2355/changes
> {code}
> [ RUN] MasterAuthorizationTest.FrameworkRemovedBeforeReregistration
> Using temporary directory '/tmp/MasterAuthorizationTest_FrameworkRemovedBeforeReregistration_0tw16Z'
> I0903 22:04:33.520237 25565 leveldb.cpp:176] Opened db in 49.073821ms
> I0903 22:04:33.538331 25565 leveldb.cpp:183] Compacted db in 18.065051ms
> I0903 22:04:33.538363 25565 leveldb.cpp:198] Created db iterator in 4826ns
> I0903 22:04:33.538377 25565 leveldb.cpp:204] Seeked to beginning of db in 682ns
> I0903 22:04:33.538385 25565 leveldb.cpp:273] Iterated through 0 keys in the db in 312ns
> I0903 22:04:33.538399 25565 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0903 22:04:33.538624 25593 recover.cpp:425] Starting replica recovery
> I0903 22:04:33.538707 25598 recover.cpp:451] Replica is in EMPTY status
> I0903 22:04:33.540909 25590 master.cpp:286] Master 20140903-220433-453759884-44122-25565 (hemera.apache.org) started on 140.211.11.27:44122
> I0903 22:04:33.540932 25590 master.cpp:332] Master only allowing authenticated frameworks to register
> I0903 22:04:33.540936 25590 master.cpp:337] Master only allowing authenticated slaves to register
> I0903 22:04:33.540941 25590 credentials.hpp:36] Loading credentials for authentication from '/tmp/MasterAuthorizationTest_FrameworkRemovedBeforeReregistration_0tw16Z/credentials'
> I0903 22:04:33.541337 25590 master.cpp:366] Authorization enabled
> I0903 22:04:33.541508 25597 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
> I0903 22:04:33.542343 25582 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@140.211.11.27:44122
> I0903 22:04:33.542445 25592 master.cpp:120] No whitelist given. Advertising offers for all slaves
> I0903 22:04:33.543175 25602 recover.cpp:188] Received a recover response from a replica in EMPTY status
> I0903 22:04:33.543637 25587 recover.cpp:542] Updating replica status to STARTING
> I0903 22:04:33.544256 25579 master.cpp:1205] The newly elected leader is master@140.211.11.27:44122 with id 20140903-220433-453759884-44122-25565
> I0903 22:04:33.544275 25579 master.cpp:1218] Elected as the leading master!
> I0903 22:04:33.544282 25579 master.cpp:1036] Recovering from registrar
> I0903 22:04:33.544401 25579 registrar.cpp:313] Recovering registrar
> I0903 22:04:33.558487 25593 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.678563ms
> I0903 22:04:33.558531 25593 replica.cpp:320] Persisted replica status to STARTING
> I0903 22:04:33.558653 25593 recover.cpp:451] Replica is in STARTING status
> I0903 22:04:33.559867 25588 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
> I0903 22:04:33.560057 25602 recover.cpp:188] Received a recover response from a replica in STARTING status
> I0903 22:04:33.561280 25584 recover.cpp:542] Updating replica status to VOTING
> I0903 22:04:33.576900 25581 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 14.712427ms
> I0903 22:04:33.576942 25581 replica.cpp:320] Persisted replica status to VOTING
> I0903 22:04:33.577018 25581 recover.cpp:556] Successfully joined the Paxos group
> I0903 22:04:33.577108 25581 recover.cpp:440] Recover process terminated
> I0903 22:04:33.577401 25581 log.cpp:656] Attempting to start the writer
> I0903 22:04:33.578559 25589 replica.cpp:474] Replica received implicit promise request with proposal 1
> I0903 22:04:33.594611 25589 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 16.029152ms
> I0903 22:04:33.594640 25589 replica.cpp:342] Persisted promised to 1
> I0903 22:04:33.595391 25584 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0903 22:04:33.597512 25588 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
> I0903 22:04:33.613037 25588 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 15.502568ms
> I0903 22:04:33.613065 25588 replica.cpp:676] Persisted action at 0
> I0903 22:04:33.615435 25585 replica.cpp:508] Replica received write request for position 0
> I0903 22:04:33.615463 25585 leveldb.cpp:438] Reading position from leveldb took 10743ns
> I0903 22:04:33.630801 25585 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 15.320225ms
> I0903 22:04:33.630852 25585 replica.cpp:676] Persisted action at 0
> I0903 22:04:33.631126 25585 replica.cpp:655] Replica received learned notice for position 0
> I0903 22:04:33.647801 25585 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 16.652951ms
> I0903 22:04:33.647830 25585 replica.cpp:676] Persisted action at 0
> I0903 22:04:33.647842 25585 replica.cpp:661] Replica learned NOP action at position 0
> I0903 22:04:33.648548 25583 log.cpp:672] Writer started with ending position 0
> I0903 22:04:33.649235 25583 leveldb.cpp:438] Reading position from leveldb took 25209ns
> I0903 22:04:33.650897 25591 registrar.cpp:346] Successfully fetched the registry (0B)
> I0903 22:04:33.650930 25591 registrar.cpp:422] Attempting to update the 'registry'
> I0903 22:04:33.652861 25601 log.cpp:680] Attempting to append 138 bytes to the log
> I0903 22:04:33.653097 25586 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0903 22:04:33.655225 25590 replica.cpp:508] Replica received write request for position 1
> I0903 22:04:33.669618 25590 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 14.337486ms
> I0903 22:04:33.669663 25590 replica.cpp:676] Persisted action at 1
> I0903 22:04:33.670045 25584 replica.cpp:655] Replica received learned notice for position 1
> I0903 22:04:34.414243 25584 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 15.401247ms
> I0903 22:04:34.414300 25584 replica.cpp:676] Persisted action at 1
> I0903 22:04:34.414316 25584 replica.cpp:661] Replica learned APPEND action at position 1
> I0903 22:04:34.414937 25589 registrar.cpp:479] Successfully updated 'registry'
> I0903 22:04:34.415069 25585 log.cpp:699] Attempting to truncate the log to 1
> I0903 22:04:34.415194 25589 registrar.cpp:372] Successfully recovered registrar
> I0903 22:04:34.415284 25589 master.cpp:1063] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register
> I0903 22:04:34.415362 25587 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0903 22:04:34.418926 25597 replica.cpp:508] Replica received write request for position 2
> I0903 22:04:34.434321 25597 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 15.368147ms
> I0903 22:04:34.434352 25597 replica.cpp:676] Persisted action at 2
> I0903 22:04:34.435022 25582 replica.cpp:655] Replica received learned notice for position 2
> I0903 22:04:34.450331 25582 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 15.284486ms
> I0903 22:04:34.450387 25582 leveldb.cpp:401] Deleting ~1 keys from leveldb took 25774ns
> I0903 22:04:34.450402 25582 replica.cpp:676] Persisted action at 2
> I0903 22:04:34.450412 25582 replica.cpp:661] Replica learned TRUNCATE action at position 2
> I0903 22:04:34.460691 25565 sched.cpp:137] Version: 0.21.0
> I0903 22:04:34.460927 25582 sched.cpp:233] New master detected at master@140.211.11.27:44122
> I0903 22:04:34.460948 25582 sched.cpp:283] Authenticating with master master@140.211.11.27:44122
> I0903 22:04:34.461359 25582 authenticatee.hpp:128] Creating new client SASL connection
> I0903 22:04:34.461647 25582 master.cpp:3637] Authenticating scheduler-04e0b571-7e0c-4ef3-bb14-c6bbfd8ac9a4@140.211.11.27:44122
> I0903 22:04:34.461801 25598 authenticator.hpp:156] Creating new server SASL connection
> I0903 22:04:34.462172 25598 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0903 22:04:34.462185 25598 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0903 22:04:34.462257 25598 authenticator.hpp:262] Received SASL authentication start
> I0903 22:04:34.462323 25598 authenticator.hpp:384] Authentication requires more steps
> I0903 22:04:34.462345 25598 authenticatee.hpp:265] Received SASL authentication step
> I0903 22:04:34.462417 25598 authenticator.hpp:290] Received SASL authentication step
> I0903 22:04:34.462522 25598 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0903 22:04:34.462529 25598 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0903 22:04:34.462538 25598 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0903 22:04:34.462543 25598 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0903 22:04:34.462548 25598 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0903 22:04:34.462550 25598 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0903 22:04:34.462558 25598 authenticator.hpp:376] Authentication success
> I0903 22:04:34.462635 25598 master.cpp:3677] Successfully authenticated principal 'test-principal' at scheduler-04e0b571-7e0c-4ef3-bb14-c6bbfd8ac9a4@140.211.11.27:44122
> I0903 22:04:34.462687 25590 authenticatee.hpp:305] Authentication success
> I0903 22:04:34.463219 25588 sched.cpp:357] Successfully authenticated with master master@140.211.11.27:44122
> I0903 22:04:34.463243 25588 sched.cpp:476] Sending registration request to master@140.211.11.27:44122
> I0903 22:04:34.463307 25588 master.cpp:1324] Received registration request from scheduler-04e0b571-7e0c-4ef3-bb14-c6bbfd8ac9a4@140.211.11.27:44122
> I0903 22:04:34.463330 25588 master.cpp:1284] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0903 22:04:34.463412 25588 master.cpp:1383] Registering framework 20140903-220433-453759884-44122-25565-0000 at scheduler-04e0b571-7e0c-4ef3-bb14-c6bbfd8ac9a4@140.211.11.27:44122
> I0903 22:04:34.463577 25598 sched.cpp:407] Framework registered with 20140903-220433-453759884-44122-25565-0000
> I0903 22:04:34.463728 25587 hierarchical_allocator_process.hpp:329] Added framework 20140903-220433-453759884-44122-25565-0000
> I0903 22:04:34.463739 25587 hierarchical_allocator_process.hpp:697] No resources available to allocate!
> I0903 22:04:34.463743 25587 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 5016ns
> I0903 22:04:34.463755 25598 sched.cpp:421] Scheduler::registered took 165035ns
> I0903 22:04:34.465558 25583 sched.cpp:227] Scheduler::disconnected took 6254ns
> I0903 22:04:34.465566 25583 sched.cpp:233] New master detected at master@140.211.11.27:44122
> I0903 22:04:34.465575 25583 sched.cpp:283] Authenticating with master master@140.211.11.27:44122
> I0903 22:04:34.465642 25583 authenticatee.hpp:128] Creating new client SASL connection
> I0903 22:04:34.465790 25583 master.cpp:1680] Deactivating framework 20140903-220433-453759884-44122-25565-0000
> I0903 22:04:34.465850 25583 master.cpp:3637] Authenticating scheduler-04e0b571-7e0c-4ef3-bb14-c6bbfd8ac9a4@140.211.11.27:44122
> I0903 22:04:34.465879 25601 hierarchical_allocator_process.hpp:405] Deactivated framework 20140903-220433-453759884-44122-25565-0000
> I0903 22:04:34.466047 25600 authenticator.hpp:156] Creating new server SASL connection
> I0903 22:04:34.466315 25600 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
> I0903 22:04:34.466326 25600 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0903 22:04:34.466346 25600 authenticator.hpp:262] Received SASL authentication start
> I0903 22:04:34.466418 25600 authenticator.hpp:384] Authentication requires more steps
> I0903 22:04:34.466436 25600 authenticatee.hpp:265] Received SASL authentication step
> I0903 22:04:34.466475 25600 authenticator.hpp:290] Received SASL authentication step
> I0903 22:04:34.466486 25600 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0903 22:04:34.466491 25600 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
> I0903 22:04:34.466496 25600 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0903 22:04:34.466502 25600 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0903 22:04:34.466506 25600 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0903 22:04:34.466509 25600 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0903 22:04:34.466516 25600 authenticator.hpp:376] Authentication success
> I0903 22:04:34.466596 25588 master.cpp:3677] Successfully authenticated principal 'test-principal' at scheduler-04e0b571-7e0c-4ef3-bb14-c6bbfd8ac9a4@140.211.11.27:44122
> I0903 22:04:34.466629 25597 authenticatee.hpp:305] Authentication success
> I0903 22:04:34.467062 25594 sched.cpp:357] Successfully authenticated with master master@140.211.11.27:44122
> I0903 22:04:34.467077 25594 sched.cpp:476] Sending registration request to master@140.211.11.27:44122
> I0903 22:04:34.467190 25588 master.cpp:1448] Received re-registration request from framework 20140903-220433-453759884-44122-25565-0000 at scheduler-04e0b571-7e0c-4ef3-bb14-c6bbfd8ac9a4@140.211.11.27:44122
> I0903 22:04:36.368134 25588 master.cpp:1284] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0903 22:04:34.542999 25594 hierarchical_allocator_process.hpp:697] No resources available to allocate!
> I0903 22:04:35.463639 25582 sched.cpp:476] Sending registration request to master@140.211.11.27:44122
> I0903 22:04:36.368185 25594 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 1.825177748secs
> I0903 22:04:36.368302 25588 master.cpp:1448] Received re-registration request from framework 20140903-220433-453759884-44122-25565-0000 at scheduler-04e0b571-7e0c-4ef3-bb14-c6bbfd8ac9a4@140.211.11.27:44122
> I0903 22:04:36.368330 25588 master.cpp:1284] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0903 22:04:36.368388 25582 sched.cpp:476] Sending registration request to master@140.211.11.27:44122
> : Failure
> Mock function called more times than expected - returning default value.
> Function call: authorize(@0x2ba11964c1b0 40-byte object <D0-ED 39-16 A1-2B 00-00 00-00 00-00 00-00 00-00 00-6C 01-3C A1-2B 00-00 30-20 00-3C A1-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 1409781876 (unix time) try "date -d @1409781876" if you are using GNU date ***
> I0903 22:04:36.368913 25598 sched.cpp:745] Stopping framework '20140903-220433-453759884-44122-25565-0000'
> PC: @ 0x2ba117a990d5 (unknown)
> *** SIGABRT (@0x3ea000063dd) received by PID 25565 (TID 0x2ba11964d700) from PID 25565; stack trace: ***
> @ 0x2ba117854cb0 (unknown)
> @ 0x2ba117a990d5 (unknown)
> @ 0x2ba117a9c83b (unknown)
> @ 0x9cba9d testing::internal::GoogleTestFailureReporter::ReportFailure()
> @ 0x790091 testing::internal::FunctionMockerBase<>::PerformDefaultAction()
> @ 0x790166 testing::internal::FunctionMockerBase<>::UntypedPerformDefaultAction()
> @ 0x9c3daa testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith()
> @ 0x787279 mesos::internal::tests::MockAuthorizer::authorize()
> @ 0x2ba1157c133d mesos::internal::master::Master::validate()
> @ 0x2ba1157c2b7a mesos::internal::master::Master::reregisterFramework()
> @ 0x2ba1157e0038 ProtobufProcess<>::handler2<>()
> @ 0x2ba1157dde89 std::tr1::_Function_handler<>::_M_invoke()
> @ 0x2ba1157b15f7 mesos::internal::master::Master::_visit()
> @ 0x2ba1157bfa3e mesos::internal::master::Master::visit()
> @ 0x2ba115caf5e7 process::ProcessManager::resume()
> @ 0x2ba115cb027c process::schedule()
> @ 0x2ba11784ce9a start_thread
> @ 0x2ba117b5731d (unknown)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)