[
https://issues.apache.org/jira/browse/MESOS-7726?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16211607#comment-16211607
]
Alexander Rukletsov commented on MESOS-7726:
--------------------------------------------
I have refined logs from good and bad runs to make the chain of events more
obvious.
Good run:
{noformat}
19:31:28.542207 16548 slave.cpp:993] New master detected at
[email protected]:60888
19:31:28.553344 16546 slave.cpp:1147] Successfully authenticated with master
[email protected]:60888
19:31:28.553395 16546 slave.cpp:1626] Will retry registration in 1.49694ms if
necessary
19:31:28.553436 16545 master.cpp:5801] Received register agent message from
slave(294)@172.16.10.126:60888 (ip-172-16-10-126.ec2.internal)
19:31:28.553725 16545 master.cpp:5954] Registering agent at
slave(294)@172.16.10.126:60888 (ip-172-16-10-126.ec2.internal) with id
43dd1579-4d4f-42c6-9a02-8ac196135ba1-S0
19:31:28.554425 16546 slave.cpp:1193] Registered with master
[email protected]:60888; given agent ID
43dd1579-4d4f-42c6-9a02-8ac196135ba1-S0
19:31:28.555630 16542 slave.cpp:993] New master detected at
[email protected]:60888
19:31:28.555724 16546 slave.cpp:1055] Authenticating with master
[email protected]:60888
19:31:28.556710 16546 master.cpp:7966] Successfully authenticated principal
'test-principal' at slave(294)@172.16.10.126:60888
19:31:28.556766 16546 slave.cpp:1147] Successfully authenticated with master
[email protected]:60888
19:31:28.556807 16546 slave.cpp:1626] Will retry registration in 9.658747ms if
necessary
19:31:28.557025 16546 master.cpp:6119] Received re-register agent message from
agent 43dd1579-4d4f-42c6-9a02-8ac196135ba1-S0 at slave(294)@172.16.10.126:60888
(ip-172-16-10-126.ec2.internal)
19:31:28.557148 16546 master.cpp:6222] Ignoring re-registration attempt from
old agent at slave(294)@172.16.10.126:60888: agent version is 0.28.1-rc1,
minimum supported agent version is 1.0.0
19:31:28.557402 16522 slave.cpp:869] Agent terminating
{noformat}
Bad run:
{noformat}
04:31:59.541496 15900 slave.cpp:993] New master detected at
[email protected]:42919
04:31:59.545332 15909 slave.cpp:1147] Successfully authenticated with master
[email protected]:42919
04:31:59.545543 15909 slave.cpp:1626] Will retry registration in 1.358313ms if
necessary
04:31:59.545763 15906 master.cpp:5801] Received register agent message from
slave(411)@172.17.0.3:42919 (37ad05bac4a7)
04:31:59.546460 15904 master.cpp:5954] Registering agent at
slave(411)@172.17.0.3:42919 (37ad05bac4a7) with id
1069c7ab-2d90-4a12-996b-ecfe9a871217-S0
04:31:59.548152 15893 slave.cpp:1626] Will retry registration in 15.765509ms if
necessary
04:31:59.548413 15912 master.cpp:6032] Registered agent
1069c7ab-2d90-4a12-996b-ecfe9a871217-S0 at slave(411)@172.17.0.3:42919
(37ad05bac4a7) with
[{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
04:31:59.548753 15902 slave.cpp:1193] Registered with master
[email protected]:42919; given agent ID 1069c7ab-2d90-4a12-996b-ecfe9a871217-S0
04:31:59.548921 15912 master.cpp:5801] Received register agent message from
slave(411)@172.17.0.3:42919 (37ad05bac4a7)
04:31:59.549670 15902 slave.cpp:993] New master detected at
[email protected]:42919
04:31:59.549906 15902 slave.cpp:1193] Registered with master
[email protected]:42919; given agent ID 1069c7ab-2d90-4a12-996b-ecfe9a871217-S0
/mesos/src/tests/master_tests.cpp:8041: Failure
Failed to wait 15secs for reregisterSlaveMessage
04:32:14.557504 15902 slave.cpp:869] Agent terminating
{noformat}
We can see that in the "bad" run, the agent sends {{RegisterSlaveMessage}}
twice, likely because the reply from the master has not arrived in
{{1.358313ms}} when the agent retries. Because the second
{{SlaveRegisteredMessage}} arrives onto the agent during authentication and
hence before it attempts to re-register, the {{ReregisterSlaveMessage}} message
is never sent out. I suggest we introduce an extra {{REGISTERING}} state, which
we enter after a (re)registration request is sent. This way we can drop all
registered / reregistered confirmations coming from the previous master during
the {{DISCONNECTED}} stage.
Additionally, looking at the code, it seems that after sending a
re-registration request in {{ReregisterSlaveMessage}} to the master, the agent
is satisfied (given it comes from the expected master), i.e., transitions from
{{DISCONNECTED}} to {{RUNNING}}, with {{SlaveRegisteredMessage}}, losing any
{{ReconcileTasksMessage}} that might be delivered in the coming and to be
ignored {{SlaveReregisteredMessage}}. This seems incorrect to me, I believe the
agent should ignore {{SlaveRegisteredMessage}} after sending
{{ReregisterSlaveMessage}}.
> MasterTest.IgnoreOldAgentReregistration test is flaky
> -----------------------------------------------------
>
> Key: MESOS-7726
> URL: https://issues.apache.org/jira/browse/MESOS-7726
> Project: Mesos
> Issue Type: Bug
> Reporter: Vinod Kone
> Assignee: Neil Conway
> Labels: flaky-test, mesosphere-oncall
> Attachments: IgnoreOldAgentReregistration-badrun.txt,
> IgnoreOldAgentReregistration-goodrun.txt
>
>
> Observed this on ASF CI.
> {code}
> [ RUN ] MasterTest.IgnoreOldAgentReregistration
> I0627 05:23:06.031154 4917 cluster.cpp:162] Creating default 'local'
> authorizer
> I0627 05:23:06.033433 4945 master.cpp:438] Master
> a8778782-0da1-49a5-9cb8-9f6d11701733 (c43debbe7e32) started on
> 172.17.0.4:41747
> I0627 05:23:06.033457 4945 master.cpp:440] Flags at startup: --acls=""
> --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate_agents="true" --authenticate_frameworks="true"
> --authenticate_http_frameworks="true" --authenticate_http_readonly="true"
> --authenticate_http_readwrite="true" --authenticators="crammd5"
> --authorizers="local" --credentials="/tmp/2BARnF/credentials"
> --filter_gpu_resources="true" --framework_sorter="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_unreachable_tasks_per_framework="1000" --port="5050" --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"
> --root_submissions="true" --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-1.4.0/_inst/share/mesos/webui"
> --work_dir="/tmp/2BARnF/master" --zk_session_timeout="10secs"
> I0627 05:23:06.033771 4945 master.cpp:490] Master only allowing
> authenticated frameworks to register
> I0627 05:23:06.033787 4945 master.cpp:504] Master only allowing
> authenticated agents to register
> I0627 05:23:06.033798 4945 master.cpp:517] Master only allowing
> authenticated HTTP frameworks to register
> I0627 05:23:06.033812 4945 credentials.hpp:37] Loading credentials for
> authentication from '/tmp/2BARnF/credentials'
> I0627 05:23:06.034080 4945 master.cpp:562] Using default 'crammd5'
> authenticator
> I0627 05:23:06.034221 4945 http.cpp:974] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-readonly'
> I0627 05:23:06.034409 4945 http.cpp:974] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-readwrite'
> I0627 05:23:06.034569 4945 http.cpp:974] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-scheduler'
> I0627 05:23:06.034688 4945 master.cpp:642] Authorization enabled
> I0627 05:23:06.034862 4938 whitelist_watcher.cpp:77] No whitelist given
> I0627 05:23:06.034868 4950 hierarchical.cpp:169] Initialized hierarchical
> allocator process
> I0627 05:23:06.037211 4957 master.cpp:2161] Elected as the leading master!
> I0627 05:23:06.037236 4957 master.cpp:1700] Recovering from registrar
> I0627 05:23:06.037333 4938 registrar.cpp:345] Recovering registrar
> I0627 05:23:06.038146 4938 registrar.cpp:389] Successfully fetched the
> registry (0B) in 768256ns
> I0627 05:23:06.038290 4938 registrar.cpp:493] Applied 1 operations in
> 30798ns; attempting to update the registry
> I0627 05:23:06.038861 4938 registrar.cpp:550] Successfully updated the
> registry in 510976ns
> I0627 05:23:06.038960 4938 registrar.cpp:422] Successfully recovered
> registrar
> I0627 05:23:06.039364 4941 hierarchical.cpp:207] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0627 05:23:06.039594 4958 master.cpp:1799] Recovered 0 agents from the
> registry (129B); allowing 10mins for agents to re-register
> I0627 05:23:06.043999 4917 containerizer.cpp:230] Using isolation:
> posix/cpu,posix/mem,filesystem/posix,network/cni,environment_secret
> W0627 05:23:06.044456 4917 backend.cpp:76] Failed to create 'aufs' backend:
> AufsBackend requires root privileges
> W0627 05:23:06.044548 4917 backend.cpp:76] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0627 05:23:06.044580 4917 provisioner.cpp:255] Using default backend 'copy'
> I0627 05:23:06.046222 4917 cluster.cpp:448] Creating default 'local'
> authorizer
> I0627 05:23:06.047572 4950 slave.cpp:249] Mesos agent started on
> (269)@172.17.0.4:41747
> I0627 05:23:06.047591 4950 slave.cpp:250] Flags at startup: --acls=""
> --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/MasterTest_IgnoreOldAgentReregistration_Bgz7OK/store/appc"
> --authenticate_http_readonly="true" --authenticate_http_readwrite="true"
> --authenticatee="crammd5" --authentication_backoff_factor="1secs"
> --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false"
> --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup"
> --cgroups_limit_swap="false" --cgroups_root="mesos"
> --container_disk_watch_interval="15secs" --containerizers="mesos"
> --credential="/tmp/MasterTest_IgnoreOldAgentReregistration_Bgz7OK/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns"
> --docker_store_dir="/tmp/MasterTest_IgnoreOldAgentReregistration_Bgz7OK/store/docker"
> --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_reregistration_timeout="2secs"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/MasterTest_IgnoreOldAgentReregistration_Bgz7OK/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --http_command_executor="false"
> --http_credentials="/tmp/MasterTest_IgnoreOldAgentReregistration_Bgz7OK/http_credentials"
> --http_heartbeat_interval="30secs" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem" --launcher="posix"
> --launcher_dir="/mesos/mesos-1.4.0/_build/src" --logbufsecs="0"
> --logging_level="INFO" --max_completed_executors_per_framework="150"
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs"
> --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns"
> --quiet="false" --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ms"
> --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true"
> --runtime_dir="/tmp/MasterTest_IgnoreOldAgentReregistration_Bgz7OK"
> --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
> --systemd_enable_support="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/MasterTest_IgnoreOldAgentReregistration_US8t6c"
> I0627 05:23:06.047937 4950 credentials.hpp:86] Loading credential for
> authentication from
> '/tmp/MasterTest_IgnoreOldAgentReregistration_Bgz7OK/credential'
> I0627 05:23:06.048065 4950 slave.cpp:282] Agent using credential for:
> test-principal
> I0627 05:23:06.048085 4950 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/MasterTest_IgnoreOldAgentReregistration_Bgz7OK/http_credentials'
> I0627 05:23:06.048274 4950 http.cpp:974] Creating default 'basic' HTTP
> authenticator for realm 'mesos-agent-readonly'
> I0627 05:23:06.048396 4950 http.cpp:974] Creating default 'basic' HTTP
> authenticator for realm 'mesos-agent-readwrite'
> I0627 05:23:06.049597 4950 slave.cpp:553] Agent resources:
> [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0627 05:23:06.049815 4950 slave.cpp:561] Agent attributes: [ ]
> I0627 05:23:06.049830 4950 slave.cpp:566] Agent hostname: c43debbe7e32
> I0627 05:23:06.049934 4941 status_update_manager.cpp:177] Pausing sending
> status updates
> I0627 05:23:06.051394 4957 state.cpp:64] Recovering state from
> '/tmp/MasterTest_IgnoreOldAgentReregistration_US8t6c/meta'
> I0627 05:23:06.051775 4954 status_update_manager.cpp:203] Recovering status
> update manager
> I0627 05:23:06.052050 4959 containerizer.cpp:582] Recovering containerizer
> I0627 05:23:06.053479 4946 provisioner.cpp:416] Provisioner recovery complete
> I0627 05:23:06.053802 4937 slave.cpp:6168] Finished recovery
> I0627 05:23:06.054203 4937 slave.cpp:6350] Querying resource estimator for
> oversubscribable resources
> I0627 05:23:06.054503 4954 slave.cpp:946] New master detected at
> [email protected]:41747
> I0627 05:23:06.054517 4950 status_update_manager.cpp:177] Pausing sending
> status updates
> I0627 05:23:06.054641 4954 slave.cpp:981] Detecting new master
> I0627 05:23:06.054774 4954 slave.cpp:6364] Received oversubscribable
> resources {} from the resource estimator
> I0627 05:23:06.065029 4943 slave.cpp:1008] Authenticating with master
> [email protected]:41747
> I0627 05:23:06.065158 4943 slave.cpp:1019] Using default CRAM-MD5
> authenticatee
> I0627 05:23:06.065412 4945 authenticatee.cpp:121] Creating new client SASL
> connection
> I0627 05:23:06.065798 4938 master.cpp:7640] Authenticating
> slave(269)@172.17.0.4:41747
> I0627 05:23:06.065937 4954 authenticator.cpp:414] Starting authentication
> session for crammd5-authenticatee(577)@172.17.0.4:41747
> I0627 05:23:06.066174 4937 authenticator.cpp:98] Creating new server SASL
> connection
> I0627 05:23:06.066419 4958 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0627 05:23:06.066448 4958 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0627 05:23:06.066550 4958 authenticator.cpp:204] Received SASL
> authentication start
> I0627 05:23:06.066612 4958 authenticator.cpp:326] Authentication requires
> more steps
> I0627 05:23:06.066845 4952 authenticatee.cpp:259] Received SASL
> authentication step
> I0627 05:23:06.067041 4936 authenticator.cpp:232] Received SASL
> authentication step
> I0627 05:23:06.067081 4936 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: 'c43debbe7e32' server FQDN: 'c43debbe7e32'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0627 05:23:06.067096 4936 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0627 05:23:06.067129 4936 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0627 05:23:06.067149 4936 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: 'c43debbe7e32' server FQDN: 'c43debbe7e32'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0627 05:23:06.067159 4936 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0627 05:23:06.067167 4936 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0627 05:23:06.067184 4936 authenticator.cpp:318] Authentication success
> I0627 05:23:06.067267 4945 authenticatee.cpp:299] Authentication success
> I0627 05:23:06.067364 4954 master.cpp:7670] Successfully authenticated
> principal 'test-principal' at slave(269)@172.17.0.4:41747
> I0627 05:23:06.067433 4943 authenticator.cpp:432] Authentication session
> cleanup for crammd5-authenticatee(577)@172.17.0.4:41747
> I0627 05:23:06.067656 4939 slave.cpp:1103] Successfully authenticated with
> master [email protected]:41747
> I0627 05:23:06.067855 4939 slave.cpp:1545] Will retry registration in
> 1.835348ms if necessary
> I0627 05:23:06.068022 4949 master.cpp:5602] Received register agent message
> from slave(269)@172.17.0.4:41747 (c43debbe7e32)
> I0627 05:23:06.068155 4949 master.cpp:3742] Authorizing agent with principal
> 'test-principal'
> I0627 05:23:06.068568 4957 master.cpp:5662] Authorized registration of agent
> at slave(269)@172.17.0.4:41747 (c43debbe7e32)
> I0627 05:23:06.068668 4957 master.cpp:5741] Registering agent at
> slave(269)@172.17.0.4:41747 (c43debbe7e32) with id
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0
> I0627 05:23:06.069067 4937 registrar.cpp:493] Applied 1 operations in
> 56568ns; attempting to update the registry
> I0627 05:23:06.069788 4937 registrar.cpp:550] Successfully updated the
> registry in 659968ns
> I0627 05:23:06.069957 4946 master.cpp:5788] Admitted agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 at slave(269)@172.17.0.4:41747
> (c43debbe7e32)
> I0627 05:23:06.070394 4950 slave.cpp:1545] Will retry registration in
> 34.487053ms if necessary
> I0627 05:23:06.070508 4950 slave.cpp:4866] Received ping from
> slave-observer(272)@172.17.0.4:41747
> I0627 05:23:06.070776 4950 slave.cpp:1149] Registered with master
> [email protected]:41747; given agent ID
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0
> I0627 05:23:06.070569 4946 master.cpp:5819] Registered agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 at slave(269)@172.17.0.4:41747
> (c43debbe7e32) with
> [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0627 05:23:06.070894 4942 status_update_manager.cpp:184] Resuming sending
> status updates
> I0627 05:23:06.070890 4949 hierarchical.cpp:587] Added agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 (c43debbe7e32) with cpus:2; mem:1024;
> disk:1024; ports:[31000-32000] (allocated: {})
> I0627 05:23:06.071032 4946 master.cpp:5602] Received register agent message
> from slave(269)@172.17.0.4:41747 (c43debbe7e32)
> I0627 05:23:06.071089 4950 slave.cpp:1169] Checkpointing SlaveInfo to
> '/tmp/MasterTest_IgnoreOldAgentReregistration_US8t6c/meta/slaves/a8778782-0da1-49a5-9cb8-9f6d11701733-S0/slave.info'
> I0627 05:23:06.071142 4946 master.cpp:3742] Authorizing agent with principal
> 'test-principal'
> I0627 05:23:06.071179 4949 hierarchical.cpp:1938] No allocations performed
> I0627 05:23:06.071238 4949 hierarchical.cpp:1493] Performed allocation for 1
> agents in 180904ns
> I0627 05:23:06.071403 4950 slave.cpp:1207] Forwarding total oversubscribed
> resources {}
> I0627 05:23:06.071549 4944 master.cpp:5662] Authorized registration of agent
> at slave(269)@172.17.0.4:41747 (c43debbe7e32)
> I0627 05:23:06.071624 4952 status_update_manager.cpp:177] Pausing sending
> status updates
> I0627 05:23:06.071624 4944 master.cpp:5719] Agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 at slave(269)@172.17.0.4:41747
> (c43debbe7e32) already registered, resending acknowledgement
> I0627 05:23:06.071624 4950 slave.cpp:946] New master detected at
> [email protected]:41747
> I0627 05:23:06.071753 4950 slave.cpp:981] Detecting new master
> I0627 05:23:06.071769 4944 master.cpp:6508] Received update of agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 at slave(269)@172.17.0.4:41747
> (c43debbe7e32) with total oversubscribed resources {}
> I0627 05:23:06.071905 4950 slave.cpp:1149] Registered with master
> [email protected]:41747; given agent ID
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0
> I0627 05:23:06.072108 4943 status_update_manager.cpp:184] Resuming sending
> status updates
> I0627 05:23:06.072243 4950 slave.cpp:1169] Checkpointing SlaveInfo to
> '/tmp/MasterTest_IgnoreOldAgentReregistration_US8t6c/meta/slaves/a8778782-0da1-49a5-9cb8-9f6d11701733-S0/slave.info'
> I0627 05:23:06.072391 4948 hierarchical.cpp:1938] No allocations performed
> I0627 05:23:06.072443 4948 hierarchical.cpp:1493] Performed allocation for 1
> agents in 158723ns
> I0627 05:23:06.072525 4950 slave.cpp:1207] Forwarding total oversubscribed
> resources {}
> I0627 05:23:06.072618 4950 slave.cpp:1008] Authenticating with master
> [email protected]:41747
> I0627 05:23:06.072661 4950 slave.cpp:1019] Using default CRAM-MD5
> authenticatee
> I0627 05:23:06.072693 4959 master.cpp:6508] Received update of agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 at slave(269)@172.17.0.4:41747
> (c43debbe7e32) with total oversubscribed resources {}
> I0627 05:23:06.072882 4946 authenticatee.cpp:121] Creating new client SASL
> connection
> I0627 05:23:06.073169 4944 master.cpp:7640] Authenticating
> slave(269)@172.17.0.4:41747
> I0627 05:23:06.073289 4950 authenticator.cpp:414] Starting authentication
> session for crammd5-authenticatee(578)@172.17.0.4:41747
> I0627 05:23:06.073531 4952 authenticator.cpp:98] Creating new server SASL
> connection
> I0627 05:23:06.073796 4949 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0627 05:23:06.073827 4949 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0627 05:23:06.073998 4936 authenticator.cpp:204] Received SASL
> authentication start
> I0627 05:23:06.074061 4936 authenticator.cpp:326] Authentication requires
> more steps
> I0627 05:23:06.074195 4957 authenticatee.cpp:259] Received SASL
> authentication step
> I0627 05:23:06.074335 4953 authenticator.cpp:232] Received SASL
> authentication step
> I0627 05:23:06.074370 4953 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: 'c43debbe7e32' server FQDN: 'c43debbe7e32'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0627 05:23:06.074388 4953 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0627 05:23:06.074416 4953 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0627 05:23:06.074436 4953 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: 'c43debbe7e32' server FQDN: 'c43debbe7e32'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0627 05:23:06.074446 4953 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0627 05:23:06.074455 4953 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0627 05:23:06.074468 4953 authenticator.cpp:318] Authentication success
> I0627 05:23:06.074553 4956 authenticatee.cpp:299] Authentication success
> I0627 05:23:06.074594 4945 master.cpp:7670] Successfully authenticated
> principal 'test-principal' at slave(269)@172.17.0.4:41747
> I0627 05:23:06.074642 4952 authenticator.cpp:432] Authentication session
> cleanup for crammd5-authenticatee(578)@172.17.0.4:41747
> I0627 05:23:06.074981 4951 slave.cpp:1103] Successfully authenticated with
> master [email protected]:41747
> ../../src/tests/master_tests.cpp:7110: Failure
> Failed to wait 15secs for reregisterSlaveMessage
> I0627 05:23:21.082969 4953 slave.cpp:818] Agent terminating
> I0627 05:23:21.083305 4936 master.cpp:1316] Agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 at slave(269)@172.17.0.4:41747
> (c43debbe7e32) disconnected
> I0627 05:23:21.083349 4936 master.cpp:3240] Disconnecting agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 at slave(269)@172.17.0.4:41747
> (c43debbe7e32)
> I0627 05:23:21.083443 4936 master.cpp:3259] Deactivating agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 at slave(269)@172.17.0.4:41747
> (c43debbe7e32)
> I0627 05:23:21.083665 4936 hierarchical.cpp:715] Agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0 deactivated
> I0627 05:23:21.089186 4917 master.cpp:1158] Master terminating
> I0627 05:23:21.090092 4944 hierarchical.cpp:620] Removed agent
> a8778782-0da1-49a5-9cb8-9f6d11701733-S0
> ../../3rdparty/libprocess/include/process/gmock.hpp:441: Failure
> Actual function call count doesn't match EXPECT_CALL(filter->mock,
> filter(testing::A<const MessageEvent&>()))...
> Expected args: message matcher (8-byte object <E8-AB 06-80 6C-2B 00-00>,
> 1-byte object <AB>, 1-byte object <E8>)
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] MasterTest.IgnoreOldAgentReregistration (15070 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
