[
https://issues.apache.org/jira/browse/MESOS-2239?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Adam B updated MESOS-2239:
--------------------------
Labels: flaky flaky-test (was: flaky-test)
> MasterAuthorizationTest.DuplicateRegistration is flaky
> ------------------------------------------------------
>
> Key: MESOS-2239
> URL: https://issues.apache.org/jira/browse/MESOS-2239
> Project: Mesos
> Issue Type: Bug
> Components: test
> Environment: CentOS5 gcc-4.8
> Reporter: Jie Yu
> Labels: flaky, flaky-test
>
> {noformat}
> 19:30:44 DEBUG: [ RUN ] MasterAuthorizationTest.DuplicateRegistration
> 19:30:44 DEBUG: Using temporary directory
> '/tmp/MasterAuthorizationTest_DuplicateRegistration_lTKlxz'
> 19:30:44 DEBUG: I0121 19:30:44.583595 54842 leveldb.cpp:176] Opened db in
> 2.002477ms
> 19:30:44 DEBUG: I0121 19:30:44.584470 54842 leveldb.cpp:183] Compacted db in
> 848351ns
> 19:30:44 DEBUG: I0121 19:30:44.584492 54842 leveldb.cpp:198] Created db
> iterator in 3830ns
> 19:30:44 DEBUG: I0121 19:30:44.584506 54842 leveldb.cpp:204] Seeked to
> beginning of db in 962ns
> 19:30:44 DEBUG: I0121 19:30:44.584519 54842 leveldb.cpp:273] Iterated through
> 0 keys in the db in 598ns
> 19:30:44 DEBUG: I0121 19:30:44.584537 54842 replica.cpp:744] Replica
> recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> 19:30:44 DEBUG: I0121 19:30:44.584684 54873 recover.cpp:449] Starting replica
> recovery
> 19:30:44 DEBUG: I0121 19:30:44.584774 54859 recover.cpp:475] Replica is in
> EMPTY status
> 19:30:44 DEBUG: I0121 19:30:44.586305 54881 replica.cpp:641] Replica in EMPTY
> status received a broadcasted recover request
> 19:30:44 DEBUG: I0121 19:30:44.586943 54866 recover.cpp:195] Received a
> recover response from a replica in EMPTY status
> 19:30:44 DEBUG: I0121 19:30:44.587247 54872 recover.cpp:566] Updating replica
> status to STARTING
> 19:30:44 DEBUG: I0121 19:30:44.587838 54867 leveldb.cpp:306] Persisting
> metadata (8 bytes) to leveldb took 393697ns
> 19:30:44 DEBUG: I0121 19:30:44.587862 54867 replica.cpp:323] Persisted
> replica status to STARTING
> 19:30:44 DEBUG: I0121 19:30:44.587920 54877 recover.cpp:475] Replica is in
> STARTING status
> 19:30:44 DEBUG: I0121 19:30:44.588341 54868 replica.cpp:641] Replica in
> STARTING status received a broadcasted recover request
> 19:30:44 DEBUG: I0121 19:30:44.588577 54877 recover.cpp:195] Received a
> recover response from a replica in STARTING status
> 19:30:44 DEBUG: I0121 19:30:44.589040 54863 recover.cpp:566] Updating replica
> status to VOTING
> 19:30:44 DEBUG: I0121 19:30:44.589344 54871 leveldb.cpp:306] Persisting
> metadata (8 bytes) to leveldb took 268257ns
> 19:30:44 DEBUG: I0121 19:30:44.589361 54871 replica.cpp:323] Persisted
> replica status to VOTING
> 19:30:44 DEBUG: I0121 19:30:44.589426 54858 recover.cpp:580] Successfully
> joined the Paxos group
> 19:30:44 DEBUG: I0121 19:30:44.589735 54858 recover.cpp:464] Recover process
> terminated
> 19:30:44 DEBUG: I0121 19:30:44.593657 54866 master.cpp:262] Master
> 20150121-193044-1711542956-52053-54842 (atlc-bev-05-sr1.corpdc.twttr.net)
> started on 172.18.4.102:52053
> 19:30:44 DEBUG: I0121 19:30:44.593690 54866 master.cpp:308] Master only
> allowing authenticated frameworks to register
> 19:30:44 DEBUG: I0121 19:30:44.593699 54866 master.cpp:313] Master only
> allowing authenticated slaves to register
> 19:30:44 DEBUG: I0121 19:30:44.593708 54866 credentials.hpp:36] Loading
> credentials for authentication from
> '/tmp/MasterAuthorizationTest_DuplicateRegistration_lTKlxz/credentials'
> 19:30:44 DEBUG: I0121 19:30:44.593808 54866 master.cpp:357] Authorization
> enabled
> 19:30:44 DEBUG: I0121 19:30:44.594319 54871 master.cpp:1219] The newly
> elected leader is [email protected]:52053 with id
> 20150121-193044-1711542956-52053-54842
> 19:30:44 DEBUG: I0121 19:30:44.594336 54871 master.cpp:1232] Elected as the
> leading master!
> 19:30:44 DEBUG: I0121 19:30:44.594343 54871 master.cpp:1050] Recovering from
> registrar
> 19:30:44 DEBUG: I0121 19:30:44.594403 54867 registrar.cpp:313] Recovering
> registrar
> 19:30:44 DEBUG: I0121 19:30:44.594558 54858 log.cpp:660] Attempting to start
> the writer
> 19:30:44 DEBUG: I0121 19:30:44.595000 54859 replica.cpp:477] Replica received
> implicit promise request with proposal 1
> 19:30:44 DEBUG: I0121 19:30:44.595340 54859 leveldb.cpp:306] Persisting
> metadata (8 bytes) to leveldb took 319942ns
> 19:30:44 DEBUG: I0121 19:30:44.595360 54859 replica.cpp:345] Persisted
> promised to 1
> 19:30:44 DEBUG: I0121 19:30:44.595700 54878 coordinator.cpp:230] Coordinator
> attemping to fill missing position
> 19:30:44 DEBUG: I0121 19:30:44.596330 54859 replica.cpp:378] Replica received
> explicit promise request for position 0 with proposal 2
> 19:30:44 DEBUG: I0121 19:30:44.596618 54859 leveldb.cpp:343] Persisting
> action (8 bytes) to leveldb took 267421ns
> 19:30:44 DEBUG: I0121 19:30:44.596632 54859 replica.cpp:679] Persisted action
> at 0
> 19:30:44 DEBUG: I0121 19:30:44.597185 54868 replica.cpp:511] Replica received
> write request for position 0
> 19:30:44 DEBUG: I0121 19:30:44.597210 54868 leveldb.cpp:438] Reading position
> from leveldb took 9925ns
> 19:30:44 DEBUG: I0121 19:30:44.597522 54868 leveldb.cpp:343] Persisting
> action (14 bytes) to leveldb took 297290ns
> 19:30:44 DEBUG: I0121 19:30:44.597537 54868 replica.cpp:679] Persisted action
> at 0
> 19:30:44 DEBUG: I0121 19:30:44.597746 54859 replica.cpp:658] Replica received
> learned notice for position 0
> 19:30:44 DEBUG: I0121 19:30:44.597869 54859 leveldb.cpp:343] Persisting
> action (16 bytes) to leveldb took 101253ns
> 19:30:44 DEBUG: I0121 19:30:44.597892 54859 replica.cpp:679] Persisted action
> at 0
> 19:30:44 DEBUG: I0121 19:30:44.597906 54859 replica.cpp:664] Replica learned
> NOP action at position 0
> 19:30:44 DEBUG: I0121 19:30:44.599227 54859 log.cpp:676] Writer started with
> ending position 0
> 19:30:44 DEBUG: I0121 19:30:44.599809 54871 leveldb.cpp:438] Reading position
> from leveldb took 10459ns
> 19:30:44 DEBUG: I0121 19:30:44.602128 54881 registrar.cpp:346] Successfully
> fetched the registry (0B) in 7.699968ms
> 19:30:44 DEBUG: I0121 19:30:44.602166 54881 registrar.cpp:445] Applied 1
> operations in 2405ns; attempting to update the 'registry'
> 19:30:44 DEBUG: I0121 19:30:44.603883 54870 log.cpp:684] Attempting to append
> 153 bytes to the log
> 19:30:44 DEBUG: I0121 19:30:44.603946 54869 coordinator.cpp:340] Coordinator
> attempting to write APPEND action at position 1
> 19:30:44 DEBUG: I0121 19:30:44.604483 54868 replica.cpp:511] Replica received
> write request for position 1
> 19:30:44 DEBUG: I0121 19:30:44.604846 54868 leveldb.cpp:343] Persisting
> action (172 bytes) to leveldb took 338069ns
> 19:30:44 DEBUG: I0121 19:30:44.604862 54868 replica.cpp:679] Persisted action
> at 1
> 19:30:44 DEBUG: I0121 19:30:44.605015 54880 replica.cpp:658] Replica received
> learned notice for position 1
> 19:30:44 DEBUG: I0121 19:30:44.605134 54880 leveldb.cpp:343] Persisting
> action (174 bytes) to leveldb took 100790ns
> 19:30:44 DEBUG: I0121 19:30:44.605150 54880 replica.cpp:679] Persisted action
> at 1
> 19:30:44 DEBUG: I0121 19:30:44.605157 54880 replica.cpp:664] Replica learned
> APPEND action at position 1
> 19:30:44 DEBUG: I0121 19:30:44.605319 54868 registrar.cpp:490] Successfully
> updated the 'registry' in 3.131904ms
> 19:30:44 DEBUG: I0121 19:30:44.605988 54868 registrar.cpp:376] Successfully
> recovered registrar
> 19:30:44 DEBUG: I0121 19:30:44.606065 54868 log.cpp:703] Attempting to
> truncate the log to 1
> 19:30:44 DEBUG: I0121 19:30:44.606083 54866 master.cpp:1077] Recovered 0
> slaves from the Registry (115B) ; allowing 10mins for slaves to re-register
> 19:30:44 DEBUG: I0121 19:30:44.606189 54878 coordinator.cpp:340] Coordinator
> attempting to write TRUNCATE action at position 2
> 19:30:44 DEBUG: I0121 19:30:44.606932 54862 replica.cpp:511] Replica received
> write request for position 2
> 19:30:44 DEBUG: I0121 19:30:44.607203 54862 leveldb.cpp:343] Persisting
> action (16 bytes) to leveldb took 249511ns
> 19:30:44 DEBUG: I0121 19:30:44.607218 54862 replica.cpp:679] Persisted action
> at 2
> 19:30:44 DEBUG: I0121 19:30:44.607465 54864 replica.cpp:658] Replica received
> learned notice for position 2
> 19:30:44 DEBUG: I0121 19:30:44.607799 54864 leveldb.cpp:343] Persisting
> action (18 bytes) to leveldb took 313807ns
> 19:30:44 DEBUG: I0121 19:30:44.607825 54864 leveldb.cpp:401] Deleting ~1 keys
> from leveldb took 11994ns
> 19:30:44 DEBUG: I0121 19:30:44.607836 54864 replica.cpp:679] Persisted action
> at 2
> 19:30:44 DEBUG: I0121 19:30:44.607843 54864 replica.cpp:664] Replica learned
> TRUNCATE action at position 2
> 19:30:44 DEBUG: I0121 19:30:44.621534 54842 sched.cpp:151] Version:
> 0.22.0-jyu1
> 19:30:44 DEBUG: I0121 19:30:44.621914 54871 sched.cpp:248] New master
> detected at [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.621948 54871 sched.cpp:304] Authenticating
> with master [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.621959 54871 sched.cpp:311] Using default
> CRAM-MD5 authenticatee
> 19:30:44 DEBUG: I0121 19:30:44.622061 54858 authenticatee.hpp:138] Creating
> new client SASL connection
> 19:30:44 DEBUG: I0121 19:30:44.622356 54865 master.cpp:4130] Authenticating
> [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.622375 54865 master.cpp:4141] Using default
> CRAM-MD5 authenticator
> 19:30:44 DEBUG: I0121 19:30:44.622581 54860 authenticator.hpp:170] Creating
> new server SASL connection
> 19:30:44 DEBUG: I0121 19:30:44.622771 54865 authenticatee.hpp:229] Received
> SASL authentication mechanisms: CRAM-MD5
> 19:30:44 DEBUG: I0121 19:30:44.622788 54865 authenticatee.hpp:255] Attempting
> to authenticate with mechanism 'CRAM-MD5'
> 19:30:44 DEBUG: I0121 19:30:44.622998 54862 authenticator.hpp:276] Received
> SASL authentication start
> 19:30:44 DEBUG: I0121 19:30:44.623064 54862 authenticator.hpp:398]
> Authentication requires more steps
> 19:30:44 DEBUG: I0121 19:30:44.623167 54862 authenticatee.hpp:275] Received
> SASL authentication step
> 19:30:44 DEBUG: I0121 19:30:44.623239 54874 authenticator.hpp:304] Received
> SASL authentication step
> 19:30:44 DEBUG: I0121 19:30:44.623270 54874 authenticator.hpp:390]
> Authentication success
> 19:30:44 DEBUG: I0121 19:30:44.623298 54874 authenticatee.hpp:315]
> Authentication success
> 19:30:44 DEBUG: I0121 19:30:44.623317 54867 master.cpp:4188] Successfully
> authenticated principal 'test-principal' at
> [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.623539 54877 sched.cpp:392] Successfully
> authenticated with master [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.623693 54867 master.cpp:1417] Received
> registration request for framework 'default' at
> [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.623718 54867 master.cpp:1298] Authorizing
> framework principal 'test-principal' to receive offers for role '*'
> 19:30:44 DEBUG: I0121 19:30:44.624754 54858 master.cpp:1417] Received
> registration request for framework 'default' at
> [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.624781 54858 master.cpp:1298] Authorizing
> framework principal 'test-principal' to receive offers for role '*'
> 19:30:44 DEBUG: I0121 19:30:44.626006 54870 sched.cpp:248] New master
> detected at [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.626066 54870 sched.cpp:304] Authenticating
> with master [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.626078 54870 sched.cpp:311] Using default
> CRAM-MD5 authenticatee
> 19:30:44 DEBUG: I0121 19:30:44.626211 54858 authenticatee.hpp:138] Creating
> new client SASL connection
> 19:30:44 DEBUG: I0121 19:30:44.626227 54869 master.cpp:1481] Registering
> framework 20150121-193044-1711542956-52053-54842-0000 (default) at
> [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.626377 54864
> hierarchical_allocator_process.hpp:319] Added framework
> 20150121-193044-1711542956-52053-54842-0000
> 19:30:44 DEBUG: I0121 19:30:44.626714 54869 master.cpp:4130] Authenticating
> [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.626727 54858 sched.cpp:442] Framework
> registered with 20150121-193044-1711542956-52053-54842-0000
> 19:30:44 DEBUG: I0121 19:30:44.626736 54869 master.cpp:4141] Using default
> CRAM-MD5 authenticator
> 19:30:44 DEBUG: I0121 19:30:44.627017 54873 authenticator.hpp:170] Creating
> new server SASL connection
> 19:30:44 DEBUG: I0121 19:30:44.627029 54874 master.cpp:1449] Dropping
> registration request for framework 'default' at
> [email protected]:52053 because new
> authentication attempt is in progress
> 19:30:44 DEBUG: I0121 19:30:44.627122 54878 authenticatee.hpp:229] Received
> SASL authentication mechanisms: CRAM-MD5
> 19:30:44 DEBUG: I0121 19:30:44.627146 54878 authenticatee.hpp:255] Attempting
> to authenticate with mechanism 'CRAM-MD5'
> 19:30:44 DEBUG: I0121 19:30:44.627214 54862 authenticator.hpp:276] Received
> SASL authentication start
> 19:30:44 DEBUG: I0121 19:30:44.627281 54862 authenticator.hpp:398]
> Authentication requires more steps
> 19:30:44 DEBUG: I0121 19:30:44.627336 54867 authenticatee.hpp:275] Received
> SASL authentication step
> 19:30:44 DEBUG: I0121 19:30:44.627410 54860 authenticator.hpp:304] Received
> SASL authentication step
> 19:30:44 DEBUG: I0121 19:30:44.627444 54860 authenticator.hpp:390]
> Authentication success
> 19:30:44 DEBUG: I0121 19:30:44.627487 54857 authenticatee.hpp:315]
> Authentication success
> 19:30:44 DEBUG: I0121 19:30:44.627498 54860 master.cpp:4188] Successfully
> authenticated principal 'test-principal' at
> [email protected]:52053
> 19:30:44 DEBUG: I0121 19:30:44.627611 54858 sched.cpp:392] Successfully
> authenticated with master [email protected]:52053
> 19:30:54 DEBUG: tests/master_authorization_tests.cpp:798: Failure
> 19:30:54 DEBUG: Failed to wait 10secs for frameworkRegisteredMessage
> 19:30:54 DEBUG: I0121 19:30:54.627919 54881 master.cpp:745] Framework
> 20150121-193044-1711542956-52053-54842-0000 (default) at
> [email protected]:52053 disconnected
> 19:30:54 DEBUG: I0121 19:30:54.627961 54881 master.cpp:1786] Disconnecting
> framework 20150121-193044-1711542956-52053-54842-0000 (default) at
> [email protected]:52053
> 19:30:54 DEBUG: I0121 19:30:54.627990 54881 master.cpp:1802] Deactivating
> framework 20150121-193044-1711542956-52053-54842-0000 (default) at
> [email protected]:52053
> 19:30:54 DEBUG: I0121 19:30:54.628021 54881 master.cpp:767] Giving framework
> 20150121-193044-1711542956-52053-54842-0000 (default) at
> [email protected]:52053 0ns to
> failover
> 19:30:54 DEBUG: I0121 19:30:54.628072 54866
> hierarchical_allocator_process.hpp:398] Deactivated framework
> 20150121-193044-1711542956-52053-54842-0000
> 19:30:54 DEBUG: I0121 19:30:54.628149 54871 master.cpp:3942] Framework
> failover timeout, removing framework
> 20150121-193044-1711542956-52053-54842-0000 (default) at
> [email protected]:52053
> 19:30:54 DEBUG: I0121 19:30:54.628175 54871 master.cpp:4500] Removing
> framework 20150121-193044-1711542956-52053-54842-0000 (default) at
> [email protected]:52053
> 19:30:54 DEBUG: I0121 19:30:54.632371 54862
> hierarchical_allocator_process.hpp:352] Removed framework
> 20150121-193044-1711542956-52053-54842-0000
> 19:30:54 DEBUG: I0121 19:30:54.632501 54842 master.cpp:654] Master terminating
> 19:30:54 DEBUG: ../3rdparty/libprocess/include/process/gmock.hpp:356: Failure
> 19:30:54 DEBUG: Actual function call count doesn't match
> EXPECT_CALL(filter->mock, filter(testing::A<const MessageEvent&>()))...
> 19:30:54 DEBUG: Expected args: message matcher (8-byte object <48-CA
> 09-50 EF-7F 00-00>, 1-byte object <F5>, 1-byte object <30>)
> 19:30:54 DEBUG: Expected: to be called once
> 19:30:54 DEBUG: Actual: never called - unsatisfied and active
> 19:30:54 DEBUG: [ FAILED ] MasterAuthorizationTest.DuplicateRegistration
> (10063 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
