[
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)
