mesos-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Benjamin Mahler (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (MESOS-2239) MasterAuthorizationTest.DuplicateRegistration is flaky
Date Wed, 11 Feb 2015 00:42:11 GMT

     [ https://issues.apache.org/jira/browse/MESOS-2239?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Benjamin Mahler updated MESOS-2239:
-----------------------------------
    Component/s: test
         Labels: flaky-test  (was: )

> 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-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 master@172.18.4.102: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 master@172.18.4.102:52053
> 19:30:44 DEBUG: I0121 19:30:44.621948 54871 sched.cpp:304] Authenticating with master
master@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102:52053
> 19:30:44 DEBUG: I0121 19:30:44.623539 54877 sched.cpp:392] Successfully authenticated
with master master@172.18.4.102:52053
> 19:30:44 DEBUG: I0121 19:30:44.623693 54867 master.cpp:1417] Received registration request
for framework 'default' at scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102: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 master@172.18.4.102:52053
> 19:30:44 DEBUG: I0121 19:30:44.626066 54870 sched.cpp:304] Authenticating with master
master@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102:52053
> 19:30:44 DEBUG: I0121 19:30:44.627611 54858 sched.cpp:392] Successfully authenticated
with master master@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102:52053
> 19:30:54 DEBUG: I0121 19:30:54.627990 54881 master.cpp:1802] Deactivating framework 20150121-193044-1711542956-52053-54842-0000
(default) at scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102:52053
> 19:30:54 DEBUG: I0121 19:30:54.628021 54881 master.cpp:767] Giving framework 20150121-193044-1711542956-52053-54842-0000
(default) at scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102: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 scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102:52053
> 19:30:54 DEBUG: I0121 19:30:54.628175 54871 master.cpp:4500] Removing framework 20150121-193044-1711542956-52053-54842-0000
(default) at scheduler-b353ed5f-d60b-4da3-a951-6bc65b5466c4@172.18.4.102: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)

Mime
View raw message