Jie Yu created MESOS-2239:
-----------------------------
Summary: MasterAuthorizationTest.DuplicateRegistration is flaky
Key: MESOS-2239
URL: https://issues.apache.org/jira/browse/MESOS-2239
Project: Mesos
Issue Type: Bug
Environment: CentOS5 gcc-4.8
Reporter: Jie Yu
{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)
