[
https://issues.apache.org/jira/browse/MESOS-3203?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14660974#comment-14660974
]
Vinod Kone commented on MESOS-3203:
-----------------------------------
Turns out this is because the scheduler sometimes retries registration (based
on a random backoff interval) which mucks up with expectations.
The fix is to simply pause the clock, much like what we did with the
re-registration test below in this file.
> MasterAuthorizationTest.DuplicateRegistration test is flaky
> -----------------------------------------------------------
>
> Key: MESOS-3203
> URL: https://issues.apache.org/jira/browse/MESOS-3203
> Project: Mesos
> Issue Type: Bug
> Components: test
> Environment:
> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu:14.04,label_exp=docker%7C%7CHadoop/639/consoleFull
> Reporter: Vinod Kone
> Assignee: Vinod Kone
>
> [ RUN ] MasterAuthorizationTest.DuplicateRegistration
> Using temporary directory
> '/tmp/MasterAuthorizationTest_DuplicateRegistration_NKT3f7'
> I0804 22:16:01.578500 26185 leveldb.cpp:176] Opened db in 2.188338ms
> I0804 22:16:01.579172 26185 leveldb.cpp:183] Compacted db in 645075ns
> I0804 22:16:01.579211 26185 leveldb.cpp:198] Created db iterator in 15766ns
> I0804 22:16:01.579227 26185 leveldb.cpp:204] Seeked to beginning of db in
> 1658ns
> I0804 22:16:01.579238 26185 leveldb.cpp:273] Iterated through 0 keys in the
> db in 313ns
> I0804 22:16:01.579282 26185 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0804 22:16:01.579787 26212 recover.cpp:449] Starting replica recovery
> I0804 22:16:01.580075 26212 recover.cpp:475] Replica is in EMPTY status
> I0804 22:16:01.581014 26205 replica.cpp:641] Replica in EMPTY status received
> a broadcasted recover request
> I0804 22:16:01.581357 26211 recover.cpp:195] Received a recover response from
> a replica in EMPTY status
> I0804 22:16:01.581761 26207 recover.cpp:566] Updating replica status to
> STARTING
> I0804 22:16:01.582334 26218 master.cpp:377] Master
> 20150804-221601-2550141356-59302-26185 (d6d349cd895b) started on
> 172.17.0.152:59302
> I0804 22:16:01.582355 26218 master.cpp:379] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5"
> --credentials="/tmp/MasterAuthorizationTest_DuplicateRegistration_NKT3f7/credentials"
> --framework_sorter="drf" --help="false" --initialize_driver_logging="true"
> --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
> --max_slave_ping_timeouts="5" --quiet="false"
> --recovery_slave_removal_limit="100%" --registry="replicated_log"
> --registry_fetch_timeout="1mins" --registry_store_timeout="25secs"
> --registry_strict="true" --root_submissions="true"
> --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins"
> --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-0.24.0/_inst/share/mesos/webui"
> --work_dir="/tmp/MasterAuthorizationTest_DuplicateRegistration_NKT3f7/master"
> --zk_session_timeout="10secs"
> I0804 22:16:01.582711 26218 master.cpp:424] Master only allowing
> authenticated frameworks to register
> I0804 22:16:01.582722 26218 master.cpp:429] Master only allowing
> authenticated slaves to register
> I0804 22:16:01.582728 26218 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/MasterAuthorizationTest_DuplicateRegistration_NKT3f7/credentials'
> I0804 22:16:01.582929 26204 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 421543ns
> I0804 22:16:01.582950 26204 replica.cpp:323] Persisted replica status to
> STARTING
> I0804 22:16:01.583032 26218 master.cpp:468] Using default 'crammd5'
> authenticator
> I0804 22:16:01.583132 26211 recover.cpp:475] Replica is in STARTING status
> I0804 22:16:01.583154 26218 master.cpp:505] Authorization enabled
> I0804 22:16:01.583356 26214 whitelist_watcher.cpp:79] No whitelist given
> I0804 22:16:01.583411 26217 hierarchical.hpp:346] Initialized hierarchical
> allocator process
> I0804 22:16:01.583976 26213 replica.cpp:641] Replica in STARTING status
> received a broadcasted recover request
> I0804 22:16:01.584187 26209 recover.cpp:195] Received a recover response from
> a replica in STARTING status
> I0804 22:16:01.584581 26213 master.cpp:1495] The newly elected leader is
> [email protected]:59302 with id 20150804-221601-2550141356-59302-26185
> I0804 22:16:01.584609 26213 master.cpp:1508] Elected as the leading master!
> I0804 22:16:01.584627 26213 master.cpp:1278] Recovering from registrar
> I0804 22:16:01.584656 26204 recover.cpp:566] Updating replica status to VOTING
> I0804 22:16:01.584770 26212 registrar.cpp:313] Recovering registrar
> I0804 22:16:01.585261 26218 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 370526ns
> I0804 22:16:01.585285 26218 replica.cpp:323] Persisted replica status to
> VOTING
> I0804 22:16:01.585412 26216 recover.cpp:580] Successfully joined the Paxos
> group
> I0804 22:16:01.585667 26216 recover.cpp:464] Recover process terminated
> I0804 22:16:01.586047 26213 log.cpp:661] Attempting to start the writer
> I0804 22:16:01.587164 26211 replica.cpp:477] Replica received implicit
> promise request with proposal 1
> I0804 22:16:01.587549 26211 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 358261ns
> I0804 22:16:01.587568 26211 replica.cpp:345] Persisted promised to 1
> I0804 22:16:01.588173 26209 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0804 22:16:01.589316 26208 replica.cpp:378] Replica received explicit
> promise request for position 0 with proposal 2
> I0804 22:16:01.589700 26208 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 351778ns
> I0804 22:16:01.589721 26208 replica.cpp:679] Persisted action at 0
> I0804 22:16:01.590698 26213 replica.cpp:511] Replica received write request
> for position 0
> I0804 22:16:01.590754 26213 leveldb.cpp:438] Reading position from leveldb
> took 31557ns
> I0804 22:16:01.591147 26213 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 321842ns
> I0804 22:16:01.591167 26213 replica.cpp:679] Persisted action at 0
> I0804 22:16:01.591790 26217 replica.cpp:658] Replica received learned notice
> for position 0
> I0804 22:16:01.592133 26217 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 315281ns
> I0804 22:16:01.592155 26217 replica.cpp:679] Persisted action at 0
> I0804 22:16:01.592180 26217 replica.cpp:664] Replica learned NOP action at
> position 0
> I0804 22:16:01.592686 26211 log.cpp:677] Writer started with ending position 0
> I0804 22:16:01.593729 26205 leveldb.cpp:438] Reading position from leveldb
> took 26394ns
> I0804 22:16:01.596165 26209 registrar.cpp:346] Successfully fetched the
> registry (0B) in 11.343104ms
> I0804 22:16:01.596281 26209 registrar.cpp:445] Applied 1 operations in
> 26242ns; attempting to update the 'registry'
> I0804 22:16:01.598415 26212 log.cpp:685] Attempting to append 178 bytes to
> the log
> I0804 22:16:01.598563 26215 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0804 22:16:01.599324 26215 replica.cpp:511] Replica received write request
> for position 1
> I0804 22:16:01.599778 26215 leveldb.cpp:343] Persisting action (197 bytes) to
> leveldb took 420523ns
> I0804 22:16:01.599800 26215 replica.cpp:679] Persisted action at 1
> I0804 22:16:01.600349 26204 replica.cpp:658] Replica received learned notice
> for position 1
> I0804 22:16:01.600684 26204 leveldb.cpp:343] Persisting action (199 bytes) to
> leveldb took 310315ns
> I0804 22:16:01.600706 26204 replica.cpp:679] Persisted action at 1
> I0804 22:16:01.600723 26204 replica.cpp:664] Replica learned APPEND action at
> position 1
> I0804 22:16:01.601632 26213 registrar.cpp:490] Successfully updated the
> 'registry' in 5.287936ms
> I0804 22:16:01.601747 26213 registrar.cpp:376] Successfully recovered
> registrar
> I0804 22:16:01.601826 26215 log.cpp:704] Attempting to truncate the log to 1
> I0804 22:16:01.601948 26210 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0804 22:16:01.602145 26208 master.cpp:1305] Recovered 0 slaves from the
> Registry (139B) ; allowing 10mins for slaves to re-register
> I0804 22:16:01.602859 26219 replica.cpp:511] Replica received write request
> for position 2
> I0804 22:16:01.603181 26219 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 284713ns
> I0804 22:16:01.603209 26219 replica.cpp:679] Persisted action at 2
> I0804 22:16:01.603984 26211 replica.cpp:658] Replica received learned notice
> for position 2
> I0804 22:16:01.604313 26211 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 302445ns
> I0804 22:16:01.604365 26211 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 29354ns
> I0804 22:16:01.604387 26211 replica.cpp:679] Persisted action at 2
> I0804 22:16:01.604408 26211 replica.cpp:664] Replica learned TRUNCATE action
> at position 2
> I0804 22:16:01.616402 26185 sched.cpp:164] Version: 0.24.0
> I0804 22:16:01.616902 26209 sched.cpp:262] New master detected at
> [email protected]:59302
> I0804 22:16:01.617000 26209 sched.cpp:318] Authenticating with master
> [email protected]:59302
> I0804 22:16:01.617019 26209 sched.cpp:325] Using default CRAM-MD5
> authenticatee
> I0804 22:16:01.617324 26212 authenticatee.cpp:115] Creating new client SASL
> connection
> I0804 22:16:01.617550 26209 master.cpp:4405] Authenticating
> [email protected]:59302
> I0804 22:16:01.617641 26212 authenticator.cpp:406] Starting authentication
> session for crammd5_authenticatee(259)@172.17.0.152:59302
> I0804 22:16:01.617858 26208 authenticator.cpp:92] Creating new server SASL
> connection
> I0804 22:16:01.618140 26216 authenticatee.cpp:206] Received SASL
> authentication mechanisms: CRAM-MD5
> I0804 22:16:01.618191 26216 authenticatee.cpp:232] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0804 22:16:01.618324 26213 authenticator.cpp:197] Received SASL
> authentication start
> I0804 22:16:01.618413 26213 authenticator.cpp:319] Authentication requires
> more steps
> I0804 22:16:01.618557 26216 authenticatee.cpp:252] Received SASL
> authentication step
> I0804 22:16:01.618664 26216 authenticator.cpp:225] Received SASL
> authentication step
> I0804 22:16:01.618703 26216 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: 'd6d349cd895b' server FQDN: 'd6d349cd895b'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0804 22:16:01.618719 26216 auxprop.cpp:174] Looking up auxiliary property
> '*userPassword'
> I0804 22:16:01.618778 26216 auxprop.cpp:174] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0804 22:16:01.618820 26216 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: 'd6d349cd895b' server FQDN: 'd6d349cd895b'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0804 22:16:01.618834 26216 auxprop.cpp:124] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0804 22:16:01.618839 26216 auxprop.cpp:124] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0804 22:16:01.618857 26216 authenticator.cpp:311] Authentication success
> I0804 22:16:01.618954 26219 authenticatee.cpp:292] Authentication success
> I0804 22:16:01.619035 26204 master.cpp:4435] Successfully authenticated
> principal 'test-principal' at
> [email protected]:59302
> I0804 22:16:01.619083 26219 authenticator.cpp:424] Authentication session
> cleanup for crammd5_authenticatee(259)@172.17.0.152:59302
> I0804 22:16:01.619309 26208 sched.cpp:407] Successfully authenticated with
> master [email protected]:59302
> I0804 22:16:01.619335 26208 sched.cpp:713] Sending SUBSCRIBE call to
> [email protected]:59302
> I0804 22:16:01.619494 26208 sched.cpp:746] Will retry registration in
> 439203ns if necessary
> I0804 22:16:01.619627 26217 master.cpp:1812] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:59302
> I0804 22:16:01.619695 26217 master.cpp:1534] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0804 22:16:01.620848 26217 sched.cpp:713] Sending SUBSCRIBE call to
> [email protected]:59302
> I0804 22:16:01.620929 26217 sched.cpp:746] Will retry registration in
> 2.099193326secs if necessary
> I0804 22:16:01.621036 26210 master.cpp:1812] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:59302
> I0804 22:16:01.621083 26210 master.cpp:1534] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0804 22:16:01.621727 26217 master.cpp:1876] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0804 22:16:01.621981 26208 sched.cpp:262] New master detected at
> [email protected]:59302
> I0804 22:16:01.622131 26208 sched.cpp:318] Authenticating with master
> [email protected]:59302
> I0804 22:16:01.622153 26208 sched.cpp:325] Using default CRAM-MD5
> authenticatee
> I0804 22:16:01.622323 26212 authenticatee.cpp:115] Creating new client SASL
> connection
> I0804 22:16:01.622324 26210 hierarchical.hpp:391] Added framework
> 20150804-221601-2550141356-59302-26185-0000
> I0804 22:16:01.622369 26210 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:01.622386 26210 hierarchical.hpp:908] Performed allocation for 0
> slaves in 28592ns
> I0804 22:16:01.622511 26210 sched.cpp:640] Framework registered with
> 20150804-221601-2550141356-59302-26185-0000
> I0804 22:16:01.622586 26210 sched.cpp:654] Scheduler::registered took 48005ns
> I0804 22:16:01.622592 26208 master.cpp:4405] Authenticating
> [email protected]:59302
> I0804 22:16:01.622673 26212 authenticator.cpp:406] Starting authentication
> session for crammd5_authenticatee(260)@172.17.0.152:59302
> I0804 22:16:01.622923 26205 authenticator.cpp:92] Creating new server SASL
> connection
> I0804 22:16:01.623112 26204 authenticatee.cpp:206] Received SASL
> authentication mechanisms: CRAM-MD5
> I0804 22:16:01.623133 26216 master.cpp:1870] Dropping SUBSCRIBE call for
> framework 'default' at
> [email protected]:59302:
> Re-authentication in progress
> I0804 22:16:01.623144 26204 authenticatee.cpp:232] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0804 22:16:01.623258 26215 authenticator.cpp:197] Received SASL
> authentication start
> I0804 22:16:01.623313 26215 authenticator.cpp:319] Authentication requires
> more steps
> I0804 22:16:01.623394 26215 authenticatee.cpp:252] Received SASL
> authentication step
> I0804 22:16:01.623512 26212 authenticator.cpp:225] Received SASL
> authentication step
> I0804 22:16:01.623546 26212 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: 'd6d349cd895b' server FQDN: 'd6d349cd895b'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0804 22:16:01.623564 26212 auxprop.cpp:174] Looking up auxiliary property
> '*userPassword'
> I0804 22:16:01.623603 26212 auxprop.cpp:174] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0804 22:16:01.623622 26212 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: 'd6d349cd895b' server FQDN: 'd6d349cd895b'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0804 22:16:01.623631 26212 auxprop.cpp:124] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0804 22:16:01.623636 26212 auxprop.cpp:124] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0804 22:16:01.623649 26212 authenticator.cpp:311] Authentication success
> I0804 22:16:01.623777 26212 authenticatee.cpp:292] Authentication success
> I0804 22:16:01.623846 26212 master.cpp:4435] Successfully authenticated
> principal 'test-principal' at
> [email protected]:59302
> I0804 22:16:01.623913 26212 authenticator.cpp:424] Authentication session
> cleanup for crammd5_authenticatee(260)@172.17.0.152:59302
> I0804 22:16:01.624130 26212 sched.cpp:407] Successfully authenticated with
> master [email protected]:59302
> I0804 22:16:02.583772 26218 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:02.583818 26218 hierarchical.hpp:908] Performed allocation for 0
> slaves in 80538ns
> I0804 22:16:03.585110 26211 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:03.585156 26211 hierarchical.hpp:908] Performed allocation for 0
> slaves in 69272ns
> I0804 22:16:04.586539 26214 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:04.586586 26214 hierarchical.hpp:908] Performed allocation for 0
> slaves in 79232ns
> I0804 22:16:05.587239 26209 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:05.587293 26209 hierarchical.hpp:908] Performed allocation for 0
> slaves in 85128ns
> I0804 22:16:06.587935 26212 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:06.587985 26212 hierarchical.hpp:908] Performed allocation for 0
> slaves in 78141ns
> I0804 22:16:07.588817 26214 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:07.588865 26214 hierarchical.hpp:908] Performed allocation for 0
> slaves in 81433ns
> I0804 22:16:08.589857 26214 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:08.589906 26214 hierarchical.hpp:908] Performed allocation for 0
> slaves in 71929ns
> I0804 22:16:09.591085 26207 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:09.591133 26207 hierarchical.hpp:908] Performed allocation for 0
> slaves in 78223ns
> I0804 22:16:10.591737 26207 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:10.591785 26207 hierarchical.hpp:908] Performed allocation for 0
> slaves in 71894ns
> I0804 22:16:11.593166 26210 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:11.593221 26210 hierarchical.hpp:908] Performed allocation for 0
> slaves in 89782ns
> I0804 22:16:12.593647 26212 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:12.593689 26212 hierarchical.hpp:908] Performed allocation for 0
> slaves in 69426ns
> I0804 22:16:13.594154 26210 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:13.594202 26210 hierarchical.hpp:908] Performed allocation for 0
> slaves in 70581ns
> I0804 22:16:14.594712 26207 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:14.594758 26207 hierarchical.hpp:908] Performed allocation for 0
> slaves in 71201ns
> I0804 22:16:15.595412 26219 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:15.595464 26219 hierarchical.hpp:908] Performed allocation for 0
> slaves in 85183ns
> I0804 22:16:16.596201 26217 hierarchical.hpp:1008] No resources available to
> allocate!
> I0804 22:16:16.596247 26217 hierarchical.hpp:908] Performed allocation for 0
> slaves in 95132ns
> ../../src/tests/master_authorization_tests.cpp:794: Failure
> Failed to wait 15secs for frameworkRegisteredMessage
> I0804 22:16:16.624354 26212 master.cpp:966] Framework
> 20150804-221601-2550141356-59302-26185-0000 (default) at
> [email protected]:59302 disconnected
> I0804 22:16:16.624398 26212 master.cpp:2092] Disconnecting framework
> 20150804-221601-2550141356-59302-26185-0000 (default) at
> [email protected]:59302
> I0804 22:16:16.624445 26212 master.cpp:2116] Deactivating framework
> 20150804-221601-2550141356-59302-26185-0000 (default) at
> [email protected]:59302
> I0804 22:16:16.624686 26212 master.cpp:988] Giving framework
> 20150804-221601-2550141356-59302-26185-0000 (default) at
> [email protected]:59302 0ns to
> failover
> I0804 22:16:16.625641 26219 hierarchical.hpp:474] Deactivated framework
> 20150804-221601-2550141356-59302-26185-0000
> I0804 22:16:16.626688 26218 master.cpp:4180] Framework failover timeout,
> removing framework 20150804-221601-2550141356-59302-26185-0000 (default) at
> [email protected]:59302
> I0804 22:16:16.626734 26218 master.cpp:4759] Removing framework
> 20150804-221601-2550141356-59302-26185-0000 (default) at
> [email protected]:59302
> I0804 22:16:16.627074 26218 master.cpp:858] Master terminating
> I0804 22:16:16.627218 26215 hierarchical.hpp:428] Removed framework
> 20150804-221601-2550141356-59302-26185-0000
> ../../3rdparty/libprocess/include/process/gmock.hpp:365: Failure
> Actual function call count doesn't match EXPECT_CALL(filter->mock,
> filter(testing::A<const MessageEvent&>()))...
> Expected args: message matcher (8-byte object <98-98 02-AC 54-2B 00-00>,
> 1-byte object <97>, 1-byte object <D2>)
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] MasterAuthorizationTest.DuplicateRegistration (15056 ms)
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
