Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
1.9.0
-
Resource Mgmt: RI17 Sp 52
-
1
Description
3: [ RUN ] MasterQuotaTest.RescindOffersEnforcingLimits 3: I0802 09:57:05.017333 15861 cluster.cpp:177] Creating default 'local' authorizer 3: I0802 09:57:05.029503 15877 master.cpp:440] Master 9dd926f8-c8be-42ad-a1c7-ef0d88a99199 (148706d6d9ee) started on 172.17.0.2:41613 3: I0802 09:57:05.029911 15877 master.cpp:443] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --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/450qM2/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_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_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/450qM2/master" --zk_session_timeout="10secs" 3: I0802 09:57:05.030527 15877 master.cpp:492] Master only allowing authenticated frameworks to register 3: I0802 09:57:05.030567 15877 master.cpp:498] Master only allowing authenticated agents to register 3: I0802 09:57:05.030601 15877 master.cpp:504] Master only allowing authenticated HTTP frameworks to register 3: I0802 09:57:05.030634 15877 credentials.hpp:37] Loading credentials for authentication from '/tmp/450qM2/credentials' 3: I0802 09:57:05.031009 15877 master.cpp:548] Using default 'crammd5' authenticator 3: I0802 09:57:05.031306 15877 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' 3: I0802 09:57:05.031747 15877 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' 3: I0802 09:57:05.032049 15877 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' 3: I0802 09:57:05.032627 15877 master.cpp:629] Authorization enabled 3: I0802 09:57:05.033092 15880 hierarchical.cpp:241] Initialized hierarchical allocator process 3: I0802 09:57:05.033552 15892 whitelist_watcher.cpp:77] No whitelist given 3: I0802 09:57:05.052621 15877 master.cpp:2168] Elected as the leading master! 3: I0802 09:57:05.052700 15877 master.cpp:1664] Recovering from registrar 3: I0802 09:57:05.052943 15873 registrar.cpp:339] Recovering registrar 3: I0802 09:57:05.054116 15873 registrar.cpp:383] Successfully fetched the registry (0B) in 1.131008ms 3: I0802 09:57:05.054304 15873 registrar.cpp:487] Applied 1 operations in 73189ns; attempting to update the registry 3: I0802 09:57:05.055423 15873 registrar.cpp:544] Successfully updated the registry in 1.02912ms 3: I0802 09:57:05.055572 15873 registrar.cpp:416] Successfully recovered registrar 3: I0802 09:57:05.057384 15876 hierarchical.cpp:280] Skipping recovery of hierarchical allocator: nothing to recover 3: I0802 09:57:05.057569 15877 master.cpp:1817] Recovered 0 agents from the registry (143B); allowing 10mins for agents to reregister 3: W0802 09:57:05.074198 15861 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:41613 3: I0802 09:57:05.086482 15880 hierarchical.cpp:1508] Performed allocation for 0 agents in 119003ns 3: I0802 09:57:05.089071 15861 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W0802 09:57:05.090075 15861 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges 3: W0802 09:57:05.090544 15861 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W0802 09:57:05.090595 15861 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I0802 09:57:05.090658 15861 provisioner.cpp:300] Using default backend 'copy' 3: I0802 09:57:05.093798 15861 cluster.cpp:518] Creating default 'local' authorizer 3: I0802 09:57:05.099562 15882 slave.cpp:267] Mesos agent started on (17)@172.17.0.2:41613 3: I0802 09:57:05.099623 15882 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/450qM2/jqdwI0/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --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/450qM2/jqdwI0/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" --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/450qM2/jqdwI0/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/450qM2/jqdwI0/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/450qM2/jqdwI0/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/450qM2/jqdwI0/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --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:1;mem:1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterQuotaTest_RescindOffersEnforcingLimits_Nys8o1" --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/MasterQuotaTest_RescindOffersEnforcingLimits_XCzL51" --zk_session_timeout="10secs" 3: I0802 09:57:05.100447 15882 credentials.hpp:86] Loading credential for authentication from '/tmp/450qM2/jqdwI0/credential' 3: I0802 09:57:05.100728 15882 slave.cpp:300] Agent using credential for: test-principal 3: I0802 09:57:05.100751 15882 credentials.hpp:37] Loading credentials for authentication from '/tmp/450qM2/jqdwI0/http_credentials' 3: I0802 09:57:05.101040 15882 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I0802 09:57:05.101528 15882 disk_profile_adaptor.cpp:78] Creating default disk profile adaptor module 3: I0802 09:57:05.102972 15882 slave.cpp:615] Agent resources: [{"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":3749337.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I0802 09:57:05.103250 15882 slave.cpp:623] Agent attributes: [ ] 3: I0802 09:57:05.103266 15882 slave.cpp:632] Agent hostname: 148706d6d9ee 3: I0802 09:57:05.104347 15886 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I0802 09:57:05.104373 15878 status_update_manager_process.hpp:379] Pausing operation status update manager 3: I0802 09:57:05.107336 15877 state.cpp:67] Recovering state from '/tmp/MasterQuotaTest_RescindOffersEnforcingLimits_XCzL51/meta' 3: I0802 09:57:05.120726 15882 slave.cpp:7444] Finished recovering checkpointed state from '/tmp/MasterQuotaTest_RescindOffersEnforcingLimits_XCzL51/meta', beginning agent recovery 3: I0802 09:57:05.121412 15892 task_status_update_manager.cpp:207] Recovering task status update manager 3: I0802 09:57:05.122179 15882 containerizer.cpp:821] Recovering Mesos containers 3: I0802 09:57:05.122614 15882 containerizer.cpp:1147] Recovering isolators 3: I0802 09:57:05.126801 15882 containerizer.cpp:1186] Recovering provisioner 3: I0802 09:57:05.127704 15876 provisioner.cpp:500] Provisioner recovery complete 3: I0802 09:57:05.140862 15882 hierarchical.cpp:1508] Performed allocation for 0 agents in 107533ns 3: I0802 09:57:05.141611 15878 composing.cpp:339] Finished recovering all containerizers 3: I0802 09:57:05.142130 15878 slave.cpp:7908] Recovering executors 3: I0802 09:57:05.142243 15878 slave.cpp:8061] Finished recovery 3: I0802 09:57:05.143589 15888 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I0802 09:57:05.143630 15886 status_update_manager_process.hpp:379] Pausing operation status update manager 3: I0802 09:57:05.143709 15892 slave.cpp:1351] New master detected at master@172.17.0.2:41613 3: I0802 09:57:05.143868 15892 slave.cpp:1416] Detecting new master 3: W0802 09:57:05.144331 15861 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:41613 3: I0802 09:57:05.146203 15861 sched.cpp:239] Version: 1.9.0 3: I0802 09:57:05.147024 15887 sched.cpp:343] New master detected at master@172.17.0.2:41613 3: I0802 09:57:05.147194 15887 sched.cpp:408] Authenticating with master master@172.17.0.2:41613 3: I0802 09:57:05.147215 15887 sched.cpp:415] Using default CRAM-MD5 authenticatee 3: I0802 09:57:05.147907 15890 authenticatee.cpp:121] Creating new client SASL connection 3: I0802 09:57:05.148314 15874 master.cpp:10578] Authenticating scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 3: I0802 09:57:05.148574 15874 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(41)@172.17.0.2:41613 3: I0802 09:57:05.149073 15874 authenticator.cpp:98] Creating new server SASL connection 3: I0802 09:57:05.149623 15874 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I0802 09:57:05.149660 15874 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I0802 09:57:05.149797 15874 authenticator.cpp:204] Received SASL authentication start 3: I0802 09:57:05.149865 15874 authenticator.cpp:326] Authentication requires more steps 3: I0802 09:57:05.150003 15874 authenticatee.cpp:259] Received SASL authentication step 3: I0802 09:57:05.150120 15874 authenticator.cpp:232] Received SASL authentication step 3: I0802 09:57:05.150152 15874 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '148706d6d9ee' server FQDN: '148706d6d9ee' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I0802 09:57:05.150167 15874 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I0802 09:57:05.150226 15874 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I0802 09:57:05.150254 15874 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '148706d6d9ee' server FQDN: '148706d6d9ee' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I0802 09:57:05.150266 15874 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I0802 09:57:05.150275 15874 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I0802 09:57:05.150293 15874 authenticator.cpp:318] Authentication success 3: I0802 09:57:05.150494 15875 authenticatee.cpp:299] Authentication success 3: I0802 09:57:05.150573 15874 master.cpp:10610] Successfully authenticated principal 'test-principal' at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 3: I0802 09:57:05.150702 15874 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(41)@172.17.0.2:41613 3: I0802 09:57:05.150995 15875 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:41613 3: I0802 09:57:05.151018 15875 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:41613 3: I0802 09:57:05.151211 15875 sched.cpp:870] Will retry registration in 24.561819ms if necessary 3: I0802 09:57:05.151538 15875 master.cpp:2908] Received SUBSCRIBE call for framework 'default' at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 3: I0802 09:57:05.151566 15875 master.cpp:2240] Authorizing framework principal 'test-principal' to receive offers for roles '{ role1 }' 3: I0802 09:57:05.152302 15891 master.cpp:2995] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] 3: I0802 09:57:05.152519 15887 slave.cpp:1443] Authenticating with master master@172.17.0.2:41613 3: I0802 09:57:05.152618 15887 slave.cpp:1452] Using default CRAM-MD5 authenticatee 3: I0802 09:57:05.153172 15887 authenticatee.cpp:121] Creating new client SASL connection 3: I0802 09:57:05.157215 15891 master.cpp:10808] Adding framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 (default) at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 with roles { } suppressed 3: I0802 09:57:05.160701 15888 hierarchical.cpp:368] Added framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 3: I0802 09:57:05.161007 15888 hierarchical.cpp:1508] Performed allocation for 0 agents in 131361ns 3: I0802 09:57:05.161232 15888 sched.cpp:751] Framework registered with 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 3: I0802 09:57:05.161291 15888 sched.cpp:770] Scheduler::registered took 43881ns 3: I0802 09:57:05.161705 15891 master.cpp:10578] Authenticating slave(17)@172.17.0.2:41613 3: I0802 09:57:05.161986 15891 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(42)@172.17.0.2:41613 3: I0802 09:57:05.162549 15891 authenticator.cpp:98] Creating new server SASL connection 3: I0802 09:57:05.162926 15891 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I0802 09:57:05.162976 15891 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I0802 09:57:05.163103 15891 authenticator.cpp:204] Received SASL authentication start 3: I0802 09:57:05.163193 15891 authenticator.cpp:326] Authentication requires more steps 3: I0802 09:57:05.163318 15891 authenticatee.cpp:259] Received SASL authentication step 3: I0802 09:57:05.163466 15881 authenticator.cpp:232] Received SASL authentication step 3: I0802 09:57:05.163518 15881 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '148706d6d9ee' server FQDN: '148706d6d9ee' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I0802 09:57:05.168320 15881 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I0802 09:57:05.168431 15881 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I0802 09:57:05.168474 15881 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '148706d6d9ee' server FQDN: '148706d6d9ee' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I0802 09:57:05.168493 15881 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I0802 09:57:05.168503 15881 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I0802 09:57:05.168534 15881 authenticator.cpp:318] Authentication success 3: I0802 09:57:05.168964 15881 authenticatee.cpp:299] Authentication success 3: I0802 09:57:05.169320 15881 master.cpp:10610] Successfully authenticated principal 'test-principal' at slave(17)@172.17.0.2:41613 3: I0802 09:57:05.169478 15881 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(42)@172.17.0.2:41613 3: I0802 09:57:05.170004 15881 slave.cpp:1543] Successfully authenticated with master master@172.17.0.2:41613 3: I0802 09:57:05.170763 15881 slave.cpp:1993] Will retry registration in 4.399581ms if necessary 3: I0802 09:57:05.171401 15881 master.cpp:7086] Received register agent message from slave(17)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:57:05.171723 15881 master.cpp:4202] Authorizing agent providing resources 'cpus:1; mem:1024; disk:3749337; ports:[31000-32000]' with principal 'test-principal' 3: I0802 09:57:05.177142 15878 slave.cpp:1993] Will retry registration in 37.129856ms if necessary 3: I0802 09:57:05.178035 15878 master.cpp:7079] Ignoring register agent message from slave(17)@172.17.0.2:41613 (148706d6d9ee) as registration is already in progress 3: I0802 09:57:05.178143 15878 master.cpp:7153] Authorized registration of agent at slave(17)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:57:05.178246 15878 master.cpp:7265] Registering agent at slave(17)@172.17.0.2:41613 (148706d6d9ee) with id 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 3: I0802 09:57:05.179272 15888 registrar.cpp:487] Applied 1 operations in 362994ns; attempting to update the registry 3: I0802 09:57:05.180107 15888 registrar.cpp:544] Successfully updated the registry in 748032ns 3: I0802 09:57:05.184391 15879 master.cpp:7313] Admitted agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 at slave(17)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:57:05.185465 15879 master.cpp:7358] Registered agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 at slave(17)@172.17.0.2:41613 (148706d6d9ee) with cpus:1; mem:1024; disk:3749337; ports:[31000-32000] 3: I0802 09:57:05.186156 15879 hierarchical.cpp:617] Added agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 (148706d6d9ee) with cpus:1; mem:1024; disk:3749337; ports:[31000-32000] (allocated: {}) 3: I0802 09:57:05.187729 15879 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.368422ms 3: I0802 09:57:05.187886 15879 slave.cpp:1576] Registered with master master@172.17.0.2:41613; given agent ID 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 3: I0802 09:57:05.192725 15876 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I0802 09:57:05.192859 15879 slave.cpp:1611] Checkpointing SlaveInfo to '/tmp/MasterQuotaTest_RescindOffersEnforcingLimits_XCzL51/meta/slaves/9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0/slave.info' 3: I0802 09:57:05.193363 15871 master.cpp:10393] Sending offers [ 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-O0 ] to framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 (default) at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 3: I0802 09:57:05.193572 15873 status_update_manager_process.hpp:385] Resuming operation status update manager 3: I0802 09:57:05.194280 15873 sched.cpp:934] Scheduler::resourceOffers took 116258ns 3: I0802 09:57:05.194945 15873 hierarchical.cpp:1508] Performed allocation for 1 agents in 375907ns 3: I0802 09:57:05.195372 15879 slave.cpp:1663] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"Chjy8C/USQqbsT32vnA1uw=="},"slave_id":{"value":"9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0"},"update_oversubscribed_resources":false} 3: I0802 09:57:05.196919 15893 master.cpp:8457] Ignoring update on agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 at slave(17)@172.17.0.2:41613 (148706d6d9ee) as it reports no changes 3: W0802 09:57:05.205972 15861 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:41613 3: I0802 09:57:05.207845 15861 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W0802 09:57:05.222391 15861 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges 3: W0802 09:57:05.222438 15861 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W0802 09:57:05.222460 15861 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I0802 09:57:05.222501 15861 provisioner.cpp:300] Using default backend 'copy' 3: I0802 09:57:05.238737 15861 cluster.cpp:518] Creating default 'local' authorizer 3: I0802 09:57:05.249315 15876 hierarchical.cpp:1508] Performed allocation for 1 agents in 408138ns 3: I0802 09:57:05.276511 15872 slave.cpp:267] Mesos agent started on (18)@172.17.0.2:41613 3: I0802 09:57:05.276571 15872 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/450qM2/TDawGY/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --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/450qM2/TDawGY/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" --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/450qM2/TDawGY/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/450qM2/TDawGY/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/450qM2/TDawGY/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/450qM2/TDawGY/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --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:1;mem:1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/MasterQuotaTest_RescindOffersEnforcingLimits_TODS3Y" --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/MasterQuotaTest_RescindOffersEnforcingLimits_w13frZ" --zk_session_timeout="10secs" 3: I0802 09:57:05.277412 15872 credentials.hpp:86] Loading credential for authentication from '/tmp/450qM2/TDawGY/credential' 3: I0802 09:57:05.277693 15872 slave.cpp:300] Agent using credential for: test-principal 3: I0802 09:57:05.277715 15872 credentials.hpp:37] Loading credentials for authentication from '/tmp/450qM2/TDawGY/http_credentials' 3: I0802 09:57:05.277998 15872 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I0802 09:57:05.278468 15872 disk_profile_adaptor.cpp:78] Creating default disk profile adaptor module 3: I0802 09:57:05.279918 15872 slave.cpp:615] Agent resources: [{"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":3749337.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I0802 09:57:05.280186 15872 slave.cpp:623] Agent attributes: [ ] 3: I0802 09:57:05.280205 15872 slave.cpp:632] Agent hostname: 148706d6d9ee 3: I0802 09:57:05.283205 15872 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I0802 09:57:05.283267 15872 status_update_manager_process.hpp:379] Pausing operation status update manager 3: I0802 09:57:05.288424 15872 state.cpp:67] Recovering state from '/tmp/MasterQuotaTest_RescindOffersEnforcingLimits_w13frZ/meta' 3: I0802 09:57:05.289094 15872 slave.cpp:7444] Finished recovering checkpointed state from '/tmp/MasterQuotaTest_RescindOffersEnforcingLimits_w13frZ/meta', beginning agent recovery 3: I0802 09:57:05.289788 15875 task_status_update_manager.cpp:207] Recovering task status update manager 3: I0802 09:57:05.290593 15872 containerizer.cpp:821] Recovering Mesos containers 3: I0802 09:57:05.290952 15872 containerizer.cpp:1147] Recovering isolators 3: I0802 09:57:05.292505 15885 containerizer.cpp:1186] Recovering provisioner 3: I0802 09:57:05.293473 15885 provisioner.cpp:500] Provisioner recovery complete 3: I0802 09:57:05.294914 15885 composing.cpp:339] Finished recovering all containerizers 3: I0802 09:57:05.295361 15885 slave.cpp:7908] Recovering executors 3: I0802 09:57:05.295472 15885 slave.cpp:8061] Finished recovery 3: W0802 09:57:05.297149 15861 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:41613 3: I0802 09:57:05.297420 15885 slave.cpp:1351] New master detected at master@172.17.0.2:41613 3: I0802 09:57:05.297458 15880 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I0802 09:57:05.297533 15885 slave.cpp:1416] Detecting new master 3: I0802 09:57:05.297538 15880 status_update_manager_process.hpp:379] Pausing operation status update manager 3: I0802 09:57:05.305006 15887 hierarchical.cpp:1508] Performed allocation for 1 agents in 317611ns 3: I0802 09:57:05.305449 15861 sched.cpp:239] Version: 1.9.0 3: I0802 09:57:05.306335 15882 sched.cpp:343] New master detected at master@172.17.0.2:41613 3: I0802 09:57:05.306438 15882 sched.cpp:408] Authenticating with master master@172.17.0.2:41613 3: I0802 09:57:05.306457 15882 sched.cpp:415] Using default CRAM-MD5 authenticatee 3: I0802 09:57:05.307082 15882 authenticatee.cpp:121] Creating new client SASL connection 3: I0802 09:57:05.307696 15882 master.cpp:10578] Authenticating scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 3: I0802 09:57:05.307929 15882 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(43)@172.17.0.2:41613 3: I0802 09:57:05.308429 15876 slave.cpp:1443] Authenticating with master master@172.17.0.2:41613 3: I0802 09:57:05.308714 15882 authenticator.cpp:98] Creating new server SASL connection 3: I0802 09:57:05.309056 15882 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I0802 09:57:05.309088 15882 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I0802 09:57:05.309224 15882 authenticator.cpp:204] Received SASL authentication start 3: I0802 09:57:05.309303 15882 authenticator.cpp:326] Authentication requires more steps 3: I0802 09:57:05.309432 15882 authenticatee.cpp:259] Received SASL authentication step 3: I0802 09:57:05.309566 15882 authenticator.cpp:232] Received SASL authentication step 3: I0802 09:57:05.309602 15882 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '148706d6d9ee' server FQDN: '148706d6d9ee' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I0802 09:57:05.309623 15882 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I0802 09:57:05.309686 15882 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I0802 09:57:05.309722 15882 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '148706d6d9ee' server FQDN: '148706d6d9ee' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I0802 09:57:05.309739 15882 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I0802 09:57:05.309751 15882 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I0802 09:57:05.309772 15882 authenticator.cpp:318] Authentication success 3: I0802 09:57:05.310050 15882 authenticatee.cpp:299] Authentication success 3: I0802 09:57:05.310207 15870 master.cpp:10610] Successfully authenticated principal 'test-principal' at scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 3: I0802 09:57:05.310354 15870 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(43)@172.17.0.2:41613 3: I0802 09:57:05.310809 15876 slave.cpp:1452] Using default CRAM-MD5 authenticatee 3: I0802 09:57:05.311417 15876 authenticatee.cpp:121] Creating new client SASL connection 3: I0802 09:57:05.311868 15876 master.cpp:10578] Authenticating slave(18)@172.17.0.2:41613 3: I0802 09:57:05.312104 15876 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(44)@172.17.0.2:41613 3: I0802 09:57:05.316658 15876 authenticator.cpp:98] Creating new server SASL connection 3: I0802 09:57:05.317152 15876 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I0802 09:57:05.317185 15876 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I0802 09:57:05.317333 15876 authenticator.cpp:204] Received SASL authentication start 3: I0802 09:57:05.317412 15876 authenticator.cpp:326] Authentication requires more steps 3: I0802 09:57:05.317543 15876 authenticatee.cpp:259] Received SASL authentication step 3: I0802 09:57:05.317685 15876 authenticator.cpp:232] Received SASL authentication step 3: I0802 09:57:05.317723 15876 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '148706d6d9ee' server FQDN: '148706d6d9ee' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I0802 09:57:05.317742 15876 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I0802 09:57:05.317811 15876 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I0802 09:57:05.317848 15876 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '148706d6d9ee' server FQDN: '148706d6d9ee' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I0802 09:57:05.317867 15876 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I0802 09:57:05.317879 15876 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I0802 09:57:05.317901 15876 authenticator.cpp:318] Authentication success 3: I0802 09:57:05.318174 15876 authenticatee.cpp:299] Authentication success 3: I0802 09:57:05.318508 15876 master.cpp:10610] Successfully authenticated principal 'test-principal' at slave(18)@172.17.0.2:41613 3: I0802 09:57:05.318650 15876 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(44)@172.17.0.2:41613 3: I0802 09:57:05.319175 15876 slave.cpp:1543] Successfully authenticated with master master@172.17.0.2:41613 3: I0802 09:57:05.320288 15873 master.cpp:7086] Received register agent message from slave(18)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:57:05.320581 15873 master.cpp:4202] Authorizing agent providing resources 'cpus:1; mem:1024; disk:3749337; ports:[31000-32000]' with principal 'test-principal' 3: I0802 09:57:05.321904 15889 master.cpp:7153] Authorized registration of agent at slave(18)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:57:05.322043 15889 master.cpp:7265] Registering agent at slave(18)@172.17.0.2:41613 (148706d6d9ee) with id 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 3: I0802 09:57:05.322157 15876 slave.cpp:1993] Will retry registration in 13.968289ms if necessary 3: I0802 09:57:05.322919 15873 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:41613 3: I0802 09:57:05.322943 15873 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:41613 3: I0802 09:57:05.322984 15889 registrar.cpp:487] Applied 1 operations in 419808ns; attempting to update the registry 3: I0802 09:57:05.323137 15873 sched.cpp:870] Will retry registration in 1.840847468secs if necessary 3: I0802 09:57:05.323462 15873 master.cpp:2908] Received SUBSCRIBE call for framework 'default' at scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 3: I0802 09:57:05.323485 15873 master.cpp:2240] Authorizing framework principal 'test-principal' to receive offers for roles '{ role1/child }' 3: I0802 09:57:05.324035 15889 registrar.cpp:544] Successfully updated the registry in 973056ns 3: I0802 09:57:05.328315 15873 master.cpp:7313] Admitted agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 at slave(18)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:57:05.329753 15875 hierarchical.cpp:617] Added agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 (148706d6d9ee) with cpus:1; mem:1024; disk:3749337; ports:[31000-32000] (allocated: {}) 3: I0802 09:57:05.331312 15875 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.343027ms 3: I0802 09:57:05.331818 15884 slave.cpp:1576] Registered with master master@172.17.0.2:41613; given agent ID 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 3: I0802 09:57:05.332558 15884 slave.cpp:1611] Checkpointing SlaveInfo to '/tmp/MasterQuotaTest_RescindOffersEnforcingLimits_w13frZ/meta/slaves/9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1/slave.info' 3: I0802 09:57:05.334188 15884 slave.cpp:1663] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"S/Rp1HolSa65hmTUbrhp9Q=="},"slave_id":{"value":"9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1"},"update_oversubscribed_resources":false} 3: I0802 09:57:05.334450 15884 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I0802 09:57:05.334573 15884 status_update_manager_process.hpp:385] Resuming operation status update manager 3: I0802 09:57:05.336449 15873 master.cpp:7358] Registered agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 at slave(18)@172.17.0.2:41613 (148706d6d9ee) with cpus:1; mem:1024; disk:3749337; ports:[31000-32000] 3: I0802 09:57:05.336958 15873 master.cpp:2995] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] 3: I0802 09:57:05.349050 15873 master.cpp:10808] Adding framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 (default) at scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 with roles { } suppressed 3: I0802 09:57:05.351337 15873 master.cpp:10393] Sending offers [ 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-O1 ] to framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 (default) at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 3: I0802 09:57:05.352591 15873 master.cpp:8457] Ignoring update on agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 at slave(18)@172.17.0.2:41613 (148706d6d9ee) as it reports no changes 3: I0802 09:57:05.353605 15881 hierarchical.cpp:368] Added framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 3: I0802 09:57:05.355470 15873 sched.cpp:934] Scheduler::resourceOffers took 47676ns 3: I0802 09:57:05.355579 15881 hierarchical.cpp:1508] Performed allocation for 2 agents in 577092ns 3: I0802 09:57:05.356719 15892 hierarchical.cpp:1508] Performed allocation for 2 agents in 446921ns 3: I0802 09:57:05.354157 15883 sched.cpp:751] Framework registered with 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 3: I0802 09:57:05.360374 15883 sched.cpp:770] Scheduler::registered took 75574ns 3: I0802 09:57:05.409284 15875 hierarchical.cpp:1508] Performed allocation for 2 agents in 493987ns 3: I0802 09:57:05.465063 15870 hierarchical.cpp:1508] Performed allocation for 2 agents in 508165ns ........... 3: I0802 09:58:05.034294 15880 hierarchical.cpp:1508] Performed allocation for 2 agents in 557279ns 3: I0802 09:58:05.086269 15876 hierarchical.cpp:1508] Performed allocation for 2 agents in 561517ns 3: I0802 09:58:05.104465 15886 slave.cpp:7359] Current disk usage 16.47%. Max allowed age: 5.146766280423298days 3: I0802 09:58:05.138171 15890 hierarchical.cpp:1508] Performed allocation for 2 agents in 517343ns 3: I0802 09:58:05.190285 15888 hierarchical.cpp:1508] Performed allocation for 2 agents in 564397ns 3: I0802 09:58:05.241955 15889 hierarchical.cpp:1508] Performed allocation for 2 agents in 569996ns 3: I0802 09:58:05.282167 15884 slave.cpp:7359] Current disk usage 16.47%. Max allowed age: 5.146765275367859days 3: I0802 09:58:05.293754 15873 hierarchical.cpp:1508] Performed allocation for 2 agents in 521450ns 3: /tmp/SRC/src/tests/master_quota_tests.cpp:2111: Failure 3: Failed to wait 1mins for offers2 3: I0802 09:58:05.308029 15870 master.cpp:1410] Framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 (default) at scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 disconnected 3: I0802 09:58:05.308115 15870 master.cpp:3360] Deactivating framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 (default) at scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 3: /tmp/SRC/src/tests/master_quota_tests.cpp:2106: Failure 3: Actual function call count doesn't match EXPECT_CALL(sched2, offerRescinded(&framework2, _))... 3: Expected: to be called once 3: Actual: never called - unsatisfied and active 3: /tmp/SRC/src/tests/master_quota_tests.cpp:2101: Failure 3: Actual function call count doesn't match EXPECT_CALL(sched2, resourceOffers(&framework2, _))... 3: Expected: to be called at least once 3: Actual: never called - unsatisfied and active 3: I0802 09:58:05.308616 15870 master.cpp:3337] Disconnecting framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 (default) at scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 3: I0802 09:58:05.308703 15870 master.cpp:1425] Giving framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 (default) at scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 0ns to failover 3: I0802 09:58:05.308718 15882 hierarchical.cpp:475] Deactivated framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 3: I0802 09:58:05.309415 15890 slave.cpp:924] Agent terminating 3: I0802 09:58:05.310885 15890 master.cpp:1295] Agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 at slave(18)@172.17.0.2:41613 (148706d6d9ee) disconnected 3: I0802 09:58:05.310933 15890 master.cpp:3397] Disconnecting agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 at slave(18)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:58:05.311017 15890 master.cpp:3416] Deactivating agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 at slave(18)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:58:05.311187 15871 hierarchical.cpp:799] Agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 deactivated 3: I0802 09:58:05.312307 15890 master.cpp:12685] Removing offer 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-O1 3: I0802 09:58:05.312551 15885 sched.cpp:960] Rescinded offer 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-O1 3: I0802 09:58:05.312649 15885 sched.cpp:971] Scheduler::offerRescinded took 42088ns 3: I0802 09:58:05.313125 15870 master.cpp:10185] Framework failover timeout, removing framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 (default) at scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 3: I0802 09:58:05.313181 15870 master.cpp:11184] Removing framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 (default) at scheduler-76d82e9d-f02c-4174-894e-be6b1a164320@172.17.0.2:41613 3: I0802 09:58:05.313244 15879 hierarchical.cpp:1218] Recovered cpus(allocated: role1):1; mem(allocated: role1):1024; disk(allocated: role1):3749337; ports(allocated: role1):[31000-32000] (total: cpus:1; mem:1024; disk:3749337; ports:[31000-32000], allocated: {}) on agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 from framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 3: I0802 09:58:05.313500 15880 slave.cpp:4056] Asked to shut down framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 by master@172.17.0.2:41613 3: I0802 09:58:05.313560 15880 slave.cpp:4071] Cannot shut down unknown framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 3: I0802 09:58:05.314222 15870 hierarchical.cpp:1432] Allocation paused 3: I0802 09:58:05.315065 15870 hierarchical.cpp:417] Removed framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0001 3: I0802 09:58:05.315119 15870 hierarchical.cpp:1442] Allocation resumed 3: I0802 09:58:05.345412 15874 hierarchical.cpp:1508] Performed allocation for 2 agents in 515090ns 3: I0802 09:58:05.386776 15887 master.cpp:1410] Framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 (default) at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 disconnected 3: I0802 09:58:05.386883 15887 master.cpp:3360] Deactivating framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 (default) at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 3: I0802 09:58:05.387162 15874 hierarchical.cpp:475] Deactivated framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 3: I0802 09:58:05.387805 15861 slave.cpp:924] Agent terminating 3: I0802 09:58:05.387997 15887 master.cpp:12685] Removing offer 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-O0 3: I0802 09:58:05.388083 15887 master.cpp:3337] Disconnecting framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 (default) at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 3: I0802 09:58:05.388149 15887 master.cpp:1425] Giving framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 (default) at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 0ns to failover 3: I0802 09:58:05.389353 15893 hierarchical.cpp:1218] Recovered cpus(allocated: role1):1; mem(allocated: role1):1024; disk(allocated: role1):3749337; ports(allocated: role1):[31000-32000] (total: cpus:1; mem:1024; disk:3749337; ports:[31000-32000], allocated: {}) on agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 from framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 3: I0802 09:58:05.392590 15877 master.cpp:10185] Framework failover timeout, removing framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 (default) at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 3: I0802 09:58:05.392665 15877 master.cpp:11184] Removing framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 (default) at scheduler-e08ce575-9286-4e6e-9572-c83259dad792@172.17.0.2:41613 3: I0802 09:58:05.397346 15881 hierarchical.cpp:1508] Performed allocation for 2 agents in 495689ns 3: I0802 09:58:05.405243 15890 hierarchical.cpp:1432] Allocation paused 3: I0802 09:58:05.405948 15890 hierarchical.cpp:417] Removed framework 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-0000 3: I0802 09:58:05.406090 15890 hierarchical.cpp:1442] Allocation resumed 3: I0802 09:58:05.406883 15884 master.cpp:1295] Agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 at slave(17)@172.17.0.2:41613 (148706d6d9ee) disconnected 3: I0802 09:58:05.406925 15884 master.cpp:3397] Disconnecting agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 at slave(17)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:58:05.407009 15884 master.cpp:3416] Deactivating agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 at slave(17)@172.17.0.2:41613 (148706d6d9ee) 3: I0802 09:58:05.407382 15871 hierarchical.cpp:799] Agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 deactivated 3: I0802 09:58:05.449240 15884 hierarchical.cpp:1508] Performed allocation for 2 agents in 264454ns 3: I0802 09:58:05.486388 15861 master.cpp:1135] Master terminating 3: I0802 09:58:05.487401 15877 hierarchical.cpp:775] Removed all filters for agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 3: I0802 09:58:05.487440 15877 hierarchical.cpp:650] Removed agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S1 3: I0802 09:58:05.487804 15877 hierarchical.cpp:775] Removed all filters for agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 3: I0802 09:58:05.487824 15877 hierarchical.cpp:650] Removed agent 9dd926f8-c8be-42ad-a1c7-ef0d88a99199-S0 3: I0802 09:58:05.500919 15888 hierarchical.cpp:1508] Performed allocation for 0 agents in 143260ns 3: [ FAILED ] MasterQuotaTest.RescindOffersEnforcingLimits (60493 ms)
If I understand correctly, the offer with resources on a second slave went to the fiirst framework, because the allocator wasn't aware about the second framework when the second slave was added.