You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Chun-Hung Hsiao (JIRA)" <ji...@apache.org> on 2019/07/05 23:57:00 UTC
[jira] [Assigned] (MESOS-9881)
StorageLocalResourceProviderTest.RetryOperationStatusUpdateAfterRecovery is
flaky.
[ https://issues.apache.org/jira/browse/MESOS-9881?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Chun-Hung Hsiao reassigned MESOS-9881:
--------------------------------------
Assignee: Chun-Hung Hsiao
> StorageLocalResourceProviderTest.RetryOperationStatusUpdateAfterRecovery is flaky.
> ----------------------------------------------------------------------------------
>
> Key: MESOS-9881
> URL: https://issues.apache.org/jira/browse/MESOS-9881
> Project: Mesos
> Issue Type: Bug
> Reporter: Benjamin Mahler
> Assignee: Chun-Hung Hsiao
> Priority: Major
> Labels: flaky-test, storage
>
> This failed in CI:
> {noformat}
> 1 tests failed.
> FAILED: CSIVersion/StorageLocalResourceProviderTest.RetryOperationStatusUpdateAfterRecovery/v0
> Error Message:
> ../../../3rdparty/libprocess/include/process/gmock.hpp:667
> Mock function called more times than expected - returning default value.
> Function call: filter(@0x5617542ee270 master@172.17.0.3:35735, @0x7f83cc053c30 264-byte object <48-23 06-32 84-7F 00-00 40-DE 07-CC 83-7F 00-00 2B-00 00-00 00-00 00-00 2B-00 00-00 00-00 00-00 4C-65 6E-67 74-68 00-6F 20-AF 00-54 17-56 00-00 10-AF 00-54 17-56 00-00 02-00 00-00 AC-11 00-03 ... 20-20 05-CC 83-7F 00-00 00-00 00-00 6E-20 76-61 50-2B 4B-53 17-56 00-00 40-2B 4B-53 17-56 00-00 60-DA 07-CC 83-7F 00-00 CA-03 00-00 00-00 00-00 CA-03 00-00 00-00 00-00 10-01 00-00 00-00 00-00>)
> Returns: false
> Expected: to be never called
> Actual: called once - over-saturated and active
> Stack Trace:
> ../../../3rdparty/libprocess/include/process/gmock.hpp:667
> Mock function called more times than expected - returning default value.
> Function call: filter(@0x5617542ee270 master@172.17.0.3:35735, @0x7f83cc053c30 264-byte object <48-23 06-32 84-7F 00-00 40-DE 07-CC 83-7F 00-00 2B-00 00-00 00-00 00-00 2B-00 00-00 00-00 00-00 4C-65 6E-67 74-68 00-6F 20-AF 00-54 17-56 00-00 10-AF 00-54 17-56 00-00 02-00 00-00 AC-11 00-03 ... 20-20 05-CC 83-7F 00-00 00-00 00-00 6E-20 76-61 50-2B 4B-53 17-56 00-00 40-2B 4B-53 17-56 00-00 60-DA 07-CC 83-7F 00-00 CA-03 00-00 00-00 00-00 CA-03 00-00 00-00 00-00 10-01 00-00 00-00 00-00>)
> Returns: false
> Expected: to be never called
> Actual: called once - over-saturated and active
> {noformat}
> Full test output:
> {noformat}
> [ RUN ] CSIVersion/StorageLocalResourceProviderTest.RetryOperationStatusUpdateAfterRecovery/v0
> I0702 06:51:02.172196 6961 cluster.cpp:176] Creating default 'local' authorizer
> I0702 06:51:02.183229 17274 master.cpp:440] Master c310f701-ca24-4ea8-a4be-df3aa3637194 (005dc56bde82) started on 172.17.0.3:35735
> I0702 06:51:02.184095 17274 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/Pq6bYz/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="/tmp/SRC/build/mesos-1.9.0/_inst/share/mesos/webui" --work_dir="/tmp/Pq6bYz/master" --zk_session_timeout="10secs"
> I0702 06:51:02.185236 17274 master.cpp:492] Master only allowing authenticated frameworks to register
> I0702 06:51:02.185819 17274 master.cpp:498] Master only allowing authenticated agents to register
> I0702 06:51:02.186395 17274 master.cpp:504] Master only allowing authenticated HTTP frameworks to register
> I0702 06:51:02.186951 17274 credentials.hpp:37] Loading credentials for authentication from '/tmp/Pq6bYz/credentials'
> I0702 06:51:02.187907 17274 master.cpp:548] Using default 'crammd5' authenticator
> I0702 06:51:02.188771 17274 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
> I0702 06:51:02.189630 17274 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
> I0702 06:51:02.190573 17274 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
> I0702 06:51:02.191690 17274 master.cpp:629] Authorization enabled
> I0702 06:51:02.195374 17265 hierarchical.cpp:236] Initialized hierarchical allocator process
> I0702 06:51:02.195753 17265 whitelist_watcher.cpp:77] No whitelist given
> I0702 06:51:02.199774 17260 master.cpp:2150] Elected as the leading master!
> I0702 06:51:02.199834 17260 master.cpp:1664] Recovering from registrar
> I0702 06:51:02.200039 17267 registrar.cpp:339] Recovering registrar
> I0702 06:51:02.201155 17267 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
> I0702 06:51:02.201329 17267 registrar.cpp:487] Applied 1 operations in 65950ns; attempting to update the registry
> I0702 06:51:02.208309 17267 registrar.cpp:544] Successfully updated the registry in 0ns
> I0702 06:51:02.208516 17267 registrar.cpp:416] Successfully recovered registrar
> I0702 06:51:02.209331 17264 master.cpp:1799] Recovered 0 agents from the registry (139B); allowing 10mins for agents to reregister
> I0702 06:51:02.209575 17264 hierarchical.cpp:275] Skipping recovery of hierarchical allocator: nothing to recover
> W0702 06:51:02.222694 6961 process.cpp:2854] Attempted to spawn already running process files@172.17.0.3:35735
> I0702 06:51:02.224586 6961 containerizer.cpp:314] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
> W0702 06:51:02.225576 6961 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
> W0702 06:51:02.225612 6961 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
> W0702 06:51:02.225634 6961 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
> I0702 06:51:02.225673 6961 provisioner.cpp:298] Using default backend 'copy'
> I0702 06:51:02.229216 6961 cluster.cpp:510] Creating default 'local' authorizer
> I0702 06:51:02.232882 17262 slave.cpp:265] Mesos agent started on (1172)@172.17.0.3:35735
> I0702 06:51:02.232951 17262 slave.cpp:266] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/Pq6bYz/GXBZYg/store/appc" --authenticate_http_executors="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_destroy_timeout="1mins" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/Pq6bYz/GXBZYg/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_profile_adaptor="org_apache_mesos_UriDiskProfileAdaptor" --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/Pq6bYz/GXBZYg/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/Pq6bYz/GXBZYg/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/Pq6bYz/GXBZYg/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/Pq6bYz/GXBZYg/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --jwt_secret_key="/tmp/Pq6bYz/GXBZYg/jwt_secret_key" --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" --resource_provider_config_dir="/tmp/Pq6bYz/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_2iEfc6" --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/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV" --zk_session_timeout="10secs"
> I0702 06:51:02.233618 17262 credentials.hpp:86] Loading credential for authentication from '/tmp/Pq6bYz/GXBZYg/credential'
> I0702 06:51:02.233850 17262 slave.cpp:298] Agent using credential for: test-principal
> I0702 06:51:02.233880 17262 credentials.hpp:37] Loading credentials for authentication from '/tmp/Pq6bYz/GXBZYg/http_credentials'
> I0702 06:51:02.234169 17262 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
> I0702 06:51:02.234387 17262 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
> I0702 06:51:02.234728 17262 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> I0702 06:51:02.234867 17262 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
> I0702 06:51:02.235152 17262 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> I0702 06:51:02.235374 17262 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
> I0702 06:51:02.235862 17262 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
> I0702 06:51:02.238118 17270 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
> I0702 06:51:02.237903 17262 slave.cpp:613] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0702 06:51:02.238188 17262 slave.cpp:621] Agent attributes: [ ]
> I0702 06:51:02.238209 17262 slave.cpp:630] Agent hostname: 005dc56bde82
> I0702 06:51:02.238900 17273 task_status_update_manager.cpp:181] Pausing sending task status updates
> I0702 06:51:02.239004 17273 status_update_manager_process.hpp:379] Pausing operation status update manager
> I0702 06:51:02.240545 17262 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/meta'
> I0702 06:51:02.240797 17272 slave.cpp:7246] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/meta', beginning agent recovery
> I0702 06:51:02.241626 17272 task_status_update_manager.cpp:207] Recovering task status update manager
> I0702 06:51:02.243257 17271 containerizer.cpp:797] Recovering Mesos containers
> I0702 06:51:02.243757 17271 containerizer.cpp:1123] Recovering isolators
> I0702 06:51:02.248575 17264 containerizer.cpp:1162] Recovering provisioner
> I0702 06:51:02.249586 17269 provisioner.cpp:498] Provisioner recovery complete
> I0702 06:51:02.251462 17272 composing.cpp:339] Finished recovering all containerizers
> I0702 06:51:02.252063 17268 slave.cpp:7708] Recovering executors
> I0702 06:51:02.252202 17268 slave.cpp:7861] Finished recovery
> I0702 06:51:02.253504 17268 task_status_update_manager.cpp:181] Pausing sending task status updates
> I0702 06:51:02.253564 17268 status_update_manager_process.hpp:379] Pausing operation status update manager
> I0702 06:51:02.253592 17269 slave.cpp:1258] New master detected at master@172.17.0.3:35735
> I0702 06:51:02.253743 17269 slave.cpp:1323] Detecting new master
> I0702 06:51:02.254282 17267 slave.cpp:1350] Authenticating with master master@172.17.0.3:35735
> I0702 06:51:02.254457 17267 slave.cpp:1359] Using default CRAM-MD5 authenticatee
> I0702 06:51:02.254948 17273 authenticatee.cpp:121] Creating new client SASL connection
> I0702 06:51:02.259784 17273 master.cpp:10380] Authenticating slave(1172)@172.17.0.3:35735
> I0702 06:51:02.260010 17266 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2005)@172.17.0.3:35735
> I0702 06:51:02.260601 17272 authenticator.cpp:98] Creating new server SASL connection
> I0702 06:51:02.261148 17272 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0702 06:51:02.261195 17272 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0702 06:51:02.261355 17272 authenticator.cpp:204] Received SASL authentication start
> I0702 06:51:02.261437 17272 authenticator.cpp:326] Authentication requires more steps
> I0702 06:51:02.261595 17272 authenticatee.cpp:259] Received SASL authentication step
> I0702 06:51:02.261812 17264 authenticator.cpp:232] Received SASL authentication step
> I0702 06:51:02.261871 17264 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '005dc56bde82' server FQDN: '005dc56bde82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0702 06:51:02.261891 17264 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0702 06:51:02.261950 17264 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0702 06:51:02.261991 17264 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '005dc56bde82' server FQDN: '005dc56bde82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0702 06:51:02.262008 17264 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0702 06:51:02.262022 17264 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0702 06:51:02.262045 17264 authenticator.cpp:318] Authentication success
> I0702 06:51:02.262325 17270 authenticatee.cpp:299] Authentication success
> I0702 06:51:02.262363 17264 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2005)@172.17.0.3:35735
> I0702 06:51:02.262472 17263 master.cpp:10412] Successfully authenticated principal 'test-principal' at slave(1172)@172.17.0.3:35735
> I0702 06:51:02.269330 17261 slave.cpp:1450] Successfully authenticated with master master@172.17.0.3:35735
> I0702 06:51:02.269960 17261 slave.cpp:1900] Will retry registration in 9.221338ms if necessary
> I0702 06:51:02.270495 17263 master.cpp:6900] Received register agent message from slave(1172)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:02.270825 17263 master.cpp:4099] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
> I0702 06:51:02.272259 17265 master.cpp:6967] Authorized registration of agent at slave(1172)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:02.272406 17265 master.cpp:7082] Registering agent at slave(1172)@172.17.0.3:35735 (005dc56bde82) with id c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:02.273365 17265 registrar.cpp:487] Applied 1 operations in 400389ns; attempting to update the registry
> I0702 06:51:02.274556 17265 registrar.cpp:544] Successfully updated the registry in 0ns
> I0702 06:51:02.274871 17265 master.cpp:7130] Admitted agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1172)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:02.275835 17265 master.cpp:7175] Registered agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1172)@172.17.0.3:35735 (005dc56bde82) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
> I0702 06:51:02.276109 17264 slave.cpp:1483] Registered with master master@172.17.0.3:35735; given agent ID c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:02.276430 17263 task_status_update_manager.cpp:188] Resuming sending task status updates
> I0702 06:51:02.276739 17264 slave.cpp:1518] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/meta/slaves/c310f701-ca24-4ea8-a4be-df3aa3637194-S0/slave.info'
> I0702 06:51:02.277153 17275 status_update_manager_process.hpp:385] Resuming operation status update manager
> I0702 06:51:02.278198 17264 slave.cpp:1570] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"klh9Nk5XRbSM8Wqrv+VD4Q=="},"slave_id":{"value":"c310f701-ca24-4ea8-a4be-df3aa3637194-S0"},"update_oversubscribed_resources":false}
> I0702 06:51:02.279945 17260 master.cpp:8261] Ignoring update on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1172)@172.17.0.3:35735 (005dc56bde82) as it reports no changes
> I0702 06:51:02.291702 17266 hierarchical.cpp:656] Added agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 (005dc56bde82) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
> I0702 06:51:02.292124 17266 hierarchical.cpp:1514] Performed allocation for 1 agents in 156338ns
> I0702 06:51:02.292205 17266 process.cpp:3648] Handling HTTP event for process 'slave(1172)' with path: '/slave(1172)/api/v1'
> I0702 06:51:02.296406 17273 http.cpp:1115] HTTP POST for /slave(1172)/api/v1 from 172.17.0.3:37298
> I0702 06:51:02.297091 17273 http.cpp:2120] Processing GET_CONTAINERS call
> I0702 06:51:02.312806 17262 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:02.319221 17266 process.cpp:3648] Handling HTTP event for process 'slave(1172)' with path: '/slave(1172)/api/v1'
> I0702 06:51:02.322252 17268 http.cpp:1115] HTTP POST for /slave(1172)/api/v1 from 172.17.0.3:37300
> I0702 06:51:02.323634 17268 http.cpp:2486] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:02.325546 17268 http.cpp:2590] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:02.326704 17265 containerizer.cpp:1358] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
> I0702 06:51:02.328778 17265 containerizer.cpp:1530] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_2iEfc6/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
> I0702 06:51:02.328840 17265 containerizer.cpp:3278] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING
> I0702 06:51:02.334002 17270 containerizer.cpp:2056] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK","--available_capacity=4GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"},{"name":"CSI_ENDPOINT","type":"VALUE","value":"unix:///tmp/mesos-csi-aRZUQY/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="97" --pipe_write="98" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_2iEfc6/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
> I0702 06:51:02.349622 17270 launcher.cpp:145] Forked child with pid '17819' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:02.350658 17270 containerizer.cpp:3278] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING
> I0702 06:51:02.353214 17270 containerizer.cpp:3278] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING
> I0702 06:51:02.353513 17270 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
> I0702 06:51:02.354631 17270 containerizer.cpp:3278] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING
> I0702 06:51:02.361428 17260 container_daemon.cpp:140] Invoking post-start hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:02.361598 17260 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-aRZUQY/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
> I0702 06:51:02.519188 17267 hierarchical.cpp:1514] Performed allocation for 1 agents in 269539ns
> I0702 06:51:02.570603 17260 hierarchical.cpp:1514] Performed allocation for 1 agents in 242972ns
> I0702 06:51:02.621702 17262 hierarchical.cpp:1514] Performed allocation for 1 agents in 275443ns
> I0702 06:51:02.679761 17271 hierarchical.cpp:1514] Performed allocation for 1 agents in 290097ns
> I0702 06:51:02.731880 17268 hierarchical.cpp:1514] Performed allocation for 1 agents in 271968ns
> I0702 06:51:02.782997 17262 hierarchical.cpp:1514] Performed allocation for 1 agents in 236926ns
> I0702 06:51:02.834995 17263 hierarchical.cpp:1514] Performed allocation for 1 agents in 250265ns
> I0702 06:51:02.875907 17261 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-aRZUQY/endpoint.sock' with CSI v1
> I0702 06:51:02.879642 17273 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-aRZUQY/endpoint.sock' with CSI v0
> I0702 06:51:02.884058 17824 test_csi_plugin.cpp:555] ProbeRequest '{}'
> I0702 06:51:02.895186 17274 hierarchical.cpp:1514] Performed allocation for 1 agents in 3.655792ms
> I0702 06:51:02.896633 17267 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:02.901665 17262 process.cpp:3648] Handling HTTP event for process 'slave(1172)' with path: '/slave(1172)/api/v1'
> I0702 06:51:02.906024 17269 http.cpp:1115] HTTP POST for /slave(1172)/api/v1 from 172.17.0.3:37302
> I0702 06:51:02.905988 17823 test_csi_plugin.cpp:541] GetPluginCapabilitiesRequest '{}'
> I0702 06:51:02.906697 17269 http.cpp:2704] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:02.914158 17824 test_csi_plugin.cpp:527] GetPluginInfoRequest '{}'
> I0702 06:51:02.914994 17823 test_csi_plugin.cpp:527] GetPluginInfoRequest '{}'
> I0702 06:51:02.916908 17272 v0_volume_manager.cpp:627] NODE_SERVICE loaded: {"name":"org.apache.mesos.csi.test","vendorVersion":"1.9.0"}
> I0702 06:51:02.917702 17272 v0_volume_manager.cpp:627] CONTROLLER_SERVICE loaded: {"name":"org.apache.mesos.csi.test","vendorVersion":"1.9.0"}
> I0702 06:51:02.927631 17825 test_csi_plugin.cpp:738] ControllerGetCapabilitiesRequest '{}'
> I0702 06:51:02.947659 17824 test_csi_plugin.cpp:863] NodeGetCapabilitiesRequest '{}'
> I0702 06:51:02.947970 17260 hierarchical.cpp:1514] Performed allocation for 1 agents in 244153ns
> I0702 06:51:02.967667 17825 test_csi_plugin.cpp:850] NodeGetIdRequest '{}'
> I0702 06:51:02.981422 17267 provider.cpp:659] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
> I0702 06:51:02.981590 17261 status_update_manager_process.hpp:379] Pausing operation status update manager
> I0702 06:51:02.982067 17267 http_connection.hpp:227] New endpoint detected at http://172.17.0.3:35735/slave(1172)/api/v1/resource_provider
> I0702 06:51:02.986032 17271 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.3:35735/slave(1172)/api/v1/resource_provider
> I0702 06:51:02.986951 17273 provider.cpp:459] Connected to resource provider manager
> I0702 06:51:02.987892 17273 http_connection.hpp:131] Sending 1 call to http://172.17.0.3:35735/slave(1172)/api/v1/resource_provider
> I0702 06:51:02.989320 17273 process.cpp:3648] Handling HTTP event for process 'slave(1172)' with path: '/slave(1172)/api/v1/resource_provider'
> I0702 06:51:02.991211 17260 http.cpp:1115] HTTP POST for /slave(1172)/api/v1/resource_provider from 172.17.0.3:37304
> I0702 06:51:02.992127 17262 manager.cpp:807] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK","--available_capacity=4GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}
> I0702 06:51:02.999853 17268 hierarchical.cpp:1514] Performed allocation for 1 agents in 234199ns
> I0702 06:51:03.028410 17272 slave.cpp:8217] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"6a809e4b-36b4-40c8-bbc7-9e717854f2a4"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK","--available_capacity=4GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}'
> I0702 06:51:03.041091 17260 provider.cpp:481] Received SUBSCRIBED event
> I0702 06:51:03.041159 17260 provider.cpp:1255] Subscribed with ID 6a809e4b-36b4-40c8-bbc7-9e717854f2a4
> I0702 06:51:03.042275 17260 status_update_manager_process.hpp:314] Recovering operation status update manager
> I0702 06:51:03.051759 17265 hierarchical.cpp:1514] Performed allocation for 1 agents in 254148ns
> I0702 06:51:03.100175 17824 test_csi_plugin.cpp:689] ListVolumesRequest '{}'
> I0702 06:51:03.103009 17268 provider.cpp:2145] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.103307 17268 provider.cpp:745] Resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4 is in READY state
> I0702 06:51:03.103412 17261 http_connection.hpp:131] Sending 3 call to http://172.17.0.3:35735/slave(1172)/api/v1/resource_provider
> I0702 06:51:03.103722 17265 status_update_manager_process.hpp:385] Resuming operation status update manager
> I0702 06:51:03.104023 17275 provider.cpp:1181] Updating profiles { test } for resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4
> I0702 06:51:03.105799 17268 process.cpp:3648] Handling HTTP event for process 'slave(1172)' with path: '/slave(1172)/api/v1/resource_provider'
> I0702 06:51:03.106741 17261 hierarchical.cpp:1514] Performed allocation for 1 agents in 200396ns
> I0702 06:51:03.107589 17273 http.cpp:1115] HTTP POST for /slave(1172)/api/v1/resource_provider from 172.17.0.3:37306
> I0702 06:51:03.108191 17270 manager.cpp:1039] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4
> I0702 06:51:03.108434 17266 slave.cpp:8217] Handling resource provider message 'UPDATE_STATE: 6a809e4b-36b4-40c8-bbc7-9e717854f2a4 {}'
> I0702 06:51:03.108538 17266 slave.cpp:8337] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
> W0702 06:51:03.110785 6961 process.cpp:2854] Attempted to spawn already running process version@172.17.0.3:35735
> I0702 06:51:03.108882 17824 test_csi_plugin.cpp:717] GetCapacityRequest '{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
> I0702 06:51:03.112313 6961 sched.cpp:238] Version: 1.9.0
> I0702 06:51:03.113307 17269 sched.cpp:342] New master detected at master@172.17.0.3:35735
> I0702 06:51:03.113500 17269 sched.cpp:407] Authenticating with master master@172.17.0.3:35735
> I0702 06:51:03.113533 17269 sched.cpp:414] Using default CRAM-MD5 authenticatee
> I0702 06:51:03.114017 17260 authenticatee.cpp:121] Creating new client SASL connection
> I0702 06:51:03.116080 17274 provider.cpp:933] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096' to the total resources
> I0702 06:51:03.127861 17266 master.cpp:10380] Authenticating scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:03.128360 17266 hierarchical.cpp:792] Grew agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 by {} (total), { } (used)
> I0702 06:51:03.128751 17266 hierarchical.cpp:749] Agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 (005dc56bde82) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
> I0702 06:51:03.128867 17266 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2006)@172.17.0.3:35735
> I0702 06:51:03.129315 17268 authenticator.cpp:98] Creating new server SASL connection
> I0702 06:51:03.129873 17268 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0702 06:51:03.129915 17268 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0702 06:51:03.130060 17268 authenticator.cpp:204] Received SASL authentication start
> I0702 06:51:03.130255 17268 authenticator.cpp:326] Authentication requires more steps
> I0702 06:51:03.130507 17268 authenticatee.cpp:259] Received SASL authentication step
> I0702 06:51:03.130772 17268 authenticator.cpp:232] Received SASL authentication step
> I0702 06:51:03.130816 17268 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '005dc56bde82' server FQDN: '005dc56bde82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0702 06:51:03.130837 17268 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0702 06:51:03.130897 17268 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0702 06:51:03.130933 17268 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '005dc56bde82' server FQDN: '005dc56bde82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0702 06:51:03.130951 17268 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0702 06:51:03.130965 17268 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0702 06:51:03.130988 17268 authenticator.cpp:318] Authentication success
> I0702 06:51:03.131119 17273 authenticatee.cpp:299] Authentication success
> I0702 06:51:03.131433 17275 master.cpp:10412] Successfully authenticated principal 'test-principal' at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:03.134840 17272 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2006)@172.17.0.3:35735
> I0702 06:51:03.135114 17268 sched.cpp:519] Successfully authenticated with master master@172.17.0.3:35735
> I0702 06:51:03.135170 17268 sched.cpp:834] Sending SUBSCRIBE call to master@172.17.0.3:35735
> I0702 06:51:03.135414 17268 sched.cpp:869] Will retry registration in 1.088791095secs if necessary
> I0702 06:51:03.136543 17268 master.cpp:2890] Received SUBSCRIBE call for framework 'default' at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:03.136713 17268 master.cpp:2222] Authorizing framework principal 'test-principal' to receive offers for roles '{ storage }'
> I0702 06:51:03.138303 17268 master.cpp:2977] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
> I0702 06:51:03.142953 17268 master.cpp:10610] Adding framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735 with roles { } suppressed
> I0702 06:51:03.144780 17268 hierarchical.cpp:363] Added framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.145588 17265 sched.cpp:750] Framework registered with c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.145679 17265 sched.cpp:769] Scheduler::registered took 39244ns
> I0702 06:51:03.148044 17266 master.cpp:10195] Sending offers [ c310f701-ca24-4ea8-a4be-df3aa3637194-O0 ] to framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:03.149538 17266 sched.cpp:933] Scheduler::resourceOffers took 172359ns
> I0702 06:51:03.151300 17261 master.cpp:6119] Processing DECLINE call for offers: [ c310f701-ca24-4ea8-a4be-df3aa3637194-O0 ] for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735 with 5 seconds filter
> I0702 06:51:03.152766 17261 master.cpp:12470] Removing offer c310f701-ca24-4ea8-a4be-df3aa3637194-O0
> I0702 06:51:03.150158 17268 hierarchical.cpp:1514] Performed allocation for 1 agents in 4.790471ms
> I0702 06:51:03.154911 17268 hierarchical.cpp:1257] Recovered cpus(allocated: storage):2; mem(allocated: storage):1024; disk(allocated: storage):1024; ports(allocated: storage):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 from framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.155544 17268 hierarchical.cpp:1303] Framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 filtered agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 for 5secs
> I0702 06:51:03.175797 17274 provider.cpp:2145] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096' and 0 operations to agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.177338 17274 http_connection.hpp:131] Sending 3 call to http://172.17.0.3:35735/slave(1172)/api/v1/resource_provider
> I0702 06:51:03.178783 17272 process.cpp:3648] Handling HTTP event for process 'slave(1172)' with path: '/slave(1172)/api/v1/resource_provider'
> I0702 06:51:03.184556 17275 hierarchical.cpp:2364] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 for role storage of framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.184734 17275 hierarchical.cpp:1514] Performed allocation for 1 agents in 836699ns
> I0702 06:51:03.221693 17261 http.cpp:1115] HTTP POST for /slave(1172)/api/v1/resource_provider from 172.17.0.3:37306
> I0702 06:51:03.222576 17261 manager.cpp:1039] Received UPDATE_STATE call with resources '[{"disk":{"source":{"profile":"test","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"6a809e4b-36b4-40c8-bbc7-9e717854f2a4"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":4096.0},"type":"SCALAR"}]' and 0 operations from resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4
> I0702 06:51:03.223399 17264 slave.cpp:8217] Handling resource provider message 'UPDATE_STATE: 6a809e4b-36b4-40c8-bbc7-9e717854f2a4 disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096'
> I0702 06:51:03.223587 17264 slave.cpp:8337] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096
> I0702 06:51:03.227221 17272 hierarchical.cpp:749] Agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 (005dc56bde82) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096
> I0702 06:51:03.230659 17272 hierarchical.cpp:1514] Performed allocation for 1 agents in 1.823732ms
> I0702 06:51:03.232621 17271 master.cpp:10195] Sending offers [ c310f701-ca24-4ea8-a4be-df3aa3637194-O1 ] to framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:03.235558 17275 sched.cpp:933] Scheduler::resourceOffers took 155315ns
> I0702 06:51:03.238257 17273 master.cpp:12470] Removing offer c310f701-ca24-4ea8-a4be-df3aa3637194-O1
> I0702 06:51:03.238976 17273 master.cpp:4636] Processing ACCEPT call for offers: [ c310f701-ca24-4ea8-a4be-df3aa3637194-O1 ] on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1172)@172.17.0.3:35735 (005dc56bde82) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:03.239114 17273 master.cpp:4009] Authorizing principal 'test-principal' to create a MOUNT disk from 'disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096'
> I0702 06:51:03.240612 17267 master.cpp:5911] Processing CREATE_DISK operation with source disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096 from framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735 to agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1172)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:03.241446 17267 master.cpp:12361] Sending operation '' (uuid: 271cc763-a33a-433d-afe0-073071a04c18) to agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1172)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:03.241878 17264 hierarchical.cpp:1438] Allocation paused
> I0702 06:51:03.242202 17274 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
> I0702 06:51:03.243458 17264 hierarchical.cpp:1257] Recovered ports(allocated: storage):[31000-32000]; cpus(allocated: storage):2; mem(allocated: storage):1024; disk(allocated: storage):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096, allocated: disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096) on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 from framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.243613 17264 hierarchical.cpp:1303] Framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 filtered agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 for 5secs
> I0702 06:51:03.243939 17264 hierarchical.cpp:1448] Allocation resumed
> I0702 06:51:03.246345 17269 provider.cpp:481] Received APPLY_OPERATION event
> I0702 06:51:03.246407 17269 provider.cpp:1295] Received CREATE_DISK operation '' (uuid: 271cc763-a33a-433d-afe0-073071a04c18)
> I0702 06:51:03.302606 17267 v0_volume_manager.cpp:291] Creating volume with name '271cc763-a33a-433d-afe0-073071a04c18'
> I0702 06:51:03.306128 17825 test_csi_plugin.cpp:566] CreateVolumeRequest '{"name":"271cc763-a33a-433d-afe0-073071a04c18","capacityRange":{"requiredBytes":"4294967296","limitBytes":"4294967296"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
> I0702 06:51:03.396706 17266 provider.cpp:1597] Applying conversion from 'disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096' to 'disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK/4GB-271cc763-a33a-433d-afe0-073071a04c18,test)]:4096' for operation (uuid: 271cc763-a33a-433d-afe0-073071a04c18)
> I0702 06:51:03.443756 17268 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for operation UUID 271cc763-a33a-433d-afe0-073071a04c18 of framework 'c310f701-ca24-4ea8-a4be-df3aa3637194-0000' on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.443872 17268 status_update_manager_process.hpp:414] Creating operation status update stream 271cc763-a33a-433d-afe0-073071a04c18 checkpoint=true
> I0702 06:51:03.444402 17268 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for operation UUID 271cc763-a33a-433d-afe0-073071a04c18 of framework 'c310f701-ca24-4ea8-a4be-df3aa3637194-0000' on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.485739 17268 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for operation UUID 271cc763-a33a-433d-afe0-073071a04c18 of framework 'c310f701-ca24-4ea8-a4be-df3aa3637194-0000' on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.487391 17272 http_connection.hpp:131] Sending 2 call to http://172.17.0.3:35735/slave(1172)/api/v1/resource_provider
> I0702 06:51:03.488907 17260 process.cpp:3648] Handling HTTP event for process 'slave(1172)' with path: '/slave(1172)/api/v1/resource_provider'
> I0702 06:51:03.533749 17269 http.cpp:1115] HTTP POST for /slave(1172)/api/v1/resource_provider from 172.17.0.3:37306
> I0702 06:51:03.535411 17274 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 271cc763-a33a-433d-afe0-073071a04c18) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
> I0702 06:51:03.535691 17274 slave.cpp:8670] Updating the state of operation with no ID (uuid: 271cc763-a33a-433d-afe0-073071a04c18) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
> I0702 06:51:03.536233 17274 slave.cpp:8424] Forwarding status update of operation with no ID (operation_uuid: 271cc763-a33a-433d-afe0-073071a04c18) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.546779 6961 slave.cpp:912] Agent terminating
> I0702 06:51:03.547896 6961 manager.cpp:163] Terminating resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4
> I0702 06:51:03.548473 17269 master.cpp:1295] Agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1172)@172.17.0.3:35735 (005dc56bde82) disconnected
> I0702 06:51:03.548516 17269 master.cpp:3379] Disconnecting agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1172)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:03.548612 17269 master.cpp:3398] Deactivating agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1172)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:03.548902 17269 hierarchical.cpp:838] Agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 deactivated
> E0702 06:51:03.549425 17266 http_connection.hpp:452] End-Of-File received
> I0702 06:51:03.559234 17266 http_connection.hpp:217] Re-detecting endpoint
> W0702 06:51:03.560179 6961 process.cpp:2854] Attempted to spawn already running process files@172.17.0.3:35735
> I0702 06:51:03.562373 6961 containerizer.cpp:314] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
> I0702 06:51:03.563567 17266 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
> I0702 06:51:03.563659 17267 provider.cpp:471] Disconnected from resource provider manager
> W0702 06:51:03.563805 6961 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
> I0702 06:51:03.563819 17261 status_update_manager_process.hpp:379] Pausing operation status update manager
> W0702 06:51:03.563843 6961 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
> I0702 06:51:03.563855 17266 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
> W0702 06:51:03.563869 6961 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
> I0702 06:51:03.563911 6961 provisioner.cpp:298] Using default backend 'copy'
> I0702 06:51:03.563935 17266 http_connection.hpp:227] New endpoint detected at http://172.17.0.3:35735/slave(1172)/api/v1/resource_provider
> I0702 06:51:03.567359 17267 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.3:35735/slave(1172)/api/v1/resource_provider
> I0702 06:51:03.568122 17275 provider.cpp:459] Connected to resource provider manager
> I0702 06:51:03.568902 17270 http_connection.hpp:131] Sending 1 call to http://172.17.0.3:35735/slave(1172)/api/v1/resource_provider
> I0702 06:51:03.570624 6961 cluster.cpp:510] Creating default 'local' authorizer
> I0702 06:51:03.571178 17276 process.cpp:2758] Returning '404 Not Found' for '/slave(1172)/api/v1/resource_provider'
> E0702 06:51:03.573320 17272 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
> I0702 06:51:03.577642 17275 slave.cpp:265] Mesos agent started on (1173)@172.17.0.3:35735
> I0702 06:51:03.577723 17275 slave.cpp:266] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/Pq6bYz/GXBZYg/store/appc" --authenticate_http_executors="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_destroy_timeout="1mins" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/Pq6bYz/GXBZYg/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_profile_adaptor="org_apache_mesos_UriDiskProfileAdaptor" --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/Pq6bYz/GXBZYg/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/Pq6bYz/GXBZYg/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/Pq6bYz/GXBZYg/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/Pq6bYz/GXBZYg/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --jwt_secret_key="/tmp/Pq6bYz/GXBZYg/jwt_secret_key" --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" --resource_provider_config_dir="/tmp/Pq6bYz/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_2iEfc6" --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/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV" --zk_session_timeout="10secs"
> I0702 06:51:03.578582 17275 credentials.hpp:86] Loading credential for authentication from '/tmp/Pq6bYz/GXBZYg/credential'
> I0702 06:51:03.578820 17275 slave.cpp:298] Agent using credential for: test-principal
> I0702 06:51:03.578853 17275 credentials.hpp:37] Loading credentials for authentication from '/tmp/Pq6bYz/GXBZYg/http_credentials'
> I0702 06:51:03.579290 17275 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
> I0702 06:51:03.579538 17275 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
> I0702 06:51:03.579946 17275 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> I0702 06:51:03.580194 17275 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
> I0702 06:51:03.590823 17275 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> I0702 06:51:03.591058 17275 http.cpp:996] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readwrite'
> I0702 06:51:03.592123 17275 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
> I0702 06:51:03.594043 17270 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
> I0702 06:51:03.594390 17275 slave.cpp:613] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0702 06:51:03.594693 17275 slave.cpp:621] Agent attributes: [ ]
> I0702 06:51:03.594714 17275 slave.cpp:630] Agent hostname: 005dc56bde82
> I0702 06:51:03.594933 17268 status_update_manager_process.hpp:379] Pausing operation status update manager
> I0702 06:51:03.595134 17262 task_status_update_manager.cpp:181] Pausing sending task status updates
> I0702 06:51:03.597132 17275 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/meta'
> I0702 06:51:03.597234 17275 state.cpp:789] No committed checkpointed resources and operations found at '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/meta/resources/resources_and_operations.state'
> I0702 06:51:03.597275 17275 state.cpp:795] No committed checkpointed resources found at '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/meta/resources/resources.info'
> I0702 06:51:03.598495 17273 slave.cpp:7246] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/meta', beginning agent recovery
> I0702 06:51:03.600863 17266 task_status_update_manager.cpp:207] Recovering task status update manager
> I0702 06:51:03.604177 17269 containerizer.cpp:797] Recovering Mesos containers
> I0702 06:51:03.614013 17269 containerizer.cpp:1123] Recovering isolators
> I0702 06:51:03.628420 17264 containerizer.cpp:1162] Recovering provisioner
> I0702 06:51:03.646904 17275 provisioner.cpp:498] Provisioner recovery complete
> I0702 06:51:03.649011 17270 composing.cpp:339] Finished recovering all containerizers
> I0702 06:51:03.649885 17264 status_update_manager_process.hpp:314] Recovering operation status update manager
> I0702 06:51:03.650401 17266 slave.cpp:7708] Recovering executors
> I0702 06:51:03.650521 17266 slave.cpp:7861] Finished recovery
> I0702 06:51:03.660862 17267 task_status_update_manager.cpp:181] Pausing sending task status updates
> I0702 06:51:03.660960 17267 status_update_manager_process.hpp:379] Pausing operation status update manager
> I0702 06:51:03.661110 17265 slave.cpp:1258] New master detected at master@172.17.0.3:35735
> I0702 06:51:03.661275 17265 slave.cpp:1323] Detecting new master
> I0702 06:51:03.661708 17265 slave.cpp:1350] Authenticating with master master@172.17.0.3:35735
> I0702 06:51:03.661919 17265 slave.cpp:1359] Using default CRAM-MD5 authenticatee
> I0702 06:51:03.662524 17270 authenticatee.cpp:121] Creating new client SASL connection
> I0702 06:51:03.663018 17270 master.cpp:10380] Authenticating slave(1173)@172.17.0.3:35735
> I0702 06:51:03.663386 17270 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2007)@172.17.0.3:35735
> I0702 06:51:03.663873 17273 authenticator.cpp:98] Creating new server SASL connection
> I0702 06:51:03.664207 17273 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> I0702 06:51:03.664242 17273 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0702 06:51:03.664376 17266 authenticator.cpp:204] Received SASL authentication start
> I0702 06:51:03.664443 17266 authenticator.cpp:326] Authentication requires more steps
> I0702 06:51:03.664608 17273 authenticatee.cpp:259] Received SASL authentication step
> I0702 06:51:03.664768 17262 authenticator.cpp:232] Received SASL authentication step
> I0702 06:51:03.664806 17262 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '005dc56bde82' server FQDN: '005dc56bde82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0702 06:51:03.664824 17262 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
> I0702 06:51:03.664925 17262 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0702 06:51:03.664963 17262 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '005dc56bde82' server FQDN: '005dc56bde82' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0702 06:51:03.664980 17262 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0702 06:51:03.664993 17262 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0702 06:51:03.665016 17262 authenticator.cpp:318] Authentication success
> I0702 06:51:03.665323 17262 master.cpp:10412] Successfully authenticated principal 'test-principal' at slave(1173)@172.17.0.3:35735
> I0702 06:51:03.665406 17267 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2007)@172.17.0.3:35735
> I0702 06:51:03.665485 17273 authenticatee.cpp:299] Authentication success
> I0702 06:51:03.675276 17263 slave.cpp:1450] Successfully authenticated with master master@172.17.0.3:35735
> I0702 06:51:03.676285 17263 slave.cpp:1900] Will retry registration in 17.793703ms if necessary
> I0702 06:51:03.676757 17263 master.cpp:7254] Received reregister agent message from agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1173)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:03.677312 17263 master.cpp:4099] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
> I0702 06:51:03.678571 17263 master.cpp:7346] Authorized re-registration of agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1173)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:03.678694 17263 master.cpp:7430] Agent is already marked as registered: c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1173)@172.17.0.3:35735 (005dc56bde82)
> I0702 06:51:03.679059 17263 master.cpp:7817] Registry updated for slave c310f701-ca24-4ea8-a4be-df3aa3637194-S0 at slave(1173)@172.17.0.3:35735(005dc56bde82)
> I0702 06:51:03.680761 17260 hierarchical.cpp:749] Agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 (005dc56bde82) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
> I0702 06:51:03.681262 17260 hierarchical.cpp:1514] Performed allocation for 1 agents in 287226ns
> I0702 06:51:03.681432 17260 slave.cpp:1607] Re-registered with master master@172.17.0.3:35735
> I0702 06:51:03.681591 17262 task_status_update_manager.cpp:188] Resuming sending task status updates
> I0702 06:51:03.681670 17271 status_update_manager_process.hpp:385] Resuming operation status update manager
> I0702 06:51:03.681843 17260 slave.cpp:1653] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"ortBOVm1SoG9oy8zqwmr6g=="},"slave_id":{"value":"c310f701-ca24-4ea8-a4be-df3aa3637194-S0"},"update_oversubscribed_resources":false}
> I0702 06:51:03.683089 17263 master.cpp:8551] Garbage collecting resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4 since it disappeared from the reported agent state
> I0702 06:51:03.683220 17269 hierarchical.cpp:826] Agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 reactivated
> I0702 06:51:03.684545 17263 hierarchical.cpp:1257] Recovered disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 from framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.684947 17263 hierarchical.cpp:749] Agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 (005dc56bde82) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
> I0702 06:51:03.690811 17271 process.cpp:3648] Handling HTTP event for process 'slave(1173)' with path: '/slave(1173)/api/v1'
> I0702 06:51:03.694967 17273 http.cpp:1115] HTTP POST for /slave(1173)/api/v1 from 172.17.0.3:37312
> I0702 06:51:03.695658 17273 http.cpp:2120] Processing GET_CONTAINERS call
> I0702 06:51:03.715111 17260 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:03.728417 17269 process.cpp:3648] Handling HTTP event for process 'slave(1173)' with path: '/slave(1173)/api/v1'
> I0702 06:51:03.732177 17261 http.cpp:1115] HTTP POST for /slave(1173)/api/v1 from 172.17.0.3:37314
> I0702 06:51:03.733371 17261 http.cpp:2486] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:03.735199 17260 http.cpp:2590] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_VxywpV/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:03.738637 17269 container_daemon.cpp:140] Invoking post-start hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:03.738871 17269 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-aRZUQY/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
> I0702 06:51:03.739390 17269 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-aRZUQY/endpoint.sock' with CSI v1
> I0702 06:51:03.752061 17273 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-aRZUQY/endpoint.sock' with CSI v0
> I0702 06:51:03.754366 17825 test_csi_plugin.cpp:555] ProbeRequest '{}'
> I0702 06:51:03.756345 17265 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:03.762058 17268 process.cpp:3648] Handling HTTP event for process 'slave(1173)' with path: '/slave(1173)/api/v1'
> I0702 06:51:03.765012 17825 test_csi_plugin.cpp:541] GetPluginCapabilitiesRequest '{}'
> I0702 06:51:03.770992 17264 http.cpp:1115] HTTP POST for /slave(1173)/api/v1 from 172.17.0.3:37316
> I0702 06:51:03.771744 17264 http.cpp:2704] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:03.774685 17825 test_csi_plugin.cpp:527] GetPluginInfoRequest '{}'
> I0702 06:51:03.779883 17825 test_csi_plugin.cpp:527] GetPluginInfoRequest '{}'
> I0702 06:51:03.782791 17267 v0_volume_manager.cpp:627] NODE_SERVICE loaded: {"name":"org.apache.mesos.csi.test","vendorVersion":"1.9.0"}
> I0702 06:51:03.783892 17267 v0_volume_manager.cpp:627] CONTROLLER_SERVICE loaded: {"name":"org.apache.mesos.csi.test","vendorVersion":"1.9.0"}
> I0702 06:51:03.787953 17825 test_csi_plugin.cpp:738] ControllerGetCapabilitiesRequest '{}'
> I0702 06:51:03.793462 17824 test_csi_plugin.cpp:863] NodeGetCapabilitiesRequest '{}'
> I0702 06:51:03.799396 17824 test_csi_plugin.cpp:850] NodeGetIdRequest '{}'
> I0702 06:51:03.804769 17274 provider.cpp:659] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
> I0702 06:51:03.805029 17262 status_update_manager_process.hpp:379] Pausing operation status update manager
> I0702 06:51:03.805425 17274 http_connection.hpp:227] New endpoint detected at http://172.17.0.3:35735/slave(1173)/api/v1/resource_provider
> I0702 06:51:03.816679 17265 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.3:35735/slave(1173)/api/v1/resource_provider
> I0702 06:51:03.817557 17265 provider.cpp:459] Connected to resource provider manager
> I0702 06:51:03.817646 17269 hierarchical.cpp:2364] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 for role storage of framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.817811 17269 hierarchical.cpp:1514] Performed allocation for 1 agents in 788572ns
> I0702 06:51:03.818590 17269 http_connection.hpp:131] Sending 1 call to http://172.17.0.3:35735/slave(1173)/api/v1/resource_provider
> I0702 06:51:03.820860 17273 process.cpp:3648] Handling HTTP event for process 'slave(1173)' with path: '/slave(1173)/api/v1/resource_provider'
> I0702 06:51:03.823202 17265 http.cpp:1115] HTTP POST for /slave(1173)/api/v1/resource_provider from 172.17.0.3:37318
> I0702 06:51:03.824156 17265 manager.cpp:807] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"6a809e4b-36b4-40c8-bbc7-9e717854f2a4"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK","--available_capacity=4GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}
> I0702 06:51:03.826800 17265 slave.cpp:8217] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"6a809e4b-36b4-40c8-bbc7-9e717854f2a4"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK","--available_capacity=4GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.9.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}'
> I0702 06:51:03.829290 17268 provider.cpp:481] Received SUBSCRIBED event
> I0702 06:51:03.829339 17268 provider.cpp:1255] Subscribed with ID 6a809e4b-36b4-40c8-bbc7-9e717854f2a4
> I0702 06:51:03.830417 17268 status_update_manager_process.hpp:314] Recovering operation status update manager
> I0702 06:51:03.830451 17268 status_update_manager_process.hpp:443] Recovering operation status update stream 271cc763-a33a-433d-afe0-073071a04c18
> I0702 06:51:03.830601 17268 status_update_manager_process.hpp:684] Replaying operation status update stream 271cc763-a33a-433d-afe0-073071a04c18
> I0702 06:51:03.871783 17262 hierarchical.cpp:2364] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 for role storage of framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.871971 17262 hierarchical.cpp:1514] Performed allocation for 1 agents in 823024ns
> I0702 06:51:03.883889 17825 test_csi_plugin.cpp:689] ListVolumesRequest '{}'
> I0702 06:51:03.890048 17269 provider.cpp:2145] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK/4GB-271cc763-a33a-433d-afe0-073071a04c18,test)]:4096' and 1 operations to agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.891535 17263 http_connection.hpp:131] Sending 3 call to http://172.17.0.3:35735/slave(1173)/api/v1/resource_provider
> I0702 06:51:03.893234 17269 provider.cpp:745] Resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4 is in READY state
> I0702 06:51:03.893364 17262 status_update_manager_process.hpp:385] Resuming operation status update manager
> I0702 06:51:03.893533 17262 status_update_manager_process.hpp:394] Sending operation status update OPERATION_FINISHED (Status UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for operation UUID 271cc763-a33a-433d-afe0-073071a04c18 of framework 'c310f701-ca24-4ea8-a4be-df3aa3637194-0000' on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.893708 17262 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for operation UUID 271cc763-a33a-433d-afe0-073071a04c18 of framework 'c310f701-ca24-4ea8-a4be-df3aa3637194-0000' on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.894066 17269 provider.cpp:1181] Updating profiles { test } for resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4
> I0702 06:51:03.894603 17270 process.cpp:3648] Handling HTTP event for process 'slave(1173)' with path: '/slave(1173)/api/v1/resource_provider'
> I0702 06:51:03.895231 17266 http_connection.hpp:131] Sending 2 call to http://172.17.0.3:35735/slave(1173)/api/v1/resource_provider
> I0702 06:51:03.898072 17267 process.cpp:3648] Handling HTTP event for process 'slave(1173)' with path: '/slave(1173)/api/v1/resource_provider'
> I0702 06:51:03.899016 17824 test_csi_plugin.cpp:717] GetCapacityRequest '{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
> I0702 06:51:03.900077 17267 http.cpp:1115] HTTP POST for /slave(1173)/api/v1/resource_provider from 172.17.0.3:37320
> I0702 06:51:03.900907 17271 http.cpp:1115] HTTP POST for /slave(1173)/api/v1/resource_provider from 172.17.0.3:37320
> I0702 06:51:03.902041 17273 manager.cpp:1039] Received UPDATE_STATE call with resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK/4GB-271cc763-a33a-433d-afe0-073071a04c18","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"6a809e4b-36b4-40c8-bbc7-9e717854f2a4"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":4096.0},"type":"SCALAR"}]' and 1 operations from resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4
> I0702 06:51:03.904001 17260 slave.cpp:8217] Handling resource provider message 'UPDATE_STATE: 6a809e4b-36b4-40c8-bbc7-9e717854f2a4 disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK/4GB-271cc763-a33a-433d-afe0-073071a04c18,test)]:4096'
> I0702 06:51:03.904436 17260 slave.cpp:8337] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK/4GB-271cc763-a33a-433d-afe0-073071a04c18,test)]:4096
> I0702 06:51:03.905464 17260 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 271cc763-a33a-433d-afe0-073071a04c18) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
> I0702 06:51:03.906247 17260 slave.cpp:8670] Updating the state of operation with no ID (uuid: 271cc763-a33a-433d-afe0-073071a04c18) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
> I0702 06:51:03.906770 17260 slave.cpp:8424] Forwarding status update of operation with no ID (operation_uuid: 271cc763-a33a-433d-afe0-073071a04c18) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.909225 17264 master.cpp:12017] Updating the state of operation '' (uuid: 271cc763-a33a-433d-afe0-073071a04c18) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
> I0702 06:51:03.910964 17271 hierarchical.cpp:792] Grew agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 by disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK/4GB-271cc763-a33a-433d-afe0-073071a04c18,test)]:4096 (total), { } (used)
> I0702 06:51:03.911810 17271 hierarchical.cpp:749] Agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 (005dc56bde82) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK/4GB-271cc763-a33a-433d-afe0-073071a04c18,test)]:4096
> I0702 06:51:03.912344 17263 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
> W0702 06:51:03.919116 17268 status_update_manager_process.hpp:561] Resending operation status update OPERATION_FINISHED (Status UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for operation UUID 271cc763-a33a-433d-afe0-073071a04c18 of framework 'c310f701-ca24-4ea8-a4be-df3aa3637194-0000' on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.919390 17268 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for operation UUID 271cc763-a33a-433d-afe0-073071a04c18 of framework 'c310f701-ca24-4ea8-a4be-df3aa3637194-0000' on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.920790 17274 hierarchical.cpp:1514] Performed allocation for 1 agents in 1.767853ms
> I0702 06:51:03.921411 17271 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
> I0702 06:51:03.921604 17267 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for stream 271cc763-a33a-433d-afe0-073071a04c18
> I0702 06:51:03.921819 17267 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for operation UUID 271cc763-a33a-433d-afe0-073071a04c18 of framework 'c310f701-ca24-4ea8-a4be-df3aa3637194-0000' on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:03.922170 17275 master.cpp:10195] Sending offers [ c310f701-ca24-4ea8-a4be-df3aa3637194-O2 ] to framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:03.923420 17275 sched.cpp:933] Scheduler::resourceOffers took 177357ns
> I0702 06:51:03.923853 17275 master.cpp:6119] Processing DECLINE call for offers: [ c310f701-ca24-4ea8-a4be-df3aa3637194-O2 ] for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735 with 5 seconds filter
> I0702 06:51:03.924742 17275 master.cpp:12470] Removing offer c310f701-ca24-4ea8-a4be-df3aa3637194-O2
> I0702 06:51:03.926450 17272 http_connection.hpp:131] Sending 2 call to http://172.17.0.3:35735/slave(1173)/api/v1/resource_provider
> I0702 06:51:03.926137 17275 hierarchical.cpp:1257] Recovered disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK/4GB-271cc763-a33a-433d-afe0-073071a04c18,test)]:4096; cpus(allocated: storage):2; mem(allocated: storage):1024; disk(allocated: storage):1024; ports(allocated: storage):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_RetryOperationStatusUpdateAfterRecovery_v0_dmtPCK/4GB-271cc763-a33a-433d-afe0-073071a04c18,test)]:4096, allocated: {}) on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 from framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:03.927861 17275 hierarchical.cpp:1303] Framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 filtered agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0 for 5secs
> I0702 06:51:03.929471 17270 process.cpp:3648] Handling HTTP event for process 'slave(1173)' with path: '/slave(1173)/api/v1/resource_provider'
> I0702 06:51:03.970381 17271 http.cpp:1115] HTTP POST for /slave(1173)/api/v1/resource_provider from 172.17.0.3:37320
> I0702 06:51:03.972749 17260 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 271cc763-a33a-433d-afe0-073071a04c18) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
> I0702 06:51:03.973163 17260 slave.cpp:8424] Forwarding status update of unknown operation with no ID (operation_uuid: 271cc763-a33a-433d-afe0-073071a04c18) for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> ../../../3rdparty/libprocess/include/process/gmock.hpp:667: Failure
> Mock function called more times than expected - returning default value.
> Function call: filter(@0x5617542ee270 master@172.17.0.3:35735, @0x7f83cc053c30 264-byte object <48-23 06-32 84-7F 00-00 40-DE 07-CC 83-7F 00-00 2B-00 00-00 00-00 00-00 2B-00 00-00 00-00 00-00 4C-65 6E-67 74-68 00-6F 20-AF 00-54 17-56 00-00 10-AF 00-54 17-56 00-00 02-00 00-00 AC-11 00-03 ... 20-20 05-CC 83-7F 00-00 00-00 00-00 6E-20 76-61 50-2B 4B-53 17-56 00-00 40-2B 4B-53 17-56 00-00 60-DA 07-CC 83-7F 00-00 CA-03 00-00 00-00 00-00 CA-03 00-00 00-00 00-00 10-01 00-00 00-00 00-00>)
> Returns: false
> Expected: to be never called
> Actual: called once - over-saturated and active
> I0702 06:51:03.974445 17260 master.cpp:8918] Forwarding operation status update OPERATION_FINISHED (Status UUID: 68c2e5d0-4a0b-4ff0-88df-5fb0db5ac96f) for operation UUID 271cc763-a33a-433d-afe0-073071a04c18 of framework 'c310f701-ca24-4ea8-a4be-df3aa3637194-0000' on agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> ../../../3rdparty/libprocess/include/process/gmock.hpp:667: Failure
> Mock function called more times than expected - returning default value.
> Function call: filter(@0x561753f7eb38 scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735, @0x7f83cc04b570 264-byte object <48-23 06-32 84-7F 00-00 30-A9 03-CC 83-7F 00-00 2B-00 00-00 00-00 00-00 2B-00 00-00 00-00 00-00 01-00 00-00 04-00 00-00 70-EA D1-53 17-56 00-00 60-EA D1-53 17-56 00-00 02-00 00-00 AC-11 00-03 ... 20-20 05-CC 83-7F 00-00 00-00 00-00 00-00 00-00 D0-E8 27-54 17-56 00-00 C0-E8 27-54 17-56 00-00 40-27 05-CC 83-7F 00-00 CA-03 00-00 00-00 00-00 CA-03 00-00 00-00 00-00 10-01 00-00 00-00 00-00>)
> Returns: false
> Expected: to be never called
> Actual: called twice - over-saturated and active
> I0702 06:51:03.979326 17267 status_update_manager_process.hpp:490] Cleaning up operation status update stream 271cc763-a33a-433d-afe0-073071a04c18
> I0702 06:51:04.021899 6961 sched.cpp:2142] Asked to stop the driver
> I0702 06:51:04.022596 17263 sched.cpp:1203] Stopping framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:04.023797 17265 master.cpp:10967] Processing TEARDOWN call for framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:04.024372 17265 master.cpp:10979] Removing framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:04.024850 17265 master.cpp:3342] Deactivating framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at scheduler-02f836bc-4477-49a8-a545-186312642018@172.17.0.3:35735
> I0702 06:51:04.025781 17269 hierarchical.cpp:470] Deactivated framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:04.026620 17269 hierarchical.cpp:1438] Allocation paused
> I0702 06:51:04.026193 17263 slave.cpp:3908] Asked to shut down framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000 by master@172.17.0.3:35735
> I0702 06:51:04.026895 17263 slave.cpp:3923] Cannot shut down unknown framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:04.027060 17263 slave.cpp:912] Agent terminating
> I0702 06:51:04.031503 17263 manager.cpp:163] Terminating resource provider 6a809e4b-36b4-40c8-bbc7-9e717854f2a4
> I0702 06:51:04.032186 17269 hierarchical.cpp:412] Removed framework c310f701-ca24-4ea8-a4be-df3aa3637194-0000
> I0702 06:51:04.032876 17269 hierarchical.cpp:1448] Allocation resumed
> E0702 06:51:04.033488 17269 http_connection.hpp:452] End-Of-File received
> I0702 06:51:04.036317 17269 http_connection.hpp:217] Re-detecting endpoint
> I0702 06:51:04.037176 17269 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
> I0702 06:51:04.037986 17266 provider.cpp:471] Disconnected from resource provider manager
> I0702 06:51:04.038122 17266 status_update_manager_process.hpp:379] Pausing operation status update manager
> I0702 06:51:04.038017 17269 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
> I0702 06:51:04.038770 17269 http_connection.hpp:227] New endpoint detected at http://172.17.0.3:35735/slave(1173)/api/v1/resource_provider
> I0702 06:51:04.048555 17266 containerizer.cpp:2576] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
> I0702 06:51:04.048635 17266 containerizer.cpp:3278] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING
> I0702 06:51:04.049026 17266 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
> I0702 06:51:04.049870 17268 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.3:35735/slave(1173)/api/v1/resource_provider
> I0702 06:51:04.050664 17268 provider.cpp:459] Connected to resource provider manager
> I0702 06:51:04.050945 17260 hierarchical.cpp:1514] Performed allocation for 1 agents in 271483ns
> I0702 06:51:04.051857 17274 http_connection.hpp:131] Sending 1 call to http://172.17.0.3:35735/slave(1173)/api/v1/resource_provider
> I0702 06:51:04.055801 17276 process.cpp:2758] Returning '404 Not Found' for '/slave(1173)/api/v1/resource_provider'
> E0702 06:51:04.064468 17269 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
> I0702 06:51:04.107865 17272 hierarchical.cpp:1514] Performed allocation for 1 agents in 323199ns
> I0702 06:51:04.153684 17263 containerizer.cpp:3117] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
> I0702 06:51:04.155720 17265 provisioner.cpp:609] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
> I0702 06:51:04.158768 17262 container_daemon.cpp:189] Invoking post-stop hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:04.159026 17262 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-aRZUQY/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
> I0702 06:51:04.159307 17263 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
> I0702 06:51:04.160019 17268 hierarchical.cpp:1514] Performed allocation for 1 agents in 289172ns
> I0702 06:51:04.163892 17276 process.cpp:2758] Returning '404 Not Found' for '/slave(1173)/api/v1'
> I0702 06:51:04.206770 6961 master.cpp:1135] Master terminating
> I0702 06:51:04.207700 17272 hierarchical.cpp:814] Removed all filters for agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> I0702 06:51:04.207731 17272 hierarchical.cpp:689] Removed agent c310f701-ca24-4ea8-a4be-df3aa3637194-S0
> [ FAILED ] CSIVersion/StorageLocalResourceProviderTest.RetryOperationStatusUpdateAfterRecovery/v0, where GetParam() = "v0" (2060 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)