[MESOS-9922] MasterQuotaTest.RescindOffersEnforcingLimits is flaky - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: 1.9.0
Fix Version/s: 1.9.0
Component/s: flaky
Labels:
- resource-management

Target Version/s:

1.9.0
Sprint:
Resource Mgmt: RI17 Sp 52
Story Points:
1

Description

Showed up on ASF CI:
https://builds.apache.org/view/M-R/view/Mesos/job/Mesos-Buildbot/6657/BUILDTOOL=cmake,COMPILER=clang,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--enable-parallel-test-execution=no,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1%20MESOS_TEST_AWAIT_TIMEOUT=60secs,OS=centos:7,label_exp=(ubuntu)&&(!ubuntu-us1)&&(!ubuntu-eu2)&&(!ubuntu-4)&&(!H21)&&(!H23)&&(!H26)&&(!H27)/consoleFull

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.

Attachments

Activity

People

Assignee:: Meng Zhu

Reporter:: Andrei Sekretenko

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 02/Aug/19 13:04

Updated:: 12/Aug/19 23:46

Resolved:: 12/Aug/19 23:46