[MESOS-9939] PersistentVolumeEndpointsTest.DynamicReservation is flaky. - ASF JIRA

Attach files

Attach Screenshot

Add vote

Voters

Watch issue

Watchers

Link

Clone

Update Comment Author

Replace String in Comment

Update Comment Visibility

Delete Comments

XML

Word

Printable

JSON

Details

Type: Bug
Status: Accepted
Priority: Major
Resolution: Unresolved
Affects Version/s: None
Fix Version/s: None
Component/s: None
Labels:
- flaky-test
- resource-management

Sprint:
Resource Mgmt: RI-17 Sprint 53
Story Points:
1

Description

[ RUN      ] PersistentVolumeEndpointsTest.DynamicReservation
I0813 20:55:33.670486 32445 cluster.cpp:177] Creating default 'local' authorizer
I0813 20:55:33.674396 32457 master.cpp:440] Master 87e437ee-0796-49fd-bfab-e7866bb7a81d (6c6cd7a3b2c1) started on 172.17.0.2:36761
I0813 20:55:33.674434 32457 master.cpp:443] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1000secs" --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/9zz3CO/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" --roles="role1" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.9.0/_inst/share/mesos/webui" --work_dir="/tmp/9zz3CO/master" --zk_session_timeout="10secs"
I0813 20:55:33.674772 32457 master.cpp:492] Master only allowing authenticated frameworks to register
I0813 20:55:33.674784 32457 master.cpp:498] Master only allowing authenticated agents to register
I0813 20:55:33.674793 32457 master.cpp:504] Master only allowing authenticated HTTP frameworks to register
I0813 20:55:33.674800 32457 credentials.hpp:37] Loading credentials for authentication from '/tmp/9zz3CO/credentials'
I0813 20:55:33.675024 32457 master.cpp:548] Using default 'crammd5' authenticator
I0813 20:55:33.675189 32457 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0813 20:55:33.675369 32457 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0813 20:55:33.675529 32457 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0813 20:55:33.675685 32457 master.cpp:629] Authorization enabled
W0813 20:55:33.675709 32457 master.cpp:692] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
I0813 20:55:33.676091 32460 whitelist_watcher.cpp:77] No whitelist given
I0813 20:55:33.676143 32455 hierarchical.cpp:241] Initialized hierarchical allocator process
I0813 20:55:33.678655 32452 master.cpp:2168] Elected as the leading master!
I0813 20:55:33.678683 32452 master.cpp:1664] Recovering from registrar
I0813 20:55:33.678833 32454 registrar.cpp:339] Recovering registrar
I0813 20:55:33.679450 32454 registrar.cpp:383] Successfully fetched the registry (0B) in 576us
I0813 20:55:33.679579 32454 registrar.cpp:487] Applied 1 operations in 46310ns; attempting to update the registry
I0813 20:55:33.680164 32454 registrar.cpp:544] Successfully updated the registry in 525824ns
I0813 20:55:33.680292 32454 registrar.cpp:416] Successfully recovered registrar
I0813 20:55:33.680759 32447 master.cpp:1817] Recovered 0 agents from the registry (143B); allowing 10mins for agents to reregister
I0813 20:55:33.680793 32459 hierarchical.cpp:280] Skipping recovery of hierarchical allocator: nothing to recover
W0813 20:55:33.687850 32445 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:36761
I0813 20:55:33.689188 32445 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0813 20:55:33.689808 32445 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0813 20:55:33.689841 32445 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0813 20:55:33.689865 32445 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0813 20:55:33.689905 32445 provisioner.cpp:300] Using default backend 'copy'
I0813 20:55:33.692245 32445 cluster.cpp:518] Creating default 'local' authorizer
I0813 20:55:33.694341 32454 slave.cpp:267] Mesos agent started on (413)@172.17.0.2:36761
I0813 20:55:33.694394 32454 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/9zz3CO/2jsvL8/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/9zz3CO/2jsvL8/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/9zz3CO/2jsvL8/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/9zz3CO/2jsvL8/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/9zz3CO/2jsvL8/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/9zz3CO/2jsvL8/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/build/mesos-1.9.0/_build/sub/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="disk(*):1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/PersistentVolumeEndpointsTest_DynamicReservation_vA1FIm" --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/PersistentVolumeEndpointsTest_DynamicReservation_yhiRFA" --zk_session_timeout="10secs"
I0813 20:55:33.694963 32454 credentials.hpp:86] Loading credential for authentication from '/tmp/9zz3CO/2jsvL8/credential'
I0813 20:55:33.695113 32454 slave.cpp:300] Agent using credential for: test-principal
I0813 20:55:33.695142 32454 credentials.hpp:37] Loading credentials for authentication from '/tmp/9zz3CO/2jsvL8/http_credentials'
I0813 20:55:33.695372 32454 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0813 20:55:33.695771 32454 disk_profile_adaptor.cpp:78] Creating default disk profile adaptor module
I0813 20:55:33.696786 32454 slave.cpp:615] Agent resources: [{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"cpus","scalar":{"value":16.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":47260.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0813 20:55:33.697023 32454 slave.cpp:623] Agent attributes: [  ]
I0813 20:55:33.697042 32454 slave.cpp:632] Agent hostname: 6c6cd7a3b2c1
I0813 20:55:33.697271 32448 task_status_update_manager.cpp:181] Pausing sending task status updates
I0813 20:55:33.697317 32453 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 20:55:33.698822 32450 state.cpp:67] Recovering state from '/tmp/PersistentVolumeEndpointsTest_DynamicReservation_yhiRFA/meta'
I0813 20:55:33.699095 32451 slave.cpp:7444] Finished recovering checkpointed state from '/tmp/PersistentVolumeEndpointsTest_DynamicReservation_yhiRFA/meta', beginning agent recovery
I0813 20:55:33.699674 32452 task_status_update_manager.cpp:207] Recovering task status update manager
I0813 20:55:33.700217 32456 containerizer.cpp:821] Recovering Mesos containers
I0813 20:55:33.700613 32456 containerizer.cpp:1157] Recovering isolators
I0813 20:55:33.701535 32460 containerizer.cpp:1196] Recovering provisioner
I0813 20:55:33.702273 32455 provisioner.cpp:500] Provisioner recovery complete
I0813 20:55:33.703128 32447 composing.cpp:339] Finished recovering all containerizers
I0813 20:55:33.703493 32449 slave.cpp:7908] Recovering executors
I0813 20:55:33.703609 32449 slave.cpp:8061] Finished recovery
I0813 20:55:33.704392 32451 task_status_update_manager.cpp:181] Pausing sending task status updates
I0813 20:55:33.704412 32460 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 20:55:33.704403 32449 slave.cpp:1351] New master detected at master@172.17.0.2:36761
I0813 20:55:33.704551 32449 slave.cpp:1416] Detecting new master
I0813 20:55:33.713974 32455 slave.cpp:1443] Authenticating with master master@172.17.0.2:36761
I0813 20:55:33.714074 32455 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I0813 20:55:33.714433 32461 authenticatee.cpp:121] Creating new client SASL connection
I0813 20:55:33.714804 32461 master.cpp:10578] Authenticating slave(413)@172.17.0.2:36761
I0813 20:55:33.715013 32458 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(858)@172.17.0.2:36761
I0813 20:55:33.715360 32448 authenticator.cpp:98] Creating new server SASL connection
I0813 20:55:33.715603 32450 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0813 20:55:33.715641 32450 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0813 20:55:33.715845 32447 authenticator.cpp:204] Received SASL authentication start
I0813 20:55:33.715935 32447 authenticator.cpp:326] Authentication requires more steps
I0813 20:55:33.716141 32453 authenticatee.cpp:259] Received SASL authentication step
I0813 20:55:33.716317 32457 authenticator.cpp:232] Received SASL authentication step
I0813 20:55:33.716368 32457 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c6cd7a3b2c1' server FQDN: '6c6cd7a3b2c1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0813 20:55:33.716389 32457 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0813 20:55:33.716436 32457 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0813 20:55:33.716468 32457 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c6cd7a3b2c1' server FQDN: '6c6cd7a3b2c1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0813 20:55:33.716485 32457 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0813 20:55:33.716498 32457 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0813 20:55:33.716521 32457 authenticator.cpp:318] Authentication success
I0813 20:55:33.716658 32456 authenticatee.cpp:299] Authentication success
I0813 20:55:33.716738 32454 master.cpp:10610] Successfully authenticated principal 'test-principal' at slave(413)@172.17.0.2:36761
I0813 20:55:33.716761 32451 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(858)@172.17.0.2:36761
I0813 20:55:33.717182 32457 slave.cpp:1543] Successfully authenticated with master master@172.17.0.2:36761
I0813 20:55:33.717685 32457 slave.cpp:1993] Will retry registration in 9.895956ms if necessary
I0813 20:55:33.717947 32446 master.cpp:7086] Received register agent message from slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1)
I0813 20:55:33.718259 32446 master.cpp:4202] Authorizing agent providing resources 'disk:1024; cpus:16; mem:47260; ports:[31000-32000]' with principal 'test-principal'
I0813 20:55:33.719044 32448 master.cpp:7153] Authorized registration of agent at slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1)
I0813 20:55:33.719144 32448 master.cpp:7265] Registering agent at slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1) with id 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:33.719799 32447 registrar.cpp:487] Applied 1 operations in 269997ns; attempting to update the registry
I0813 20:55:33.720464 32447 registrar.cpp:544] Successfully updated the registry in 592128ns
I0813 20:55:33.720662 32452 master.cpp:7313] Admitted agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 at slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1)
I0813 20:55:33.721354 32452 master.cpp:7358] Registered agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 at slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1) with disk:1024; cpus:16; mem:47260; ports:[31000-32000]
I0813 20:55:33.721664 32455 hierarchical.cpp:617] Added agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 (6c6cd7a3b2c1) with disk:1024; cpus:16; mem:47260; ports:[31000-32000] (allocated: {})
I0813 20:55:33.721722 32456 slave.cpp:1576] Registered with master master@172.17.0.2:36761; given agent ID 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:33.721937 32446 task_status_update_manager.cpp:188] Resuming sending task status updates
I0813 20:55:33.722024 32455 hierarchical.cpp:1508] Performed allocation for 1 agents in 174471ns
I0813 20:55:33.725461 32447 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/reserve'
I0813 20:55:33.727319 32446 http.cpp:1115] HTTP POST for /master/reserve from 172.17.0.2:59366
I0813 20:55:33.728411 32446 master.cpp:3824] Authorizing principal 'test-principal' to reserve resources 'disk(reservations: [(DYNAMIC,role1,test-principal)]):1024'
I0813 20:55:33.730700 32449 master.cpp:12576] Sending operation '' (uuid: 4bf07619-d588-468c-a325-37daa2aadfb0) to agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 at slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1)
W0813 20:55:33.732224 32445 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:36761
I0813 20:55:33.733377 32445 sched.cpp:239] Version: 1.9.0
I0813 20:55:33.734076 32449 sched.cpp:343] New master detected at master@172.17.0.2:36761
I0813 20:55:33.734189 32449 sched.cpp:408] Authenticating with master master@172.17.0.2:36761
I0813 20:55:33.734212 32449 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0813 20:55:33.734484 32453 authenticatee.cpp:121] Creating new client SASL connection
I0813 20:55:33.734863 32451 master.cpp:10578] Authenticating scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:55:33.735035 32458 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(859)@172.17.0.2:36761
I0813 20:55:33.735350 32457 authenticator.cpp:98] Creating new server SASL connection
I0813 20:55:33.735607 32461 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0813 20:55:33.735656 32461 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0813 20:55:33.735802 32461 authenticator.cpp:204] Received SASL authentication start
I0813 20:55:33.735889 32461 authenticator.cpp:326] Authentication requires more steps
I0813 20:55:33.736107 32446 authenticatee.cpp:259] Received SASL authentication step
I0813 20:55:33.736277 32448 authenticator.cpp:232] Received SASL authentication step
I0813 20:55:33.736322 32448 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c6cd7a3b2c1' server FQDN: '6c6cd7a3b2c1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0813 20:55:33.736343 32448 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0813 20:55:33.736380 32448 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0813 20:55:33.736412 32448 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '6c6cd7a3b2c1' server FQDN: '6c6cd7a3b2c1' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0813 20:55:33.736428 32448 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0813 20:55:33.736438 32448 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0813 20:55:33.736456 32448 authenticator.cpp:318] Authentication success
I0813 20:55:33.736552 32450 authenticatee.cpp:299] Authentication success
I0813 20:55:33.736645 32459 master.cpp:10610] Successfully authenticated principal 'test-principal' at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:55:33.736675 32460 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(859)@172.17.0.2:36761
I0813 20:55:33.736990 32452 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:36761
I0813 20:55:33.737020 32452 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:36761
I0813 20:55:33.737156 32452 sched.cpp:870] Will retry registration in 1.951321709secs if necessary
I0813 20:55:33.737473 32451 master.cpp:2908] Received SUBSCRIBE call for framework 'default' at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:55:33.737502 32451 master.cpp:2240] Authorizing framework principal 'test-principal' to receive offers for roles '{ role1 }'
I0813 20:55:33.738072 32457 master.cpp:2995] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0813 20:55:33.740895 32457 master.cpp:10808] Adding framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761 with roles {  } suppressed
I0813 20:55:33.741605 32457 sched.cpp:751] Framework registered with 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000
I0813 20:55:33.741663 32457 sched.cpp:770] Scheduler::registered took 31022ns
I0813 20:55:33.741833 32461 hierarchical.cpp:368] Added framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000
I0813 20:55:33.743193 32461 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.179363ms
I0813 20:55:33.743842 32448 master.cpp:10393] Sending offers [ 87e437ee-0796-49fd-bfab-e7866bb7a81d-O0 ] to framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:55:33.744581 32453 sched.cpp:934] Scheduler::resourceOffers took 110001ns
I0813 20:55:33.747743 32447 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/create-volumes'
I0813 20:55:33.749470 32460 http.cpp:1115] HTTP POST for /master/create-volumes from 172.17.0.2:59368
I0813 20:55:33.750532 32460 master.cpp:3951] Authorizing principal 'test-principal' to create volumes '[{"disk":{"persistence":{"id":"id1","principal":"test-principal"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":64.0},"type":"SCALAR"}]'
I0813 20:55:33.751803 32456 slave.cpp:1611] Checkpointing SlaveInfo to '/tmp/PersistentVolumeEndpointsTest_DynamicReservation_yhiRFA/meta/slaves/87e437ee-0796-49fd-bfab-e7866bb7a81d-S0/slave.info'
I0813 20:55:33.751893 32451 status_update_manager_process.hpp:385] Resuming operation status update manager
I0813 20:55:33.752228 32450 master.cpp:12685] Removing offer 87e437ee-0796-49fd-bfab-e7866bb7a81d-O0
I0813 20:55:33.752394 32455 sched.cpp:960] Rescinded offer 87e437ee-0796-49fd-bfab-e7866bb7a81d-O0
I0813 20:55:33.752483 32455 sched.cpp:971] Scheduler::offerRescinded took 50103ns
I0813 20:55:33.752831 32452 hierarchical.cpp:1218] Recovered disk(allocated: role1)(reservations: [(DYNAMIC,role1,test-principal)]):1024; cpus(allocated: role1):16; mem(allocated: role1):47260; ports(allocated: role1):[31000-32000] (total: ports:[31000-32000]; cpus:16; mem:47260; disk(reservations: [(DYNAMIC,role1,test-principal)]):1024, allocated: {}) on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 from framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000
I0813 20:55:33.752938 32452 hierarchical.cpp:1264] Framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 filtered agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 for 5secs
I0813 20:55:33.753031 32456 slave.cpp:1663] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"o0rWj6TKRjCx0erYVTVZ0g=="},"slave_id":{"value":"87e437ee-0796-49fd-bfab-e7866bb7a81d-S0"},"update_oversubscribed_resources":false}
I0813 20:55:33.753692 32456 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
W0813 20:55:33.753916 32448 master.cpp:8522] Performing explicit reconciliation with agent for known operation 4bf07619-d588-468c-a325-37daa2aadfb0 since it was not present in original reconciliation message from agent
I0813 20:55:33.754012 32456 slave.cpp:8870] Updating the state of operation with no ID (uuid: 4bf07619-d588-468c-a325-37daa2aadfb0) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 20:55:33.755149 32449 master.cpp:12576] Sending operation '' (uuid: 387d0260-4b71-44ec-b63f-7db945dde737) to agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 at slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1)
I0813 20:55:33.755159 32456 slave.cpp:4422] Updated checkpointed resources from {} to disk(reservations: [(DYNAMIC,role1,test-principal)]):1024
I0813 20:55:33.755204 32456 slave.cpp:4430] Updated checkpointed operations from [  ] to [ 4bf07619-d588-468c-a325-37daa2aadfb0 (RESERVE, latest state: OPERATION_FINISHED) ]
I0813 20:55:33.755548 32451 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 4eb41dbe-6b64-4d16-9721-86837226f858) for operation UUID 4bf07619-d588-468c-a325-37daa2aadfb0 on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:33.755606 32451 status_update_manager_process.hpp:414] Creating operation status update stream 4bf07619-d588-468c-a325-37daa2aadfb0 checkpoint=true
I0813 20:55:33.755919 32451 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 4eb41dbe-6b64-4d16-9721-86837226f858) for operation UUID 4bf07619-d588-468c-a325-37daa2aadfb0 on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:33.756283 32452 hierarchical.cpp:710] Agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 (6c6cd7a3b2c1) updated with total resources ports:[31000-32000]; cpus:16; mem:47260; disk(reservations: [(DYNAMIC,role1,test-principal)]):1024
I0813 20:55:33.756403 32457 master.cpp:6415] Processing REVIVE call for framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:55:33.756772 32452 hierarchical.cpp:2358] Filtered offer with disk(reservations: [(DYNAMIC,role1,test-principal)]):1024; cpus:16; mem:47260; ports:[31000-32000] on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 for role role1 of framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000
I0813 20:55:33.756878 32452 hierarchical.cpp:1508] Performed allocation for 1 agents in 431512ns
I0813 20:55:33.757047 32452 hierarchical.cpp:1365] Unsuppressed offers for roles { role1 } of framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000
I0813 20:55:33.757076 32452 hierarchical.cpp:1387] Revived roles { role1 } of framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000
I0813 20:55:33.758065 32452 hierarchical.cpp:1508] Performed allocation for 1 agents in 883883ns
I0813 20:55:33.758560 32454 master.cpp:10393] Sending offers [ 87e437ee-0796-49fd-bfab-e7866bb7a81d-O1 ] to framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:55:33.759104 32447 sched.cpp:934] Scheduler::resourceOffers took 120803ns
../../../src/tests/persistent_volume_endpoints_tests.cpp:305: Failure
Value of: Resources(offer.resources()).contains( allocatedResources(volume, frameworkInfo.roles(0)))
  Actual: false
Expected: true
I0813 20:55:33.762249 32457 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/destroy-volumes'
I0813 20:55:33.763955 32450 http.cpp:1115] HTTP POST for /master/destroy-volumes from 172.17.0.2:59370
I0813 20:55:33.765049 32450 master.cpp:3996] Authorizing principal 'test-principal' to destroy volumes '[{"disk":{"persistence":{"id":"id1","principal":"test-principal"},"volume":{"container_path":"path1","mode":"RW"}},"name":"disk","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":64.0},"type":"SCALAR"}]'
I0813 20:55:33.766412 32448 hierarchical.cpp:991] Failed to update available resources on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0: {} does not contain disk(reservations: [(DYNAMIC,role1,test-principal)])[id1:path1]:64
../../../src/tests/persistent_volume_endpoints_tests.cpp:318: Failure
Value of: (response)->status
  Actual: "409 Conflict"
Expected: Accepted().status
Which is: "202 Accepted"
    Body: "{} does not contain disk(reservations: [(DYNAMIC,role1,test-principal)])[id1:path1]:64"
I0813 20:55:33.794924 32456 slave.cpp:4430] Updated checkpointed operations from [ 4bf07619-d588-468c-a325-37daa2aadfb0 (RESERVE, latest state: OPERATION_FINISHED) ] to [ 4bf07619-d588-468c-a325-37daa2aadfb0 (RESERVE, latest state: OPERATION_FINISHED), 387d0260-4b71-44ec-b63f-7db945dde737 (CREATE, latest state: OPERATION_PENDING) ]
I0813 20:55:33.795425 32456 slave.cpp:8870] Updating the state of operation with no ID (uuid: 387d0260-4b71-44ec-b63f-7db945dde737) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 20:55:33.797060 32456 slave.cpp:4422] Updated checkpointed resources from disk(reservations: [(DYNAMIC,role1,test-principal)]):1024 to disk(reservations: [(DYNAMIC,role1,test-principal)]):960; disk(reservations: [(DYNAMIC,role1,test-principal)])[id1:path1]:64
I0813 20:55:33.797538 32456 slave.cpp:4430] Updated checkpointed operations from [ 4bf07619-d588-468c-a325-37daa2aadfb0 (RESERVE, latest state: OPERATION_FINISHED), 387d0260-4b71-44ec-b63f-7db945dde737 (CREATE, latest state: OPERATION_PENDING) ] to [ 4bf07619-d588-468c-a325-37daa2aadfb0 (RESERVE, latest state: OPERATION_FINISHED), 387d0260-4b71-44ec-b63f-7db945dde737 (CREATE, latest state: OPERATION_FINISHED) ]
I0813 20:55:33.859820 32451 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 4eb41dbe-6b64-4d16-9721-86837226f858) for operation UUID 4bf07619-d588-468c-a325-37daa2aadfb0 on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:33.860033 32451 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: d1ab5628-9a4d-4a3b-b3e4-758c1b60d48d) for operation UUID 387d0260-4b71-44ec-b63f-7db945dde737 on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:33.860085 32451 status_update_manager_process.hpp:414] Creating operation status update stream 387d0260-4b71-44ec-b63f-7db945dde737 checkpoint=true
I0813 20:55:33.860110 32459 slave.cpp:8870] Updating the state of operation with no ID (uuid: 4bf07619-d588-468c-a325-37daa2aadfb0) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 20:55:33.860169 32459 slave.cpp:6279] Forwarding status update of operation with no ID (operation_uuid: 4bf07619-d588-468c-a325-37daa2aadfb0) for an operator API call
I0813 20:55:33.860332 32451 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: d1ab5628-9a4d-4a3b-b3e4-758c1b60d48d) for operation UUID 387d0260-4b71-44ec-b63f-7db945dde737 on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:33.860407 32459 master.cpp:12232] Updating the state of operation '' (uuid: 4bf07619-d588-468c-a325-37daa2aadfb0) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 20:55:33.929335 32451 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: d1ab5628-9a4d-4a3b-b3e4-758c1b60d48d) for operation UUID 387d0260-4b71-44ec-b63f-7db945dde737 on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:33.929564 32451 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 4eb41dbe-6b64-4d16-9721-86837226f858) for stream 4bf07619-d588-468c-a325-37daa2aadfb0
I0813 20:55:33.929622 32452 slave.cpp:8870] Updating the state of operation with no ID (uuid: 387d0260-4b71-44ec-b63f-7db945dde737) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 20:55:33.929627 32451 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 4eb41dbe-6b64-4d16-9721-86837226f858) for operation UUID 4bf07619-d588-468c-a325-37daa2aadfb0 on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:33.929677 32452 slave.cpp:6279] Forwarding status update of operation with no ID (operation_uuid: 387d0260-4b71-44ec-b63f-7db945dde737) for an operator API call
I0813 20:55:33.929900 32446 master.cpp:12232] Updating the state of operation '' (uuid: 387d0260-4b71-44ec-b63f-7db945dde737) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 20:55:34.001979 32451 status_update_manager_process.hpp:490] Cleaning up operation status update stream 4bf07619-d588-468c-a325-37daa2aadfb0
I0813 20:55:34.002261 32451 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: d1ab5628-9a4d-4a3b-b3e4-758c1b60d48d) for stream 387d0260-4b71-44ec-b63f-7db945dde737
I0813 20:55:34.002342 32451 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: d1ab5628-9a4d-4a3b-b3e4-758c1b60d48d) for operation UUID 387d0260-4b71-44ec-b63f-7db945dde737 on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:55:34.003449 32457 slave.cpp:4430] Updated checkpointed operations from [ 4bf07619-d588-468c-a325-37daa2aadfb0 (RESERVE, latest state: OPERATION_FINISHED), 387d0260-4b71-44ec-b63f-7db945dde737 (CREATE, latest state: OPERATION_FINISHED) ] to [ 387d0260-4b71-44ec-b63f-7db945dde737 (CREATE, latest state: OPERATION_FINISHED) ]
I0813 20:55:34.069253 32451 status_update_manager_process.hpp:490] Cleaning up operation status update stream 387d0260-4b71-44ec-b63f-7db945dde737
I0813 20:55:34.070192 32451 slave.cpp:4430] Updated checkpointed operations from [ 387d0260-4b71-44ec-b63f-7db945dde737 (CREATE, latest state: OPERATION_FINISHED) ] to [  ]
I0813 20:56:33.698092 32459 slave.cpp:7359] Current disk usage 5.96%. Max allowed age: 5.882465802822755days
../../../src/tests/persistent_volume_endpoints_tests.cpp:320: Failure
Failed to wait 1mins for rescindedOfferId
I0813 20:56:33.770623 32458 master.cpp:1410] Framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761 disconnected
I0813 20:56:33.770709 32458 master.cpp:3360] Deactivating framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:56:33.771288 32456 hierarchical.cpp:475] Deactivated framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000
../../../src/tests/persistent_volume_endpoints_tests.cpp:307: Failure
Actual function call count doesn't match EXPECT_CALL(sched, offerRescinded(&driver, _))...
         Expected: to be called once
           Actual: never called - unsatisfied and active
I0813 20:56:33.771973 32458 master.cpp:12685] Removing offer 87e437ee-0796-49fd-bfab-e7866bb7a81d-O1
I0813 20:56:33.772083 32458 master.cpp:3337] Disconnecting framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:56:33.772130 32445 slave.cpp:924] Agent terminating
I0813 20:56:33.772157 32458 master.cpp:1425] Giving framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761 0ns to failover
I0813 20:56:33.773061 32456 hierarchical.cpp:1218] Recovered disk(allocated: role1)(reservations: [(DYNAMIC,role1,test-principal)]):1024; cpus(allocated: role1):16; mem(allocated: role1):47260; ports(allocated: role1):[31000-32000] (total: ports:[31000-32000]; cpus:16; mem:47260; disk(reservations: [(DYNAMIC,role1,test-principal)]):1024, allocated: {}) on agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 from framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000
I0813 20:56:33.773207 32459 master.cpp:1295] Agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 at slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1) disconnected
I0813 20:56:33.773264 32459 master.cpp:3397] Disconnecting agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 at slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1)
I0813 20:56:33.773423 32459 master.cpp:3416] Deactivating agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 at slave(413)@172.17.0.2:36761 (6c6cd7a3b2c1)
I0813 20:56:33.773660 32447 hierarchical.cpp:799] Agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0 deactivated
I0813 20:56:33.773746 32459 master.cpp:10185] Framework failover timeout, removing framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:56:33.773800 32459 master.cpp:11184] Removing framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000 (default) at scheduler-fe570ef7-35cb-4f83-a76c-6b18e1207681@172.17.0.2:36761
I0813 20:56:33.774410 32449 hierarchical.cpp:1432] Allocation paused
I0813 20:56:33.774942 32449 hierarchical.cpp:417] Removed framework 87e437ee-0796-49fd-bfab-e7866bb7a81d-0000
I0813 20:56:33.775012 32449 hierarchical.cpp:1442] Allocation resumed
I0813 20:56:33.784154 32445 master.cpp:1135] Master terminating
I0813 20:56:33.784792 32453 hierarchical.cpp:775] Removed all filters for agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
I0813 20:56:33.784824 32453 hierarchical.cpp:650] Removed agent 87e437ee-0796-49fd-bfab-e7866bb7a81d-S0
[  FAILED  ] PersistentVolumeEndpointsTest.DynamicReservation (60140 ms)