Benjamin Mahler created MESOS-9881:
--------------------------------------
Summary:
StorageLocalResourceProviderTest.RetryOperationStatusUpdateAfterRecovery is
flaky.
Key: MESOS-9881
URL: https://issues.apache.org/jira/browse/MESOS-9881
Project: Mesos
Issue Type: Improvement
Reporter: Benjamin Mahler
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 [email protected]: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 [email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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 [email protected]: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
[email protected]:35735
I0702 06:51:03.113500 17269 sched.cpp:407] Authenticating with master
[email protected]: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
[email protected]: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
[email protected]: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 [email protected]:35735
I0702 06:51:03.135170 17268 sched.cpp:834] Sending SUBSCRIBE call to
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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
[email protected]:35735
I0702 06:51:04.024372 17265 master.cpp:10979] Removing framework
c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at
[email protected]:35735
I0702 06:51:04.024850 17265 master.cpp:3342] Deactivating framework
c310f701-ca24-4ea8-a4be-df3aa3637194-0000 (default) at
[email protected]: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 [email protected]: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)
