Details
-
Bug
-
Status: Open
-
Major
-
Resolution: Unresolved
-
1.8.0
-
None
-
Debian 9, autotools, libevent + SSL
Description
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)