Details
-
Twitter Mesos Q3 Sprint 3
-
1
Description
[ 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 master@172.17.0.152: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 master@172.17.0.152:59302
I0804 22:16:01.617000 26209 sched.cpp:318] Authenticating with master master@172.17.0.152: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 scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152: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 scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152: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 master@172.17.0.152:59302
I0804 22:16:01.619335 26208 sched.cpp:713] Sending SUBSCRIBE call to master@172.17.0.152: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 scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152: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 master@172.17.0.152: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 scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152: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 master@172.17.0.152:59302
I0804 22:16:01.622131 26208 sched.cpp:318] Authenticating with master master@172.17.0.152: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 scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152: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 scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152: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 scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152: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 master@172.17.0.152: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 scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152:59302 disconnected
I0804 22:16:16.624398 26212 master.cpp:2092] Disconnecting framework 20150804-221601-2550141356-59302-26185-0000 (default) at scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152:59302
I0804 22:16:16.624445 26212 master.cpp:2116] Deactivating framework 20150804-221601-2550141356-59302-26185-0000 (default) at scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152:59302
I0804 22:16:16.624686 26212 master.cpp:988] Giving framework 20150804-221601-2550141356-59302-26185-0000 (default) at scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152: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 scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152:59302
I0804 22:16:16.626734 26218 master.cpp:4759] Removing framework 20150804-221601-2550141356-59302-26185-0000 (default) at scheduler-ac5e7b68-e2d2-441c-a5f5-60c1ff8cf00c@172.17.0.152: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)
Attachments
Issue Links
- duplicates
-
MESOS-2239 MasterAuthorizationTest.DuplicateRegistration is flaky
-
- Resolved
-