[
https://issues.apache.org/jira/browse/MESOS-8266?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16761770#comment-16761770
]
Vinod Kone commented on MESOS-8266:
-----------------------------------
Observed this on internal CI.
{code}
[ RUN ] MasterMaintenanceTest.AcceptInvalidInverseOffer
I0206 05:13:46.592031 27319 cluster.cpp:174] Creating default 'local' authorizer
I0206 05:13:46.593217 27341 master.cpp:414] Master
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8 (ip-172-16-10-145.ec2.internal) started on
172.16.10.145:36957
I0206 05:13:46.593240 27341 master.cpp:417] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --allocator
="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwri
te="true" --authentication_v0_timeout="15secs" --authenticators="crammd5"
--authorizers="local" --credentials="/tmp/cBTYhp/credentials"
--filter_gpu_resources="true" --framework_s
orter="drf" --help="false" --hostname_lookup="true"
--http_authenticators="basic" --http_framework_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize=
"true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--max_operator_event_stream
_subscribers="1000" --max_unreachable_tasks_per_framework="1000"
--memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32"
--port="5050" --publish_per_framework_me
trics="true" --quiet="false" --recovery_agent_removal_limit="100%"
--registry="in_memory" --registry_fetch_timeout="1mins"
--registry_gc_interval="15mins" --registry_max_agent_age
="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--require_agent_domain="false" --role_sorter="drf" --root_submissions="t
rue" --version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/tmp/cBTYhp/master" --zk_session_timeout="10secs"
I0206 05:13:46.593377 27341 master.cpp:466] Master only allowing authenticated
frameworks to register
I0206 05:13:46.593385 27341 master.cpp:472] Master only allowing authenticated
agents to register
I0206 05:13:46.593391 27341 master.cpp:478] Master only allowing authenticated
HTTP frameworks to register
I0206 05:13:46.593397 27341 credentials.hpp:37] Loading credentials for
authentication from '/tmp/cBTYhp/credentials'
I0206 05:13:46.593485 27341 master.cpp:522] Using default 'crammd5'
authenticator
I0206 05:13:46.593521 27341 http.cpp:965] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0206 05:13:46.593560 27341 http.cpp:965] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0206 05:13:46.593582 27341 http.cpp:965] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0206 05:13:46.593605 27341 master.cpp:603] Authorization enabled
I0206 05:13:46.594100 27340 hierarchical.cpp:176] Initialized hierarchical
allocator process
I0206 05:13:46.594298 27341 whitelist_watcher.cpp:77] No whitelist given
I0206 05:13:46.594842 27344 master.cpp:2103] Elected as the leading master!
I0206 05:13:46.594856 27344 master.cpp:1638] Recovering from registrar
I0206 05:13:46.594935 27344 registrar.cpp:339] Recovering registrar
I0206 05:13:46.595073 27344 registrar.cpp:383] Successfully fetched the
registry (0B) in 115968ns
I0206 05:13:46.595101 27344 registrar.cpp:487] Applied 1 operations in 6424ns;
attempting to update the registry
I0206 05:13:46.595223 27344 registrar.cpp:544] Successfully updated the
registry in 105984ns
I0206 05:13:46.595314 27344 registrar.cpp:416] Successfully recovered registrar
I0206 05:13:46.595392 27344 master.cpp:1752] Recovered 0 agents from the
registry (176B); allowing 10mins for agents to reregister
I0206 05:13:46.595446 27344 hierarchical.cpp:216] Skipping recovery of
hierarchical allocator: nothing to recover
W0206 05:13:46.595887 27319 process.cpp:2829] Attempted to spawn already
running process version@172.16.10.145:36957
I0206 05:13:46.597141 27319 sched.cpp:232] Version: 1.8.0
I0206 05:13:46.597421 27345 sched.cpp:336] New master detected at
master@172.16.10.145:36957
I0206 05:13:46.597458 27345 sched.cpp:401] Authenticating with master
master@172.16.10.145:36957
I0206 05:13:46.597509 27345 sched.cpp:408] Using default CRAM-MD5 authenticatee
I0206 05:13:46.597611 27345 authenticatee.cpp:121] Creating new client SASL
connection
I0206 05:13:46.597707 27345 master.cpp:9902] Authenticating
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957
I0206 05:13:46.597754 27345 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(459)@172.16.10.145:36957
I0206 05:13:46.597805 27345 authenticator.cpp:98] Creating new server SASL
connection
I0206 05:13:46.597946 27345 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0206 05:13:46.597962 27345 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0206 05:13:46.597993 27345 authenticator.cpp:204] Received SASL authentication
start
I0206 05:13:46.598042 27345 authenticator.cpp:326] Authentication requires more
steps
I0206 05:13:46.598074 27345 authenticatee.cpp:259] Received SASL authentication
step
I0206 05:13:46.598117 27345 authenticator.cpp:232] Received SASL authentication
step
I0206 05:13:46.598134 27345 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-145' server FQDN:
'ip-172-16-10-145' SASL_AUXPROP_OVERRID
E: false SASL_AUXPROP_AUTHZID: false
I0206 05:13:46.598141 27345 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0206 05:13:46.598153 27345 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0206 05:13:46.598162 27345 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-145' server FQDN:
'ip-172-16-10-145' SASL_AUXPROP_OVERRID
E: false SASL_AUXPROP_AUTHZID: true
I0206 05:13:46.598170 27345 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0206 05:13:46.598176 27345 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0206 05:13:46.598189 27345 authenticator.cpp:318] Authentication success
I0206 05:13:46.598278 27346 authenticatee.cpp:299] Authentication success
I0206 05:13:46.601868 27344 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(459)@172.16.10.145:36957
I0206 05:13:46.601971 27346 sched.cpp:513] Successfully authenticated with
master master@172.16.10.145:36957
I0206 05:13:46.601984 27346 sched.cpp:817] Sending SUBSCRIBE call to
master@172.16.10.145:36957
I0206 05:13:46.602026 27346 sched.cpp:850] Will retry registration in
407.644532ms if necessary
I0206 05:13:46.602324 27342 master.cpp:9934] Successfully authenticated
principal 'test-principal' at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957
I0206 05:13:46.602547 27342 master.cpp:2879] Received SUBSCRIBE call for
framework 'default' at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957
I0206 05:13:46.602775 27342 master.cpp:2175] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
I0206 05:13:46.603092 27342 master.cpp:2960] Subscribing framework default with
checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0206 05:13:46.603636 27342 master.cpp:10132] Adding framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000 (default) at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957 with roles {
} suppressed
I0206 05:13:46.604151 27341 hierarchical.cpp:305] Added framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000
I0206 05:13:46.604200 27341 hierarchical.cpp:1558] Performed allocation for 0
agents in 9359ns
I0206 05:13:46.604594 27340 master.cpp:5894] Processing ACCEPT_INVERSE_OFFERS
call for inverse offers: [ invalid-inverse-offer ] for framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000 (default) at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957
W0206 05:13:46.604635 27340 master.cpp:5929] Ignoring accept of inverse offer
invalid-inverse-offer since it is no longer valid
W0206 05:13:46.604643 27340 master.cpp:5935] ACCEPT_INVERSE_OFFERS call used
invalid offers '[ invalid-inverse-offer ]': Inverse offer invalid-inverse-offer
is no longer valid
I0206 05:13:46.604686 27319 sched.cpp:2008] Asked to stop the driver
I0206 05:13:46.604753 27342 sched.cpp:725] Ignoring framework registered
message because the driver is not running!
I0206 05:13:46.604771 27342 sched.cpp:1184] Stopping framework
I0206 05:13:46.604898 27340 master.cpp:1384] Framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000 (default) at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957 disconnected
I0206 05:13:46.604915 27340 master.cpp:3255] Deactivating framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000 (default) at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957
I0206 05:13:46.604931 27340 master.cpp:3232] Disconnecting framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000 (default) at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957
I0206 05:13:46.604943 27340 master.cpp:1399] Giving framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000 (default) at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957 0ns to
failover
I0206 05:13:46.604982 27340 hierarchical.cpp:419] Deactivated framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000
I0206 05:13:46.605463 27341 master.cpp:9509] Framework failover timeout,
removing framework 9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000 (default) at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957
I0206 05:13:46.605481 27341 master.cpp:10449] Removing framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000 (default) at
scheduler-6e5ae29d-e284-4d9b-bbc2-2df8747428fd@172.16.10.145:36957
../../src/tests/master_maintenance_tests.cpp:1920: Failure
Actual function call count doesn't match EXPECT_CALL(sched, registered(&driver,
_, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I0206 05:13:46.607028 27319 master.cpp:1109] Master terminating
I0206 05:13:46.610884 27344 hierarchical.cpp:358] Removed framework
9ee5ab9a-1898-4ba6-a7f3-0093d03b19f8-0000
[ FAILED ] MasterMaintenanceTest.AcceptInvalidInverseOffer (20 ms)
{code}
> MasterMaintenanceTest.AcceptInvalidInverseOffer is flaky.
> ---------------------------------------------------------
>
> Key: MESOS-8266
> URL: https://issues.apache.org/jira/browse/MESOS-8266
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 1.5.0
> Environment: Ubuntu 17.04
> Reporter: Alexander Rukletsov
> Priority: Minor
> Labels: flaky-test
> Attachments: AcceptInvalidInverseOffer-badrun.txt
>
>
> {noformat}
> /home/ubuntu/workspace/mesos/Mesos_CI-build/FLAG/CMake/label/mesos-ec2-ubuntu-17.04/mesos/src/tests/master_maintenance_tests.cpp:1923
> Actual function call count doesn't match EXPECT_CALL(sched,
> registered(&driver, _, _))...
> Expected: to be called once
> Actual: never called - unsatisfied and active
> {noformat}
> Full log attached.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
