Till Toenshoff created MESOS-9450:
-------------------------------------
Summary: MasterAuthorizationTest.SlaveRemovedDropped is flaky.
Key: MESOS-9450
URL: https://issues.apache.org/jira/browse/MESOS-9450
Project: Mesos
Issue Type: Bug
Components: test
Affects Versions: 1.8.0
Environment: Debian 9, autotools, libevent + SSL
Reporter: Till Toenshoff
{noformat}
23:50:59 [ RUN ] MasterAuthorizationTest.SlaveRemovedDropped
23:50:59 I1203 23:50:59.123471 1137 master.cpp:414] Master
1f14ff95-e61f-4410-a724-dfec18eb52b0 (localhost) started on 127.0.0.1:33161
23:50:59 I1203 23:50:59.123558 1137 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_readwrite="true" --authentication_v0_timeout="15secs"
--authenticators="crammd5" --authorizers="local"
--credentials="/tmp/0p45nb/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" --memory_profiling="false"
--min_allocatable_resources="cpus:0.01|mem:32" --port="5050"
--publish_per_framework_metrics="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="true"
--version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/tmp/0p45nb/master" --zk_session_timeout="10secs"
23:50:59 W1203 23:50:59.123672 1137 master.cpp:420]
23:50:59 **************************************************
23:50:59 Master bound to loopback interface! Cannot communicate with remote
schedulers or agents. You might want to set '--ip' flag to a routable IP
address.
23:50:59 **************************************************
23:50:59 I1203 23:50:59.123688 1137 master.cpp:466] Master only allowing
authenticated frameworks to register
23:50:59 I1203 23:50:59.123695 1137 master.cpp:472] Master only allowing
authenticated agents to register
23:50:59 I1203 23:50:59.123702 1137 master.cpp:478] Master only allowing
authenticated HTTP frameworks to register
23:50:59 I1203 23:50:59.123708 1137 credentials.hpp:37] Loading credentials
for authentication from '/tmp/0p45nb/credentials'
23:50:59 I1203 23:50:59.123761 1137 master.cpp:522] Using default 'crammd5'
authenticator
23:50:59 I1203 23:50:59.123819 1137 http.cpp:1017] Creating default 'basic'
HTTP authenticator for realm 'mesos-master-readonly'
23:50:59 I1203 23:50:59.123875 1137 http.cpp:1017] Creating default 'basic'
HTTP authenticator for realm 'mesos-master-readwrite'
23:50:59 I1203 23:50:59.123903 1137 http.cpp:1017] Creating default 'basic'
HTTP authenticator for realm 'mesos-master-scheduler'
23:50:59 I1203 23:50:59.123939 1137 master.cpp:603] Authorization enabled
23:50:59 I1203 23:50:59.124068 1133 hierarchical.cpp:175] Initialized
hierarchical allocator process
23:50:59 I1203 23:50:59.124094 1138 whitelist_watcher.cpp:77] No whitelist
given
23:50:59 I1203 23:50:59.124608 1137 master.cpp:2089] Elected as the leading
master!
23:50:59 I1203 23:50:59.124625 1137 master.cpp:1644] Recovering from registrar
23:50:59 I1203 23:50:59.124652 1136 registrar.cpp:339] Recovering registrar
23:50:59 I1203 23:50:59.124763 1136 registrar.cpp:383] Successfully fetched
the registry (0B) in 97024ns
23:50:59 I1203 23:50:59.124807 1136 registrar.cpp:487] Applied 1 operations
in 6279ns; attempting to update the registry
23:50:59 I1203 23:50:59.124967 1136 registrar.cpp:544] Successfully updated
the registry in 143104ns
23:50:59 I1203 23:50:59.125001 1136 registrar.cpp:416] Successfully recovered
registrar
23:50:59 I1203 23:50:59.125172 1137 master.cpp:1758] Recovered 0 agents from
the registry (125B); allowing 10mins for agents to reregister
23:50:59 I1203 23:50:59.125355 1138 hierarchical.cpp:215] Skipping recovery
of hierarchical allocator: nothing to recover
23:50:59 W1203 23:50:59.126682 1117 process.cpp:2829] Attempted to spawn
already running process files@127.0.0.1:33161
23:50:59 I1203 23:50:59.126904 1117 cluster.cpp:485] Creating default 'local'
authorizer
23:50:59 I1203 23:50:59.127399 1131 slave.cpp:268] Mesos agent started on
(190)@127.0.0.1:33161
23:50:59 I1203 23:50:59.127424 1131 slave.cpp:269] Flags at startup:
--acls="" --appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authenticatee="crammd5"
--authentication_backoff_factor="1secs" --authentication_timeout_max="1mins"
--authentication_timeout_min="5secs" --authorizer="local"
--cgroups_cpu_enable_pids_and_tids_count="false"
--cgroups_destroy_timeout="1mins" --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/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA/credential"
--default_role="*" --disallow_sharing_agent_pid_namespace="false"
--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/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA/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/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA/fetch"
--fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins"
--frameworks_home="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA/frameworks"
--gc_delay="1weeks" --gc_disk_headroom="0.1"
--gc_non_executor_container_sandboxes="false" --help="false"
--hostname_lookup="true" --http_command_executor="false"
--http_credentials="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA/jwt_secret_key"
--launcher="linux"
--launcher_dir="/home/admin/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mesos-ec2-debian-9/mesos/build/src"
--logbufsecs="0" --logging_level="INFO"
--max_completed_executors_per_framework="150" --memory_profiling="false"
--network_cni_metrics="true" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins" --port="5051"
--qos_correction_interval_min="0ns" --quiet="false"
--reconfiguration_policy="equal" --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/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="false"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/MasterAuthorizationTest_SlaveRemovedDropped_Y4CBOS"
--zk_session_timeout="10secs"
23:50:59 W1203 23:50:59.127579 1131 slave.cpp:272]
23:50:59 **************************************************
23:50:59 Agent bound to loopback interface! Cannot communicate with remote
master(s). You might want to set '--ip' flag to a routable IP address.
23:50:59 **************************************************
23:50:59 I1203 23:50:59.127590 1131 credentials.hpp:86] Loading credential
for authentication from
'/tmp/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA/credential'
23:50:59 I1203 23:50:59.127629 1131 slave.cpp:301] Agent using credential
for: test-principal
23:50:59 I1203 23:50:59.127647 1131 credentials.hpp:37] Loading credentials
for authentication from
'/tmp/MasterAuthorizationTest_SlaveRemovedDropped_HAw7eA/http_credentials'
23:50:59 I1203 23:50:59.127701 1131 http.cpp:1017] Creating default 'basic'
HTTP authenticator for realm 'mesos-agent-executor'
23:50:59 I1203 23:50:59.127737 1131 http.cpp:1038] Creating default 'jwt'
HTTP authenticator for realm 'mesos-agent-executor'
23:50:59 I1203 23:50:59.127779 1131 http.cpp:1017] Creating default 'basic'
HTTP authenticator for realm 'mesos-agent-readonly'
23:50:59 I1203 23:50:59.127809 1131 http.cpp:1038] Creating default 'jwt'
HTTP authenticator for realm 'mesos-agent-readonly'
23:50:59 I1203 23:50:59.127840 1131 http.cpp:1017] Creating default 'basic'
HTTP authenticator for realm 'mesos-agent-readwrite'
23:50:59 I1203 23:50:59.127867 1131 http.cpp:1038] Creating default 'jwt'
HTTP authenticator for realm 'mesos-agent-readwrite'
23:50:59 I1203 23:50:59.127928 1131 disk_profile_adaptor.cpp:80] Creating
default disk profile adaptor module
23:50:59 I1203 23:50:59.128084 1131 slave.cpp:616] 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"}]
23:50:59 I1203 23:50:59.128134 1131 slave.cpp:624] Agent attributes: [ ]
23:50:59 I1203 23:50:59.128142 1131 slave.cpp:633] Agent hostname: localhost
23:50:59 I1203 23:50:59.128199 1132 task_status_update_manager.cpp:181]
Pausing sending task status updates
23:50:59 I1203 23:50:59.128334 1131 state.cpp:66] Recovering state from
'/tmp/MasterAuthorizationTest_SlaveRemovedDropped_Y4CBOS/meta'
23:50:59 I1203 23:50:59.128453 1136 slave.cpp:6914] Finished recovering
checkpointed state from
'/tmp/MasterAuthorizationTest_SlaveRemovedDropped_Y4CBOS/meta', beginning agent
recovery
23:50:59 I1203 23:50:59.128532 1132 task_status_update_manager.cpp:207]
Recovering task status update manager
23:50:59 W1203 23:50:59.128793 1117 sched.cpp:1714]
23:50:59 **************************************************
23:50:59 Scheduler driver bound to loopback interface! Cannot communicate with
remote master(s). You might want to set 'LIBPROCESS_IP' environment variable to
use a routable IP address.
23:50:59 **************************************************
23:50:59 I1203 23:50:59.128831 1138 composing.cpp:339] Finished recovering
all containerizers
23:50:59 I1203 23:50:59.128896 1134 slave.cpp:7143] Recovering executors
23:50:59 I1203 23:50:59.128999 1134 slave.cpp:7296] Finished recovery
23:50:59 W1203 23:50:59.128830 1117 process.cpp:2829] Attempted to spawn
already running process version@127.0.0.1:33161
23:50:59 I1203 23:50:59.129387 1135 task_status_update_manager.cpp:181]
Pausing sending task status updates
23:50:59 I1203 23:50:59.129427 1134 slave.cpp:1259] New master detected at
master@127.0.0.1:33161
23:50:59 I1203 23:50:59.129547 1134 slave.cpp:1324] Detecting new master
23:50:59 I1203 23:50:59.129853 1117 sched.cpp:232] Version: 1.8.0
23:50:59 I1203 23:50:59.130002 1134 sched.cpp:336] New master detected at
master@127.0.0.1:33161
23:50:59 I1203 23:50:59.130035 1134 sched.cpp:401] Authenticating with master
master@127.0.0.1:33161
23:50:59 I1203 23:50:59.130043 1134 sched.cpp:408] Using default CRAM-MD5
authenticatee
23:50:59 I1203 23:50:59.130195 1136 authenticatee.cpp:121] Creating new
client SASL connection
23:50:59 I1203 23:50:59.130283 1136 master.cpp:9649] Authenticating
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161
23:50:59 I1203 23:50:59.130326 1137 authenticator.cpp:414] Starting
authentication session for crammd5-authenticatee(411)@127.0.0.1:33161
23:50:59 I1203 23:50:59.130451 1137 authenticator.cpp:98] Creating new server
SASL connection
23:50:59 I1203 23:50:59.130590 1133 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
23:50:59 I1203 23:50:59.130611 1133 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
23:50:59 I1203 23:50:59.130645 1131 authenticator.cpp:204] Received SASL
authentication start
23:50:59 I1203 23:50:59.130674 1131 authenticator.cpp:326] Authentication
requires more steps
23:50:59 I1203 23:50:59.130722 1133 authenticatee.cpp:259] Received SASL
authentication step
23:50:59 I1203 23:50:59.130771 1134 authenticator.cpp:232] Received SASL
authentication step
23:50:59 I1203 23:50:59.130786 1134 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-142' server FQDN:
'ip-172-16-10-142' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
23:50:59 I1203 23:50:59.130807 1134 auxprop.cpp:181] Looking up auxiliary
property '*userPassword'
23:50:59 I1203 23:50:59.130817 1134 auxprop.cpp:181] Looking up auxiliary
property '*cmusaslsecretCRAM-MD5'
23:50:59 I1203 23:50:59.130825 1134 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-142' server FQDN:
'ip-172-16-10-142' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
23:50:59 I1203 23:50:59.130831 1134 auxprop.cpp:131] Skipping auxiliary
property '*userPassword' since SASL_AUXPROP_AUTHZID == true
23:50:59 I1203 23:50:59.130848 1134 auxprop.cpp:131] Skipping auxiliary
property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
23:50:59 I1203 23:50:59.130861 1134 authenticator.cpp:318] Authentication
success
23:50:59 I1203 23:50:59.130895 1138 master.cpp:9681] Successfully
authenticated principal 'test-principal' at
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161
23:50:59 I1203 23:50:59.130961 1134 authenticator.cpp:432] Authentication
session cleanup for crammd5-authenticatee(411)@127.0.0.1:33161
23:50:59 I1203 23:50:59.133492 1133 authenticatee.cpp:299] Authentication
success
23:50:59 I1203 23:50:59.133700 1133 sched.cpp:513] Successfully authenticated
with master master@127.0.0.1:33161
23:50:59 I1203 23:50:59.133756 1138 slave.cpp:1351] Authenticating with
master master@127.0.0.1:33161
23:50:59 I1203 23:50:59.133787 1138 slave.cpp:1360] Using default CRAM-MD5
authenticatee
23:50:59 I1203 23:50:59.133772 1133 sched.cpp:817] Sending SUBSCRIBE call to
master@127.0.0.1:33161
23:50:59 I1203 23:50:59.133908 1133 sched.cpp:850] Will retry registration in
525.348239ms if necessary
23:50:59 I1203 23:50:59.133846 1138 authenticatee.cpp:121] Creating new
client SASL connection
23:50:59 I1203 23:50:59.133991 1137 master.cpp:2860] Received SUBSCRIBE call
for framework 'default' at
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161
23:50:59 I1203 23:50:59.134230 1137 master.cpp:2161] Authorizing framework
principal 'test-principal' to receive offers for roles '{ * }'
23:50:59 I1203 23:50:59.134366 1137 master.cpp:9649] Authenticating
slave(190)@127.0.0.1:33161
23:50:59 I1203 23:50:59.134440 1132 authenticator.cpp:414] Starting
authentication session for crammd5-authenticatee(412)@127.0.0.1:33161
23:50:59 I1203 23:50:59.134565 1132 authenticator.cpp:98] Creating new server
SASL connection
23:50:59 I1203 23:50:59.134413 1137 master.cpp:2941] Subscribing framework
default with checkpointing disabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT, PARTITION_AWARE ]
23:50:59 I1203 23:50:59.134711 1132 authenticatee.cpp:213] Received SASL
authentication mechanisms: CRAM-MD5
23:50:59 I1203 23:50:59.134816 1132 authenticatee.cpp:239] Attempting to
authenticate with mechanism 'CRAM-MD5'
23:50:59 I1203 23:50:59.134907 1132 authenticator.cpp:204] Received SASL
authentication start
23:50:59 I1203 23:50:59.134990 1132 authenticator.cpp:326] Authentication
requires more steps
23:50:59 I1203 23:50:59.135082 1132 authenticatee.cpp:259] Received SASL
authentication step
23:50:59 I1203 23:50:59.135176 1132 authenticator.cpp:232] Received SASL
authentication step
23:50:59 I1203 23:50:59.135254 1132 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-142' server FQDN:
'ip-172-16-10-142' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
23:50:59 I1203 23:50:59.135318 1132 auxprop.cpp:181] Looking up auxiliary
property '*userPassword'
23:50:59 I1203 23:50:59.135380 1132 auxprop.cpp:181] Looking up auxiliary
property '*cmusaslsecretCRAM-MD5'
23:50:59 I1203 23:50:59.135457 1132 auxprop.cpp:109] Request to lookup
properties for user: 'test-principal' realm: 'ip-172-16-10-142' server FQDN:
'ip-172-16-10-142' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
23:50:59 I1203 23:50:59.135519 1132 auxprop.cpp:131] Skipping auxiliary
property '*userPassword' since SASL_AUXPROP_AUTHZID == true
23:50:59 I1203 23:50:59.135578 1132 auxprop.cpp:131] Skipping auxiliary
property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
23:50:59 I1203 23:50:59.135644 1132 authenticator.cpp:318] Authentication
success
23:50:59 I1203 23:50:59.135723 1131 authenticatee.cpp:299] Authentication
success
23:50:59 I1203 23:50:59.135804 1138 slave.cpp:1451] Successfully
authenticated with master master@127.0.0.1:33161
23:50:59 I1203 23:50:59.135816 1135 authenticator.cpp:432] Authentication
session cleanup for crammd5-authenticatee(412)@127.0.0.1:33161
23:50:59 I1203 23:50:59.135885 1138 slave.cpp:1882] Will retry registration
in 1.72993ms if necessary
23:50:59 I1203 23:50:59.136350 1137 master.cpp:9879] Adding framework
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000 (default) at
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161 with roles { }
suppressed
23:50:59 I1203 23:50:59.136554 1132 sched.cpp:744] Framework registered with
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000
23:50:59 I1203 23:50:59.136646 1135 hierarchical.cpp:304] Added framework
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000
23:50:59 I1203 23:50:59.136693 1135 hierarchical.cpp:1566] Performed
allocation for 0 agents in 6815ns
23:50:59 I1203 23:50:59.136698 1132 sched.cpp:758] Scheduler::registered took
41510ns
23:50:59 I1203 23:50:59.136837 1137 master.cpp:9681] Successfully
authenticated principal 'test-principal' at slave(190)@127.0.0.1:33161
23:50:59 I1203 23:50:59.136957 1137 master.cpp:6600] Received register agent
message from slave(190)@127.0.0.1:33161 (localhost)
23:50:59 I1203 23:50:59.137078 1137 master.cpp:3930] Authorizing agent
providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with
principal 'test-principal'
23:50:59 I1203 23:50:59.137264 1136 master.cpp:6667] Authorized registration
of agent at slave(190)@127.0.0.1:33161 (localhost)
23:50:59 I1203 23:50:59.137300 1136 master.cpp:6782] Registering agent at
slave(190)@127.0.0.1:33161 (localhost) with id
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0
23:50:59 I1203 23:50:59.137399 1136 registrar.cpp:487] Applied 1 operations
in 29046ns; attempting to update the registry
23:50:59 I1203 23:50:59.137612 1136 registrar.cpp:544] Successfully updated
the registry in 188928ns
23:50:59 I1203 23:50:59.137661 1136 master.cpp:6830] Admitted agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0 at slave(190)@127.0.0.1:33161
(localhost)
23:50:59 I1203 23:50:59.137811 1138 hierarchical.cpp:603] Added agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0 (localhost) with cpus:2; mem:1024;
disk:1024; ports:[31000-32000] (allocated: {})
23:50:59 I1203 23:50:59.137928 1138 hierarchical.cpp:1566] Performed
allocation for 1 agents in 66190ns
23:50:59 I1203 23:50:59.138115 1135 slave.cpp:1882] Will retry registration
in 8.146728ms if necessary
23:50:59 I1203 23:50:59.138185 1136 master.cpp:6875] Registered agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0 at slave(190)@127.0.0.1:33161
(localhost) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
23:50:59 I1203 23:50:59.138203 1131 slave.cpp:1484] Registered with master
master@127.0.0.1:33161; given agent ID 1f14ff95-e61f-4410-a724-dfec18eb52b0-S0
23:50:59 I1203 23:50:59.138299 1136 master.cpp:9464] Sending offers [
1f14ff95-e61f-4410-a724-dfec18eb52b0-O0 ] to framework
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000 (default) at
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161
23:50:59 I1203 23:50:59.138345 1138 task_status_update_manager.cpp:188]
Resuming sending task status updates
23:50:59 I1203 23:50:59.138355 1131 slave.cpp:1504] Checkpointing SlaveInfo
to
'/tmp/MasterAuthorizationTest_SlaveRemovedDropped_Y4CBOS/meta/slaves/1f14ff95-e61f-4410-a724-dfec18eb52b0-S0/slave.info'
23:50:59 I1203 23:50:59.138448 1138 sched.cpp:914] Scheduler::resourceOffers
took 34264ns
23:50:59 I1203 23:50:59.138561 1136 master.cpp:6600] Received register agent
message from slave(190)@127.0.0.1:33161 (localhost)
23:50:59 I1203 23:50:59.138612 1131 slave.cpp:1553] Forwarding agent update
{"operations":{},"resource_version_uuid":{"value":"s4oKlvW0SqGIwtabOQA/Kw=="},"slave_id":{"value":"1f14ff95-e61f-4410-a724-dfec18eb52b0-S0"},"update_oversubscribed_resources":false}
23:50:59 I1203 23:50:59.138622 1136 master.cpp:3930] Authorizing agent
providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with
principal 'test-principal'
23:50:59 I1203 23:50:59.139066 1117 slave.cpp:955] Unregistering and shutting
down
23:50:59 I1203 23:50:59.139091 1117 slave.cpp:914] Agent terminating
23:50:59 I1203 23:50:59.139104 1136 master.cpp:7934] Ignoring update on agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0 at slave(190)@127.0.0.1:33161
(localhost) as it reports no changes
23:50:59 I1203 23:50:59.139221 1136 master.cpp:11463] Removing offer
1f14ff95-e61f-4410-a724-dfec18eb52b0-O0
23:50:59 I1203 23:50:59.139493 1136 master.cpp:4451] Processing ACCEPT call
for offers: [ 1f14ff95-e61f-4410-a724-dfec18eb52b0-O0 ] on agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0 at slave(190)@127.0.0.1:33161
(localhost) for framework 1f14ff95-e61f-4410-a724-dfec18eb52b0-0000 (default)
at scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161
23:50:59 I1203 23:50:59.139535 1136 master.cpp:3547] Authorizing framework
principal 'test-principal' to launch task 3e709379-4bcf-43ac-b512-14144fcedc94
23:50:59 ../../src/tests/master_authorization_tests.cpp:730: Failure
23:50:59 Mock function called more times than expected - returning default
value.
23:50:59 Function call: authorized(@0x7f70b98d7d20 48-byte object <90-CC
B1-C7 70-7F 00-00 00-00 00-00 00-00 00-00 07-00 00-00 00-00 00-00 F0-26 09-98
70-7F 00-00 A0-BE 0C-98 70-7F 00-00 02-00 00-00 E2-84 5A-3B>)
23:50:59 Returns: Abandoned
23:50:59 Expected: to be called once
23:50:59 Actual: called twice - over-saturated and active
23:50:59 I1203 23:50:59.141641 1136 master.cpp:10568] Removing agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0 at slave(190)@127.0.0.1:33161
(localhost): the agent unregistered
23:50:59 I1203 23:50:59.141929 1136 registrar.cpp:487] Applied 1 operations
in 14037ns; attempting to update the registry
23:50:59 I1203 23:50:59.145511 1135 registrar.cpp:544] Successfully updated
the registry in 3.556096ms
23:50:59 I1203 23:50:59.145565 1134 master.cpp:10610] Removed agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0 at slave(190)@127.0.0.1:33161
(localhost): the agent unregistered
23:50:59 I1203 23:50:59.145629 1134 master.cpp:2006] Notifying framework
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000 (default) at
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161 of lost agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0 (localhost)
23:50:59 I1203 23:50:59.145730 1134 hierarchical.cpp:643] Removed agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0
23:50:59 I1203 23:50:59.145773 1134 sched.cpp:1084] Lost agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S0
23:50:59 I1203 23:50:59.145884 1134 sched.cpp:1095] Scheduler::slaveLost took
12093ns
23:50:59 I1203 23:50:59.148435 1133 master.cpp:6667] Authorized registration
of agent at slave(190)@127.0.0.1:33161 (localhost)
23:50:59 I1203 23:50:59.148476 1133 master.cpp:6782] Registering agent at
slave(190)@127.0.0.1:33161 (localhost) with id
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1
23:50:59 I1203 23:50:59.148671 1133 registrar.cpp:487] Applied 1 operations
in 28758ns; attempting to update the registry
23:50:59 I1203 23:50:59.148871 1133 registrar.cpp:544] Successfully updated
the registry in 173056ns
23:50:59 I1203 23:50:59.148982 1133 master.cpp:6830] Admitted agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1 at slave(190)@127.0.0.1:33161
(localhost)
23:50:59 I1203 23:50:59.149173 1138 hierarchical.cpp:603] Added agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1 (localhost) with cpus:2; mem:1024;
disk:1024; ports:[31000-32000] (allocated: {})
23:50:59 I1203 23:50:59.149292 1138 hierarchical.cpp:1566] Performed
allocation for 1 agents in 68046ns
23:50:59 I1203 23:50:59.149422 1133 master.cpp:6875] Registered agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1 at slave(190)@127.0.0.1:33161
(localhost) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
23:50:59 I1203 23:50:59.149507 1133 master.cpp:1275] Agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1 at slave(190)@127.0.0.1:33161
(localhost) disconnected
23:50:59 I1203 23:50:59.149590 1133 master.cpp:3273] Disconnecting agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1 at slave(190)@127.0.0.1:33161
(localhost)
23:50:59 I1203 23:50:59.149610 1133 master.cpp:3292] Deactivating agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1 at slave(190)@127.0.0.1:33161
(localhost)
23:50:59 I1203 23:50:59.149828 1131 hierarchical.cpp:801] Agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1 deactivated
23:50:59 W1203 23:50:59.149855 1133 master.cpp:9319] Master returning
resources offered because agent 1f14ff95-e61f-4410-a724-dfec18eb52b0-S1 at
slave(190)@127.0.0.1:33161 (localhost) is disconnected
23:50:59 I1203 23:50:59.150014 1136 hierarchical.cpp:1238] Recovered
cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024;
ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024;
ports:[31000-32000], allocated: {}) on agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1 from framework
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000
23:51:00 I1203 23:51:00.124913 1136 hierarchical.cpp:1566] Performed
allocation for 1 agents in 31120ns
23:51:01 I1203 23:51:01.125872 1134 hierarchical.cpp:1566] Performed
allocation for 1 agents in 29988ns
23:51:02 I1203 23:51:02.127084 1135 hierarchical.cpp:1566] Performed
allocation for 1 agents in 30038ns
23:51:03 I1203 23:51:03.127851 1132 hierarchical.cpp:1566] Performed
allocation for 1 agents in 30798ns
23:51:04 I1203 23:51:04.128324 1136 hierarchical.cpp:1566] Performed
allocation for 1 agents in 32370ns
23:51:05 I1203 23:51:05.129272 1137 hierarchical.cpp:1566] Performed
allocation for 1 agents in 29156ns
23:51:06 I1203 23:51:06.130210 1135 hierarchical.cpp:1566] Performed
allocation for 1 agents in 31558ns
23:51:07 I1203 23:51:07.131202 1134 hierarchical.cpp:1566] Performed
allocation for 1 agents in 31200ns
23:51:08 I1203 23:51:08.132498 1135 hierarchical.cpp:1566] Performed
allocation for 1 agents in 32824ns
23:51:09 I1203 23:51:09.133617 1133 hierarchical.cpp:1566] Performed
allocation for 1 agents in 31312ns
23:51:10 I1203 23:51:10.134618 1135 hierarchical.cpp:1566] Performed
allocation for 1 agents in 32366ns
23:51:11 I1203 23:51:11.135648 1133 hierarchical.cpp:1566] Performed
allocation for 1 agents in 31148ns
23:51:12 I1203 23:51:12.136601 1132 hierarchical.cpp:1566] Performed
allocation for 1 agents in 31649ns
23:51:13 I1203 23:51:13.137598 1134 hierarchical.cpp:1566] Performed
allocation for 1 agents in 30865ns
23:51:14 I1203 23:51:14.138133 1133 hierarchical.cpp:1566] Performed
allocation for 1 agents in 30841ns
23:51:14 ../../src/tests/master_authorization_tests.cpp:761: Failure
23:51:14 Failed to wait 15secs for status
23:51:14 I../../src/tests/master_authorization_tests.cpp:751: Failure
23:51:14 Actual function call count doesn't match EXPECT_CALL(sched,
statusUpdate(&driver, _))...
23:51:14 Expected: to be called once
23:51:14 Actual: never called - unsatisfied and active
23:51:14 1203 23:51:14.149539 1131 master.cpp:1390] Framework
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000 (default) at
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161 disconnected
23:51:14 I1203 23:51:14.149920 1131 master.cpp:3236] Deactivating framework
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000 (default) at
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161
23:51:14 I1203 23:51:14.149957 1131 master.cpp:3213] Disconnecting framework
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000 (default) at
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161
23:51:14 I1203 23:51:14.149972 1131 master.cpp:1405] Giving framework
1f14ff95-e61f-4410-a724-dfec18eb52b0-0000 (default) at
scheduler-5b888f8c-bf1b-4028-ba88-a095bd795459@127.0.0.1:33161 0ns to failover
23:51:14 I1203 23:51:14.150179 1131 master.cpp:1117] Master terminating
23:51:14 I1203 23:51:14.150317 1133 hierarchical.cpp:418] Deactivated
framework 1f14ff95-e61f-4410-a724-dfec18eb52b0-0000
23:51:14 I1203 23:51:14.151087 1133 hierarchical.cpp:643] Removed agent
1f14ff95-e61f-4410-a724-dfec18eb52b0-S1
23:51:14 [ FAILED ] MasterAuthorizationTest.SlaveRemovedDropped (15029 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
