Mailing-List: contact issues-help@mesos.apache.org; run by ezmlm
Precedence: bulk
Reply-To: dev@mesos.apache.org
Date: Wed, 11 Feb 2015 00:42:11 +0000 (UTC)
From: "Benjamin Mahler (JIRA)" <jira@apache.org>
To: issues@mesos.apache.org
Message-ID: <JIRA.12769122.1421875432000.7810.1423615331612@Atlassian.JIRA>
In-Reply-To: <JIRA.12769122.1421875432000@Atlassian.JIRA>
References: <JIRA.12769122.1421875432000@Atlassian.JIRA>
 <JIRA.12769122.1421875432381@arcas>
Subject: [jira] [Updated] (MESOS-2239)
 MasterAuthorizationTest.DuplicateRegistration is flaky
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit


     [ 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)