-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/#review216711
-----------------------------------------------------------



Bad patch!

Reviews applied: [71109, 71110, 71061, 71068, 71111]

Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:14.04' 
BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose 
--disable-libtool-wrappers --disable-parallel-test-execution' 
ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/docker-build.sh 2>&1 | tee 
build_71111"]

Error:
...<truncated>...
b-ade3-31adcc3bff52 on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:48.936278 18267 http_connection.hpp:131] Sending 2 call to 
http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
I0718 06:35:48.937249 18275 process.cpp:3671] Handling HTTP event for process 
'slave(1216)' with path: '/slave(1216)/api/v1/resource_provider'
I0718 06:35:48.940191 18257 process.cpp:3671] Handling HTTP event for process 
'master' with path: '/master/api/v1'
I0718 06:35:48.941807 18280 http.cpp:1115] HTTP POST for /master/api/v1 from 
172.17.0.2:52610
I0718 06:35:48.942044 18280 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0718 06:35:48.942693 18280 master.cpp:3888] Authorizing principal 
'test-principal' to unreserve resources 
'[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a","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":"8e9395d9-3d92-4641-876e-2a95f843d191"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0718 06:35:48.944628 18263 master.cpp:12685] Removing offer 
58665dec-7eb8-49bb-ad94-85d02ec4f434-O5
I0718 06:35:48.944752 18276 sched.cpp:960] Rescinded offer 
58665dec-7eb8-49bb-ad94-85d02ec4f434-O5
I0718 06:35:48.944823 18276 sched.cpp:971] Scheduler::offerRescinded took 
21015ns
I0718 06:35:48.945453 18259 hierarchical.cpp:1218] Recovered disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a,test)]:2048;
 cpus(allocated: storage/default-role):2; mem(allocated: 
storage/default-role):1024; disk(allocated: storage/default-role):1024; 
ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; 
disk:1024; ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a,test)]:2048,
 allocated: {}) on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 from framework 
58665dec-7eb8-49
 bb-ad94-85d02ec4f434-0000
I0718 06:35:48.945569 18259 hierarchical.cpp:1264] Framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 filtered agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 for 5secs
I0718 06:35:48.948091 18273 master.cpp:12576] Sending operation '' (uuid: 
32631748-d534-4830-af5b-2860ca4a04ce) to agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 at slave(1216)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:48.948653 18267 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:48.951097 18279 hierarchical.cpp:1508] Performed allocation for 1 
agents in 1.161105ms
I0718 06:35:48.951505 18262 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:48.951555 18262 provider.cpp:1295] Received UNRESERVE operation '' 
(uuid: 32631748-d534-4830-af5b-2860ca4a04ce)
I0718 06:35:48.951690 18260 master.cpp:10393] Sending offers [ 
58665dec-7eb8-49bb-ad94-85d02ec4f434-O6 ] to framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at 
scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
I0718 06:35:48.952296 18261 sched.cpp:934] Scheduler::resourceOffers took 
77288ns
I0718 06:35:48.976239 18268 http.cpp:1115] HTTP POST for 
/slave(1216)/api/v1/resource_provider from 172.17.0.2:52600
I0718 06:35:48.977198 18271 slave.cpp:8406] Handling resource provider message 
'UPDATE_OPERATION_STATUS: (uuid: d9520b5c-c932-4e3b-ade3-31adcc3bff52) for 
framework  (latest state: OPERATION_FINISHED, status update state: 
OPERATION_FINISHED)'
I0718 06:35:48.977396 18271 slave.cpp:8859] Updating the state of operation 
with no ID (uuid: d9520b5c-c932-4e3b-ade3-31adcc3bff52) for an operation API 
call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:48.977449 18271 slave.cpp:8613] Forwarding status update of 
operation with no ID (operation_uuid: d9520b5c-c932-4e3b-ade3-31adcc3bff52) for 
an operator API call
I0718 06:35:48.977864 18272 master.cpp:12232] Updating the state of operation 
'' (uuid: d9520b5c-c932-4e3b-ade3-31adcc3bff52) for an operator API call 
(latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:48.978397 18275 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:49.053128 18261 status_update_manager_process.hpp:152] Received 
operation status update OPERATION_FINISHED (Status UUID: 
ee21e755-02b8-4795-8df7-ca8c77ebabe3) for operation UUID 
32631748-d534-4830-af5b-2860ca4a04ce on agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.053190 18261 status_update_manager_process.hpp:414] Creating 
operation status update stream 32631748-d534-4830-af5b-2860ca4a04ce 
checkpoint=true
I0718 06:35:49.053222 18262 provider.cpp:481] Received 
ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:49.053681 18261 status_update_manager_process.hpp:929] 
Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status 
UUID: ee21e755-02b8-4795-8df7-ca8c77ebabe3) for operation UUID 
32631748-d534-4830-af5b-2860ca4a04ce on agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.119984 18261 status_update_manager_process.hpp:528] Forwarding 
operation status update OPERATION_FINISHED (Status UUID: 
ee21e755-02b8-4795-8df7-ca8c77ebabe3) for operation UUID 
32631748-d534-4830-af5b-2860ca4a04ce on agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.120317 18261 status_update_manager_process.hpp:252] Received 
operation status update acknowledgement (UUID: 
815ffb76-1d43-4a60-9368-d331b763824a) for stream 
d9520b5c-c932-4e3b-ade3-31adcc3bff52
I0718 06:35:49.120391 18261 status_update_manager_process.hpp:929] 
Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 
815ffb76-1d43-4a60-9368-d331b763824a) for operation UUID 
d9520b5c-c932-4e3b-ade3-31adcc3bff52 on agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.120766 18276 http_connection.hpp:131] Sending 2 call to 
http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
I0718 06:35:49.121618 18269 process.cpp:3671] Handling HTTP event for process 
'slave(1216)' with path: '/slave(1216)/api/v1/resource_provider'
I0718 06:35:49.160171 18272 http.cpp:1115] HTTP POST for 
/slave(1216)/api/v1/resource_provider from 172.17.0.2:52600
I0718 06:35:49.161003 18275 slave.cpp:8406] Handling resource provider message 
'UPDATE_OPERATION_STATUS: (uuid: 32631748-d534-4830-af5b-2860ca4a04ce) for 
framework  (latest state: OPERATION_FINISHED, status update state: 
OPERATION_FINISHED)'
I0718 06:35:49.161162 18275 slave.cpp:8859] Updating the state of operation 
with no ID (uuid: 32631748-d534-4830-af5b-2860ca4a04ce) for an operation API 
call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:49.161221 18275 slave.cpp:8613] Forwarding status update of 
operation with no ID (operation_uuid: 32631748-d534-4830-af5b-2860ca4a04ce) for 
an operator API call
I0718 06:35:49.161540 18265 master.cpp:12232] Updating the state of operation 
'' (uuid: 32631748-d534-4830-af5b-2860ca4a04ce) for an operator API call 
(latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:49.162003 18266 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:49.163297 18263 provider.cpp:481] Received 
ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:49.186823 18261 status_update_manager_process.hpp:490] Cleaning up 
operation status update stream d9520b5c-c932-4e3b-ade3-31adcc3bff52
I0718 06:35:49.187043 18261 status_update_manager_process.hpp:252] Received 
operation status update acknowledgement (UUID: 
ee21e755-02b8-4795-8df7-ca8c77ebabe3) for stream 
32631748-d534-4830-af5b-2860ca4a04ce
I0718 06:35:49.187108 18261 status_update_manager_process.hpp:929] 
Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 
ee21e755-02b8-4795-8df7-ca8c77ebabe3) for operation UUID 
32631748-d534-4830-af5b-2860ca4a04ce on agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.270552 18261 status_update_manager_process.hpp:490] Cleaning up 
operation status update stream 32631748-d534-4830-af5b-2860ca4a04ce
I0718 06:35:49.330803 18277 master.cpp:1410] Framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at 
scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893 disconnected
I0718 06:35:49.330852 18277 master.cpp:3360] Deactivating framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at 
scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
I0718 06:35:49.331161 18272 hierarchical.cpp:475] Deactivated framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000
I0718 06:35:49.331636 18264 slave.cpp:914] Agent terminating
I0718 06:35:49.331769 18277 master.cpp:12685] Removing offer 
58665dec-7eb8-49bb-ad94-85d02ec4f434-O6
I0718 06:35:49.331845 18277 master.cpp:3337] Disconnecting framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at 
scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
I0718 06:35:49.331902 18277 master.cpp:1425] Giving framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at 
scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893 0ns to failover
I0718 06:35:49.332553 18264 manager.cpp:163] Terminating resource provider 
8e9395d9-3d92-4641-876e-2a95f843d191
I0718 06:35:49.332798 18272 hierarchical.cpp:1218] Recovered disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a,test)]:2048;
 cpus(allocated: storage/default-role):2; mem(allocated: 
storage/default-role):1024; disk(allocated: storage/default-role):1024; 
ports(allocated: storage/default-role):[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_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a,test)]:2048,
 allocated: {}) on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 from framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000
I0718 06:35:49.332942 18268 master.cpp:1295] Agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 at slave(1216)@172.17.0.2:42893 
(2dfcf722f334) disconnected
I0718 06:35:49.332975 18268 master.cpp:3397] Disconnecting agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 at slave(1216)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:49.333076 18268 master.cpp:3416] Deactivating agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 at slave(1216)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:49.333236 18263 hierarchical.cpp:799] Agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 deactivated
I0718 06:35:49.333317 18268 master.cpp:10185] Framework failover timeout, 
removing framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at 
scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
I0718 06:35:49.333348 18268 master.cpp:11184] Removing framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at 
scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
E0718 06:35:49.333554 18257 http_connection.hpp:452] End-Of-File received
I0718 06:35:49.333743 18279 hierarchical.cpp:1432] Allocation paused
I0718 06:35:49.334012 18257 http_connection.hpp:217] Re-detecting endpoint
I0718 06:35:49.334133 18279 hierarchical.cpp:417] Removed framework 
58665dec-7eb8-49bb-ad94-85d02ec4f434-0000
I0718 06:35:49.334301 18279 hierarchical.cpp:1442] Allocation resumed
I0718 06:35:49.334461 18257 http_connection.hpp:338] Ignoring disconnection 
attempt from stale connection
I0718 06:35:49.334540 18257 http_connection.hpp:338] Ignoring disconnection 
attempt from stale connection
I0718 06:35:49.334599 18262 provider.cpp:471] Disconnected from resource 
provider manager
I0718 06:35:49.334620 18257 http_connection.hpp:227] New endpoint detected at 
http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
I0718 06:35:49.334723 18262 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0718 06:35:49.336087 18263 containerizer.cpp:2575] Destroying container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 in RUNNING state
I0718 06:35:49.336127 18263 containerizer.cpp:3277] 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
I0718 06:35:49.336532 18263 launcher.cpp:161] Asked to destroy container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.337605 18280 http_connection.hpp:283] Connected with the remote 
endpoint at http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
I0718 06:35:49.338202 18259 provider.cpp:459] Connected to resource provider 
manager
I0718 06:35:49.338624 18262 hierarchical.cpp:1508] Performed allocation for 1 
agents in 171742ns
I0718 06:35:49.338865 18269 http_connection.hpp:131] Sending 1 call to 
http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
E0718 06:35:49.339365 18269 provider.cpp:702] Failed to subscribe resource 
provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Cannot 
process 'SUBSCRIBE' call as the driver is in state SUBSCRIBING
I0718 06:35:49.339617 18281 process.cpp:2781] Returning '404 Not Found' for 
'/slave(1216)/api/v1/resource_provider'
E0718 06:35:49.340737 18257 provider.cpp:702] Failed to subscribe resource 
provider with type 'org.apache.mesos.rp.local.storage' and name 'test': 
Received '404 Not Found' ()
I0718 06:35:49.389438 18271 hierarchical.cpp:1508] Performed allocation for 1 
agents in 119409ns
I0718 06:35:49.440466 18266 containerizer.cpp:3116] Container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 has exited
I0718 06:35:49.440948 18267 hierarchical.cpp:1508] Performed allocation for 1 
agents in 118003ns
I0718 06:35:49.441980 18279 provisioner.cpp:611] Ignoring destroy request for 
unknown container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.444370 18274 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'
I0718 06:35:49.444556 18271 service_manager.cpp:723] Disconnected from endpoint 
'unix:///tmp/mesos-csi-xn82K9/endpoint.sock' of CSI plugin container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.444809 18277 container_daemon.cpp:121] Launching container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.447003 18281 process.cpp:2781] Returning '404 Not Found' for 
'/slave(1216)/api/v1'
I0718 06:35:49.462693 18256 master.cpp:1135] Master terminating
I0718 06:35:49.463418 18263 hierarchical.cpp:775] Removed all filters for agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.463449 18263 hierarchical.cpp:650] Removed agent 
58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
[       OK ] 
CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v0
 (2347 ms)
[ RUN      ] 
CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1
I0718 06:35:49.487236 18256 cluster.cpp:176] Creating default 'local' authorizer
I0718 06:35:49.493167 18268 master.cpp:440] Master 
f44b3929-d9b5-487c-bc8a-9166548ec65c (2dfcf722f334) started on 172.17.0.2:42893
I0718 06:35:49.493196 18268 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/afMihM/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_alloca
 table_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="/mesos/mesos-1.9.0/_inst/share/mesos/webui" 
--work_dir="/tmp/afMihM/master" --zk_session_timeout="10secs"
I0718 06:35:49.493587 18268 master.cpp:492] Master only allowing authenticated 
frameworks to register
I0718 06:35:49.493602 18268 master.cpp:498] Master only allowing authenticated 
agents to register
I0718 06:35:49.493609 18268 master.cpp:504] Master only allowing authenticated 
HTTP frameworks to register
I0718 06:35:49.493618 18268 credentials.hpp:37] Loading credentials for 
authentication from '/tmp/afMihM/credentials'
I0718 06:35:49.493932 18268 master.cpp:548] Using default 'crammd5' 
authenticator
I0718 06:35:49.494132 18268 http.cpp:975] Creating default 'basic' HTTP 
authenticator for realm 'mesos-master-readonly'
I0718 06:35:49.494351 18268 http.cpp:975] Creating default 'basic' HTTP 
authenticator for realm 'mesos-master-readwrite'
I0718 06:35:49.494525 18268 http.cpp:975] Creating default 'basic' HTTP 
authenticator for realm 'mesos-master-scheduler'
I0718 06:35:49.494688 18268 master.cpp:629] Authorization enabled
I0718 06:35:49.495096 18258 hierarchical.cpp:241] Initialized hierarchical 
allocator process
I0718 06:35:49.495121 18266 whitelist_watcher.cpp:77] No whitelist given
I0718 06:35:49.498165 18262 master.cpp:2168] Elected as the leading master!
I0718 06:35:49.498209 18262 master.cpp:1664] Recovering from registrar
I0718 06:35:49.498469 18257 registrar.cpp:339] Recovering registrar
I0718 06:35:49.499452 18257 registrar.cpp:383] Successfully fetched the 
registry (0B) in 0ns
I0718 06:35:49.499619 18257 registrar.cpp:487] Applied 1 operations in 49105ns; 
attempting to update the registry
I0718 06:35:49.500439 18257 registrar.cpp:544] Successfully updated the 
registry in 0ns
I0718 06:35:49.500612 18257 registrar.cpp:416] Successfully recovered registrar
I0718 06:35:49.501106 18277 master.cpp:1817] Recovered 0 agents from the 
registry (143B); allowing 10mins for agents to reregister
I0718 06:35:49.501122 18276 hierarchical.cpp:280] Skipping recovery of 
hierarchical allocator: nothing to recover
W0718 06:35:49.510432 18256 process.cpp:2877] Attempted to spawn already 
running process files@172.17.0.2:42893
I0718 06:35:49.511931 18256 containerizer.cpp:314] Using isolation { 
environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0718 06:35:49.512583 18256 backend.cpp:76] Failed to create 'overlay' backend: 
OverlayBackend requires root privileges
W0718 06:35:49.512614 18256 backend.cpp:76] Failed to create 'aufs' backend: 
AufsBackend requires root privileges
W0718 06:35:49.512758 18256 backend.cpp:76] Failed to create 'bind' backend: 
BindBackend requires root privileges
I0718 06:35:49.512816 18256 provisioner.cpp:300] Using default backend 'copy'
I0718 06:35:49.515456 18256 cluster.cpp:510] Creating default 'local' authorizer
I0718 06:35:49.517908 18280 slave.cpp:265] Mesos agent started on 
(1217)@172.17.0.2:42893
I0718 06:35:49.517946 18280 slave.cpp:266] Flags at startup: --acls="" 
--appc_simple_discovery_uri_prefix="http://"; 
--appc_store_dir="/tmp/afMihM/LJ1J7u/store/appc" 
--authenticate_http_readonly="true" --authenticate_http_readwrite="false" 
--authenticatee="crammd5" --authentication_backoff_factor="1secs" 
--authentication_timeout_max="1mins" --authentication_timeout_min="5secs" 
--authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" 
--cgroups_destroy_timeout="1mins" --cgroups_enable_cfs="false" 
--cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" 
--cgroups_root="mesos" --container_disk_watch_interval="15secs" 
--containerizers="mesos" --credential="/tmp/afMihM/LJ1J7u/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/afMihM/LJ1J7u/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/afMihM/LJ1J7u/fetch" --fetcher_cache_size="2GB" 
--fetcher_stall_timeout="1mins" 
--frameworks_home="/tmp/afMihM/LJ1J7u/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/afMihM/LJ1J7u/http_credentials" 
--http_heartbeat_interval="30secs" --initialize_driver_logging="true" 
--isolation="posix/cpu,posix/mem" --launcher="posix" 
--launcher_dir="/mesos/mesos-1.9.0/_build/src" --logbufsecs="0" --
 logging_level="INFO" --max_completed_executors_per_framework="150" 
--memory_profiling="false" --network_cni_metrics="true" 
--network_cni_root_dir_persist="false" 
--oversubscribed_resources_interval="15secs" --perf_duration="10secs" 
--perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" 
--quiet="false" --reconfiguration_policy="equal" --recover="reconnect" 
--recovery_timeout="15mins" --registration_backoff_factor="10ms" 
--resource_provider_config_dir="/tmp/afMihM/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_OperatorOperationsWithResourceProviderResources_v1_oAuNTO"
 --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_OperatorOperationsW
 ithResourceProviderResources_v1_ikcSF8" --zk_session_timeout="10secs"
I0718 06:35:49.518683 18280 credentials.hpp:86] Loading credential for 
authentication from '/tmp/afMihM/LJ1J7u/credential'
I0718 06:35:49.518950 18280 slave.cpp:298] Agent using credential for: 
test-principal
I0718 06:35:49.518985 18280 credentials.hpp:37] Loading credentials for 
authentication from '/tmp/afMihM/LJ1J7u/http_credentials'
I0718 06:35:49.519269 18280 http.cpp:975] Creating default 'basic' HTTP 
authenticator for realm 'mesos-agent-readonly'
I0718 06:35:49.519717 18280 disk_profile_adaptor.cpp:82] Creating disk profile 
adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0718 06:35:49.521451 18280 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"}]
I0718 06:35:49.521661 18280 slave.cpp:621] Agent attributes: [  ]
I0718 06:35:49.521677 18280 slave.cpp:630] Agent hostname: 2dfcf722f334
I0718 06:35:49.521881 18279 task_status_update_manager.cpp:181] Pausing sending 
task status updates
I0718 06:35:49.521966 18274 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0718 06:35:49.522753 18270 process.cpp:3671] Handling HTTP event for process 
'test-disk-profile-server' with path: '/test-disk-profile-server/profiles'
I0718 06:35:49.523643 18259 state.cpp:67] Recovering state from 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/meta'
I0718 06:35:49.523870 18270 slave.cpp:7433] Finished recovering checkpointed 
state from 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/meta',
 beginning agent recovery
I0718 06:35:49.524508 18257 task_status_update_manager.cpp:207] Recovering task 
status update manager
I0718 06:35:49.524986 18263 containerizer.cpp:796] Recovering Mesos containers
I0718 06:35:49.525370 18263 containerizer.cpp:1122] Recovering isolators
I0718 06:35:49.526113 18259 containerizer.cpp:1161] Recovering provisioner
I0718 06:35:49.526892 18267 provisioner.cpp:500] Provisioner recovery complete
I0718 06:35:49.526926 18258 uri_disk_profile_adaptor.cpp:305] Updated disk 
profile mapping to 1 active profiles
I0718 06:35:49.527727 18269 composing.cpp:339] Finished recovering all 
containerizers
I0718 06:35:49.528043 18268 slave.cpp:7897] Recovering executors
I0718 06:35:49.528167 18268 slave.cpp:8050] Finished recovery
I0718 06:35:49.528998 18273 task_status_update_manager.cpp:181] Pausing sending 
task status updates
I0718 06:35:49.529022 18280 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0718 06:35:49.529038 18268 slave.cpp:1340] New master detected at 
master@172.17.0.2:42893
I0718 06:35:49.529153 18268 slave.cpp:1405] Detecting new master
I0718 06:35:49.530478 18263 slave.cpp:1432] Authenticating with master 
master@172.17.0.2:42893
I0718 06:35:49.530588 18263 slave.cpp:1441] Using default CRAM-MD5 authenticatee
I0718 06:35:49.530939 18266 authenticatee.cpp:121] Creating new client SASL 
connection
I0718 06:35:49.531298 18259 master.cpp:10578] Authenticating 
slave(1217)@172.17.0.2:42893
I0718 06:35:49.531458 18261 authenticator.cpp:414] Starting authentication 
session for crammd5-authenticatee(2067)@172.17.0.2:42893
I0718 06:35:49.531769 18260 authenticator.cpp:98] Creating new server SASL 
connection
I0718 06:35:49.532027 18270 authenticatee.cpp:213] Received SASL authentication 
mechanisms: CRAM-MD5
I0718 06:35:49.532060 18270 authenticatee.cpp:239] Attempting to authenticate 
with mechanism 'CRAM-MD5'
I0718 06:35:49.532186 18270 authenticator.cpp:204] Received SASL authentication 
start
I0718 06:35:49.532263 18270 authenticator.cpp:326] Authentication requires more 
steps
I0718 06:35:49.532397 18267 authenticatee.cpp:259] Received SASL authentication 
step
I0718 06:35:49.532549 18277 authenticator.cpp:232] Received SASL authentication 
step
I0718 06:35:49.532588 18277 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2dfcf722f334' server FQDN: '2dfcf722f334' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: false 
I0718 06:35:49.532601 18277 auxprop.cpp:181] Looking up auxiliary property 
'*userPassword'
I0718 06:35:49.532647 18277 auxprop.cpp:181] Looking up auxiliary property 
'*cmusaslsecretCRAM-MD5'
I0718 06:35:49.532673 18277 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2dfcf722f334' server FQDN: '2dfcf722f334' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: true 
I0718 06:35:49.532685 18277 auxprop.cpp:131] Skipping auxiliary property 
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0718 06:35:49.532693 18277 auxprop.cpp:131] Skipping auxiliary property 
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0718 06:35:49.532711 18277 authenticator.cpp:318] Authentication success
I0718 06:35:49.532845 18275 authenticatee.cpp:299] Authentication success
I0718 06:35:49.532934 18276 master.cpp:10610] Successfully authenticated 
principal 'test-principal' at slave(1217)@172.17.0.2:42893
I0718 06:35:49.532964 18257 authenticator.cpp:432] Authentication session 
cleanup for crammd5-authenticatee(2067)@172.17.0.2:42893
I0718 06:35:49.533296 18265 slave.cpp:1532] Successfully authenticated with 
master master@172.17.0.2:42893
I0718 06:35:49.533687 18265 slave.cpp:1982] Will retry registration in 
14.219294ms if necessary
I0718 06:35:49.533859 18264 master.cpp:7086] Received register agent message 
from slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:49.534157 18264 master.cpp:4202] Authorizing agent providing 
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 
'test-principal'
I0718 06:35:49.534883 18273 master.cpp:7153] Authorized registration of agent 
at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:49.534976 18273 master.cpp:7265] Registering agent at 
slave(1217)@172.17.0.2:42893 (2dfcf722f334) with id 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:49.535847 18268 registrar.cpp:487] Applied 1 operations in 
346039ns; attempting to update the registry
I0718 06:35:49.536739 18268 registrar.cpp:544] Successfully updated the 
registry in 0ns
I0718 06:35:49.536936 18259 master.cpp:7313] Admitted agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:49.537765 18259 master.cpp:7358] Registered agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0718 06:35:49.537971 18260 hierarchical.cpp:617] Added agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 (2dfcf722f334) with cpus:2; mem:1024; 
disk:1024; ports:[31000-32000] (allocated: {})
I0718 06:35:49.537988 18258 slave.cpp:1565] Registered with master 
master@172.17.0.2:42893; given agent ID f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:49.538180 18267 task_status_update_manager.cpp:188] Resuming 
sending task status updates
I0718 06:35:49.538328 18260 hierarchical.cpp:1508] Performed allocation for 1 
agents in 144421ns
I0718 06:35:49.538522 18258 slave.cpp:1600] Checkpointing SlaveInfo to 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/meta/slaves/f44b3929-d9b5-487c-bc8a-9166548ec65c-S0/slave.info'
I0718 06:35:49.538590 18277 status_update_manager_process.hpp:385] Resuming 
operation status update manager
I0718 06:35:49.539849 18258 slave.cpp:1652] Forwarding agent update 
{"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"Gnc6CnPVSvK5CEN7Jq8Esw=="},"slave_id":{"value":"f44b3929-d9b5-487c-bc8a-9166548ec65c-S0"},"update_oversubscribed_resources":false}
I0718 06:35:49.540607 18258 master.cpp:8457] Ignoring update on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334) as it reports no changes
I0718 06:35:49.544711 18263 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1'
I0718 06:35:49.545956 18260 http.cpp:1115] HTTP POST for /slave(1217)/api/v1 
from 172.17.0.2:52620
I0718 06:35:49.546427 18260 http.cpp:2131] Processing GET_CONTAINERS call
I0718 06:35:49.552007 18271 container_daemon.cpp:121] Launching container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.554302 18261 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1'
I0718 06:35:49.555373 18260 http.cpp:1115] HTTP POST for /slave(1217)/api/v1 
from 172.17.0.2:52622
I0718 06:35:49.556149 18260 http.cpp:2497] Processing LAUNCH_CONTAINER call for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.557004 18269 http.cpp:2601] Creating sandbox 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.557669 18272 containerizer.cpp:1357] Starting container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.558848 18272 containerizer.cpp:1529] Checkpointed 
ContainerConfig at 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_oAuNTO/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0718 06:35:49.558892 18272 containerizer.cpp:3277] 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
I0718 06:35:49.561774 18273 containerizer.cpp:2055] Launching 
'mesos-containerizer' with flags '--help="false" 
--launch_info="{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/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-h4Grme/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperat
 
ionsWithResourceProviderResources_v1_ikcSF8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}"
 --pipe_read="89" --pipe_write="90" 
--runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_oAuNTO/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"
 --unshare_namespace_mnt="false"'
I0718 06:35:49.571067 18273 launcher.cpp:145] Forked child with pid '32265' for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.571827 18273 containerizer.cpp:3277] 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
I0718 06:35:49.573238 18273 containerizer.cpp:3277] 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
I0718 06:35:49.573511 18273 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_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.574594 18273 containerizer.cpp:3277] 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
I0718 06:35:49.577538 18257 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'
I0718 06:35:49.577924 18269 service_manager.cpp:703] Connecting to endpoint 
'unix:///tmp/mesos-csi-h4Grme/endpoint.sock' of CSI plugin container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.703343 18278 hierarchical.cpp:1508] Performed allocation for 1 
agents in 211596ns
I0718 06:35:49.754878 18259 hierarchical.cpp:1508] Performed allocation for 1 
agents in 212471ns
I0718 06:35:49.806216 18265 hierarchical.cpp:1508] Performed allocation for 1 
agents in 115730ns
I0718 06:35:49.857538 18272 hierarchical.cpp:1508] Performed allocation for 1 
agents in 110070ns
I0718 06:35:49.908625 18271 hierarchical.cpp:1508] Performed allocation for 1 
agents in 202178ns
I0718 06:35:49.945896 18273 service_manager.cpp:545] Probing endpoint 
'unix:///tmp/mesos-csi-h4Grme/endpoint.sock' with CSI v1
I0718 06:35:49.960067 18270 hierarchical.cpp:1508] Performed allocation for 1 
agents in 110587ns
I0718 06:35:49.962503 32269 test_csi_plugin.cpp:909] ProbeRequest '{}'
I0718 06:35:49.964473 18265 container_daemon.cpp:171] Waiting for container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.966799 32269 test_csi_plugin.cpp:895] 
GetPluginCapabilitiesRequest '{}'
I0718 06:35:49.967489 18278 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1'
I0718 06:35:49.968814 18277 http.cpp:1115] HTTP POST for /slave(1217)/api/v1 
from 172.17.0.2:52624
I0718 06:35:49.969342 18277 http.cpp:2715] Processing WAIT_CONTAINER call for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.970137 32269 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0718 06:35:49.970537 32270 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0718 06:35:49.971812 18264 v1_volume_manager.cpp:648] NODE_SERVICE loaded: 
{"name":".","vendorVersion":"1.9.0"}
I0718 06:35:49.972340 18264 v1_volume_manager.cpp:648] CONTROLLER_SERVICE 
loaded: {"name":".","vendorVersion":"1.9.0"}
I0718 06:35:49.974244 32269 test_csi_plugin.cpp:1105] 
ControllerGetCapabilitiesRequest '{}'
I0718 06:35:49.978019 32271 test_csi_plugin.cpp:1241] 
NodeGetCapabilitiesRequest '{}'
I0718 06:35:49.980964 32269 test_csi_plugin.cpp:1255] NodeGetInfoRequest '{}'
I0718 06:35:49.982805 18274 provider.cpp:659] Finished recovery for resource 
provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0718 06:35:49.982946 18267 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0718 06:35:49.983366 18265 http_connection.hpp:227] New endpoint detected at 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:49.986076 18275 http_connection.hpp:283] Connected with the remote 
endpoint at http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:49.986701 18259 provider.cpp:459] Connected to resource provider 
manager
I0718 06:35:49.987385 18261 http_connection.hpp:131] Sending 1 call to 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:49.989063 18277 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:49.990777 18257 http.cpp:1115] HTTP POST for 
/slave(1217)/api/v1/resource_provider from 172.17.0.2:52628
I0718 06:35:49.991423 18269 manager.cpp:807] Subscribing resource provider 
{"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/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"}
I0718 06:35:50.011234 18278 hierarchical.cpp:1508] Performed allocation for 1 
agents in 162283ns
I0718 06:35:50.041683 18268 slave.cpp:8406] Handling resource provider message 
'SUBSCRIBE: 
{"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"ab871185-944c-426f-96fa-c6831d8cca77"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/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"}'
I0718 06:35:50.043459 18262 provider.cpp:481] Received SUBSCRIBED event
I0718 06:35:50.043503 18262 provider.cpp:1255] Subscribed with ID 
ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:50.044394 18257 status_update_manager_process.hpp:314] Recovering 
operation status update manager
I0718 06:35:50.062119 18265 hierarchical.cpp:1508] Performed allocation for 1 
agents in 138827ns
I0718 06:35:50.094015 32271 test_csi_plugin.cpp:1050] ListVolumesRequest '{}'
I0718 06:35:50.096356 18259 provider.cpp:2145] Sending UPDATE_STATE call with 
resources '{}' and 0 operations to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.096578 18259 provider.cpp:745] Resource provider 
ab871185-944c-426f-96fa-c6831d8cca77 is in READY state
I0718 06:35:50.096638 18270 status_update_manager_process.hpp:385] Resuming 
operation status update manager
I0718 06:35:50.096748 18261 http_connection.hpp:131] Sending 3 call to 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.097267 18273 provider.cpp:1181] Updating profiles { test } for 
resource provider ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:50.097743 18257 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.099234 18271 http.cpp:1115] HTTP POST for 
/slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.099692 18259 manager.cpp:1039] Received UPDATE_STATE call with 
resources '[]' and 0 operations from resource provider 
ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:50.099930 18261 slave.cpp:8406] Handling resource provider message 
'UPDATE_STATE: ab871185-944c-426f-96fa-c6831d8cca77 {}'
I0718 06:35:50.100023 18261 slave.cpp:8526] Forwarding new total resources 
cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0718 06:35:50.100754 32269 test_csi_plugin.cpp:1078] GetCapacityRequest 
'{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0718 06:35:50.101701 18264 hierarchical.cpp:753] Grew agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 by {} (total), {  } (used)
I0718 06:35:50.102058 18264 hierarchical.cpp:710] Agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 (2dfcf722f334) updated with total 
resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
W0718 06:35:50.102881 18256 process.cpp:2877] Attempted to spawn already 
running process version@172.17.0.2:42893
I0718 06:35:50.104557 18256 sched.cpp:239] Version: 1.9.0
I0718 06:35:50.105274 18275 provider.cpp:933] Removing '{}' and adding 
'disk(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to the 
total resources
I0718 06:35:50.105537 18270 sched.cpp:343] New master detected at 
master@172.17.0.2:42893
I0718 06:35:50.105690 18270 sched.cpp:408] Authenticating with master 
master@172.17.0.2:42893
I0718 06:35:50.105712 18270 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0718 06:35:50.106098 18276 authenticatee.cpp:121] Creating new client SASL 
connection
I0718 06:35:50.106461 18277 master.cpp:10578] Authenticating 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.106591 18273 hierarchical.cpp:1508] Performed allocation for 1 
agents in 191270ns
I0718 06:35:50.106680 18263 authenticator.cpp:414] Starting authentication 
session for crammd5-authenticatee(2068)@172.17.0.2:42893
I0718 06:35:50.107017 18258 authenticator.cpp:98] Creating new server SASL 
connection
I0718 06:35:50.107264 18267 authenticatee.cpp:213] Received SASL authentication 
mechanisms: CRAM-MD5
I0718 06:35:50.107295 18267 authenticatee.cpp:239] Attempting to authenticate 
with mechanism 'CRAM-MD5'
I0718 06:35:50.107434 18272 authenticator.cpp:204] Received SASL authentication 
start
I0718 06:35:50.107501 18272 authenticator.cpp:326] Authentication requires more 
steps
I0718 06:35:50.107630 18260 authenticatee.cpp:259] Received SASL authentication 
step
I0718 06:35:50.107770 18274 authenticator.cpp:232] Received SASL authentication 
step
I0718 06:35:50.107806 18274 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2dfcf722f334' server FQDN: '2dfcf722f334' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: false 
I0718 06:35:50.107825 18274 auxprop.cpp:181] Looking up auxiliary property 
'*userPassword'
I0718 06:35:50.107872 18274 auxprop.cpp:181] Looking up auxiliary property 
'*cmusaslsecretCRAM-MD5'
I0718 06:35:50.107897 18274 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2dfcf722f334' server FQDN: '2dfcf722f334' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: true 
I0718 06:35:50.107911 18274 auxprop.cpp:131] Skipping auxiliary property 
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0718 06:35:50.107919 18274 auxprop.cpp:131] Skipping auxiliary property 
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0718 06:35:50.107936 18274 authenticator.cpp:318] Authentication success
I0718 06:35:50.108047 18264 authenticatee.cpp:299] Authentication success
I0718 06:35:50.108144 18257 master.cpp:10610] Successfully authenticated 
principal 'test-principal' at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.108250 18279 authenticator.cpp:432] Authentication session 
cleanup for crammd5-authenticatee(2068)@172.17.0.2:42893
I0718 06:35:50.108518 18280 sched.cpp:520] Successfully authenticated with 
master master@172.17.0.2:42893
I0718 06:35:50.108549 18280 sched.cpp:835] Sending SUBSCRIBE call to 
master@172.17.0.2:42893
I0718 06:35:50.108745 18280 sched.cpp:870] Will retry registration in 
699.506857ms if necessary
I0718 06:35:50.108958 18271 master.cpp:2908] Received SUBSCRIBE call for 
framework 'default' at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.109004 18271 master.cpp:2240] Authorizing framework principal 
'test-principal' to receive offers for roles '{ storage/default-role }'
I0718 06:35:50.109678 18259 master.cpp:2995] Subscribing framework default with 
checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0718 06:35:50.112325 18259 master.cpp:10808] Adding framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 with roles {  } 
suppressed
I0718 06:35:50.112905 18259 sched.cpp:751] Framework registered with 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.112958 18259 sched.cpp:770] Scheduler::registered took 25522ns
I0718 06:35:50.113319 18270 hierarchical.cpp:368] Added framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.114655 18270 hierarchical.cpp:1508] Performed allocation for 1 
agents in 1.189537ms
I0718 06:35:50.115185 18267 master.cpp:10393] Sending offers [ 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O0 ] to framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.115813 18272 sched.cpp:934] Scheduler::resourceOffers took 
124289ns
I0718 06:35:50.116174 18272 master.cpp:6222] Processing DECLINE call for 
offers: [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O0 ] for framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 with 5 seconds 
filter
I0718 06:35:50.116768 18272 master.cpp:12685] Removing offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O0
I0718 06:35:50.117504 18266 hierarchical.cpp:1218] Recovered cpus(allocated: 
storage/default-role):2; mem(allocated: storage/default-role):1024; 
disk(allocated: storage/default-role):1024; ports(allocated: 
storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; 
ports:[31000-32000], allocated: {}) on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.117584 18266 hierarchical.cpp:1264] Framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:50.158517 18275 provider.cpp:2145] Sending UPDATE_STATE call with 
resources 'disk(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' and 0 
operations to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.158982 18257 http_connection.hpp:131] Sending 3 call to 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.160059 18269 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.200642 18261 http.cpp:1115] HTTP POST for 
/slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.201333 18262 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":"ab871185-944c-426f-96fa-c6831d8cca77"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
 and 0 operations from resource provider ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:50.201990 18276 slave.cpp:8406] Handling resource provider message 
'UPDATE_STATE: ab871185-944c-426f-96fa-c6831d8cca77 disk(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0718 06:35:50.202152 18276 slave.cpp:8526] 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)]:2048
I0718 06:35:50.204303 18258 hierarchical.cpp:710] Agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 (2dfcf722f334) 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)]:2048
I0718 06:35:50.205917 18258 hierarchical.cpp:1508] Performed allocation for 1 
agents in 1.416548ms
I0718 06:35:50.206583 18270 master.cpp:10393] Sending offers [ 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O1 ] to framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.207168 18267 sched.cpp:934] Scheduler::resourceOffers took 
80757ns
I0718 06:35:50.213413 18275 hierarchical.cpp:1508] Performed allocation for 1 
agents in 256217ns
I0718 06:35:50.213567 18257 master.cpp:12685] Removing offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O1
I0718 06:35:50.214010 18257 master.cpp:4739] Processing ACCEPT call for offers: 
[ f44b3929-d9b5-487c-bc8a-9166548ec65c-O1 ] on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334) for framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 
(default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.214113 18257 master.cpp:4112] Authorizing principal 
'test-principal' to create a MOUNT disk from 'disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0718 06:35:50.215229 18269 master.cpp:6014] Processing CREATE_DISK operation 
with source disk(allocated: storage/default-role)(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048 from 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 to agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:50.215819 18269 master.cpp:12576] Sending operation '' (uuid: 
fa3040be-761c-48af-8744-eeacd859c2b1) to agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:50.216156 18279 hierarchical.cpp:1432] Allocation paused
I0718 06:35:50.216315 18268 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:50.217308 18279 hierarchical.cpp:1218] Recovered ports(allocated: 
storage/default-role):[31000-32000]; cpus(allocated: storage/default-role):2; 
mem(allocated: storage/default-role):1024; disk(allocated: 
storage/default-role):1024 (total: cpus:2; mem:1024; disk:1024; 
ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048, 
allocated: disk(allocated: storage/default-role)(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048) on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.217403 18279 hierarchical.cpp:1264] Framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:50.217617 18279 hierarchical.cpp:1442] Allocation resumed
I0718 06:35:50.218603 18277 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:50.218650 18277 provider.cpp:1295] Received CREATE_DISK operation 
'' (uuid: fa3040be-761c-48af-8744-eeacd859c2b1)
I0718 06:35:50.264605 18270 hierarchical.cpp:2358] Filtered offer with cpus:2; 
mem:1024; disk:1024; ports:[31000-32000] on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.264715 18270 hierarchical.cpp:1508] Performed allocation for 1 
agents in 721700ns
I0718 06:35:50.267459 18267 v1_volume_manager.cpp:292] Creating volume with 
name 'fa3040be-761c-48af-8744-eeacd859c2b1'
I0718 06:35:50.269886 32271 test_csi_plugin.cpp:922] CreateVolumeRequest 
'{"name":"fa3040be-761c-48af-8744-eeacd859c2b1","capacityRange":{"requiredBytes":"2147483648","limitBytes":"2147483648"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0718 06:35:50.316169 18274 hierarchical.cpp:2358] Filtered offer with cpus:2; 
mem:1024; disk:1024; ports:[31000-32000] on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.316279 18274 hierarchical.cpp:1508] Performed allocation for 1 
agents in 450001ns
I0718 06:35:50.352061 18264 provider.cpp:1597] Applying conversion from 
'disk(allocated: storage/default-role)(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to 
'disk(allocated: storage/default-role)(reservations: 
[(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048'
 for operation (uuid: fa3040be-761c-48af-8744-eeacd859c2b1)
I0718 06:35:50.367465 18269 hierarchical.cpp:2358] Filtered offer with cpus:2; 
mem:1024; disk:1024; ports:[31000-32000] on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.367585 18269 hierarchical.cpp:1508] Performed allocation for 1 
agents in 436515ns
I0718 06:35:50.402191 18280 status_update_manager_process.hpp:152] Received 
operation status update OPERATION_FINISHED (Status UUID: 
c1e2518c-b64f-4d8d-adbd-33f804348ec5) for operation UUID 
fa3040be-761c-48af-8744-eeacd859c2b1 of framework 
'f44b3929-d9b5-487c-bc8a-9166548ec65c-0000' on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.402269 18280 status_update_manager_process.hpp:414] Creating 
operation status update stream fa3040be-761c-48af-8744-eeacd859c2b1 
checkpoint=true
I0718 06:35:50.402807 18280 status_update_manager_process.hpp:929] 
Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status 
UUID: c1e2518c-b64f-4d8d-adbd-33f804348ec5) for operation UUID 
fa3040be-761c-48af-8744-eeacd859c2b1 of framework 
'f44b3929-d9b5-487c-bc8a-9166548ec65c-0000' on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.419173 18271 hierarchical.cpp:2358] Filtered offer with cpus:2; 
mem:1024; disk:1024; ports:[31000-32000] on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.419293 18271 hierarchical.cpp:1508] Performed allocation for 1 
agents in 444662ns
I0718 06:35:50.469071 18280 status_update_manager_process.hpp:528] Forwarding 
operation status update OPERATION_FINISHED (Status UUID: 
c1e2518c-b64f-4d8d-adbd-33f804348ec5) for operation UUID 
fa3040be-761c-48af-8744-eeacd859c2b1 of framework 
'f44b3929-d9b5-487c-bc8a-9166548ec65c-0000' on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.469879 18279 http_connection.hpp:131] Sending 2 call to 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.470650 18276 hierarchical.cpp:2358] Filtered offer with cpus:2; 
mem:1024; disk:1024; ports:[31000-32000] on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.470762 18276 hierarchical.cpp:1508] Performed allocation for 1 
agents in 430674ns
I0718 06:35:50.470855 18273 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.509068 18266 http.cpp:1115] HTTP POST for 
/slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.510097 18260 slave.cpp:8406] Handling resource provider message 
'UPDATE_OPERATION_STATUS: (uuid: fa3040be-761c-48af-8744-eeacd859c2b1) for 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (latest state: 
OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0718 06:35:50.510287 18260 slave.cpp:8859] Updating the state of operation 
with no ID (uuid: fa3040be-761c-48af-8744-eeacd859c2b1) for framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (latest state: OPERATION_FINISHED, 
status update state: OPERATION_FINISHED)
I0718 06:35:50.510596 18260 slave.cpp:8613] Forwarding status update of 
operation with no ID (operation_uuid: fa3040be-761c-48af-8744-eeacd859c2b1) for 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.510973 18278 master.cpp:12232] Updating the state of operation 
'' (uuid: fa3040be-761c-48af-8744-eeacd859c2b1) for framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (latest state: OPERATION_PENDING, 
status update state: OPERATION_FINISHED)
I0718 06:35:50.512049 18269 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:50.512818 18275 hierarchical.cpp:956] Updated allocation of 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048 to 
disk(allocated: storage/default-role)(reservations: 
[(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048
I0718 06:35:50.513881 18276 provider.cpp:481] Received 
ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:50.513953 18275 hierarchical.cpp:1218] Recovered disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048
 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048,
 allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.514142 18259 status_update_manager_process.hpp:252] Received 
operation status update acknowledgement (UUID: 
c1e2518c-b64f-4d8d-adbd-33f804348ec5) for stream 
fa3040be-761c-48af-8744-eeacd859c2b1
I0718 06:35:50.514245 18259 status_update_manager_process.hpp:929] 
Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 
c1e2518c-b64f-4d8d-adbd-33f804348ec5) for operation UUID 
fa3040be-761c-48af-8744-eeacd859c2b1 of framework 
'f44b3929-d9b5-487c-bc8a-9166548ec65c-0000' on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.523241 18270 hierarchical.cpp:1508] Performed allocation for 1 
agents in 1.624642ms
I0718 06:35:50.524140 18277 master.cpp:10393] Sending offers [ 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O2 ] to framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.525131 18272 sched.cpp:934] Scheduler::resourceOffers took 
184138ns
I0718 06:35:50.529074 18278 process.cpp:3671] Handling HTTP event for process 
'master' with path: '/master/api/v1'
I0718 06:35:50.530931 18263 http.cpp:1115] HTTP POST for /master/api/v1 from 
172.17.0.2:52630
I0718 06:35:50.531266 18263 http.cpp:263] Processing call RESERVE_RESOURCES
I0718 06:35:50.532136 18263 master.cpp:3824] Authorizing principal 
'test-principal' to reserve resources 'disk(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048'
I0718 06:35:50.534296 18275 master.cpp:12685] Removing offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O2
I0718 06:35:50.534413 18270 sched.cpp:960] Rescinded offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O2
I0718 06:35:50.534502 18270 sched.cpp:971] Scheduler::offerRescinded took 
25607ns
I0718 06:35:50.535185 18258 hierarchical.cpp:1218] Recovered disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048;
 cpus(allocated: storage/default-role):2; mem(allocated: 
storage/default-role):1024; disk(allocated: storage/default-role):1024; 
ports(allocated: storage/default-role):[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_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048,
 allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.535307 18258 hierarchical.cpp:1264] Framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:50.538084 18277 master.cpp:12576] Sending operation '' (uuid: 
dacd81f2-2272-4c62-9dfb-906d9e6d751c) to agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:50.538652 18277 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:50.541456 18279 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:50.541501 18279 provider.cpp:1295] Received RESERVE operation '' 
(uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c)
I0718 06:35:50.594462 18259 status_update_manager_process.hpp:490] Cleaning up 
operation status update stream fa3040be-761c-48af-8744-eeacd859c2b1
I0718 06:35:50.662050 18261 status_update_manager_process.hpp:152] Received 
operation status update OPERATION_FINISHED (Status UUID: 
20c2d345-e373-497d-a205-0d157a4444f4) for operation UUID 
dacd81f2-2272-4c62-9dfb-906d9e6d751c on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.662115 18261 status_update_manager_process.hpp:414] Creating 
operation status update stream dacd81f2-2272-4c62-9dfb-906d9e6d751c 
checkpoint=true
I0718 06:35:50.662621 18261 status_update_manager_process.hpp:929] 
Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status 
UUID: 20c2d345-e373-497d-a205-0d157a4444f4) for operation UUID 
dacd81f2-2272-4c62-9dfb-906d9e6d751c on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.737598 18261 status_update_manager_process.hpp:528] Forwarding 
operation status update OPERATION_FINISHED (Status UUID: 
20c2d345-e373-497d-a205-0d157a4444f4) for operation UUID 
dacd81f2-2272-4c62-9dfb-906d9e6d751c on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.738670 18273 http_connection.hpp:131] Sending 2 call to 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.739692 18275 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.743198 18258 hierarchical.cpp:1508] Performed allocation for 1 
agents in 1.649531ms
I0718 06:35:50.744285 18266 master.cpp:10393] Sending offers [ 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O3 ] to framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.745348 18272 sched.cpp:934] Scheduler::resourceOffers took 
130355ns
I0718 06:35:50.748872 18260 process.cpp:3671] Handling HTTP event for process 
'master' with path: '/master/api/v1'
I0718 06:35:50.750543 18271 http.cpp:1115] HTTP POST for /master/api/v1 from 
172.17.0.2:52632
I0718 06:35:50.750867 18271 http.cpp:263] Processing call CREATE_VOLUMES
I0718 06:35:50.751615 18271 master.cpp:3951] Authorizing principal 
'test-principal' to create volumes 
'[{"disk":{"persistence":{"id":"6a9a0667-d9f8-4259-96f2-5bbca5a04aa9","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"},"volume":{"container_path":"volume","mode":"RW"}},"name":"disk","provider_id":{"value":"ab871185-944c-426f-96fa-c6831d8cca77"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0718 06:35:50.753542 18262 master.cpp:12685] Removing offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O3
I0718 06:35:50.753687 18261 sched.cpp:960] Rescinded offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O3
I0718 06:35:50.753769 18261 sched.cpp:971] Scheduler::offerRescinded took 
29139ns
I0718 06:35:50.754274 18279 hierarchical.cpp:1218] Recovered disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048;
 cpus(allocated: storage/default-role):2; mem(allocated: 
storage/default-role):1024; disk(allocated: storage/default-role):1024; 
ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; 
disk:1024; ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048,
 allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework 
f44b3929-d9b5-48
 7c-bc8a-9166548ec65c-0000
I0718 06:35:50.754384 18279 hierarchical.cpp:1264] Framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:50.756850 18263 master.cpp:12576] Sending operation '' (uuid: 
ed2820e5-b8f8-4fef-bf2d-cd9862689444) to agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:50.757478 18275 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:50.760519 18264 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:50.760560 18264 provider.cpp:1295] Received CREATE operation '' 
(uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444)
I0718 06:35:50.767174 18268 master.cpp:6415] Processing REVIVE call for 
framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.767566 18271 hierarchical.cpp:1365] Unsuppressed offers for 
roles { storage/default-role } of framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.767611 18271 hierarchical.cpp:1387] Revived roles { 
storage/default-role } of framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.769394 18271 hierarchical.cpp:1508] Performed allocation for 1 
agents in 1.63964ms
I0718 06:35:50.769804 18271 hierarchical.cpp:1508] Performed allocation for 1 
agents in 196524ns
I0718 06:35:50.770030 18259 master.cpp:10393] Sending offers [ 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O4 ] to framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.770589 18261 sched.cpp:934] Scheduler::resourceOffers took 
75638ns
I0718 06:35:50.780107 18270 http.cpp:1115] HTTP POST for 
/slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.780961 18275 slave.cpp:8406] Handling resource provider message 
'UPDATE_OPERATION_STATUS: (uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c) for 
framework  (latest state: OPERATION_FINISHED, status update state: 
OPERATION_FINISHED)'
I0718 06:35:50.781131 18275 slave.cpp:8859] Updating the state of operation 
with no ID (uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c) for an operation API 
call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:50.781180 18275 slave.cpp:8613] Forwarding status update of 
operation with no ID (operation_uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c) for 
an operator API call
I0718 06:35:50.781606 18275 master.cpp:12232] Updating the state of operation 
'' (uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c) for an operator API call 
(latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:50.782094 18277 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:50.863780 18261 status_update_manager_process.hpp:152] Received 
operation status update OPERATION_FINISHED (Status UUID: 
c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for operation UUID 
ed2820e5-b8f8-4fef-bf2d-cd9862689444 on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.863840 18261 status_update_manager_process.hpp:414] Creating 
operation status update stream ed2820e5-b8f8-4fef-bf2d-cd9862689444 
checkpoint=true
I0718 06:35:50.863894 18264 provider.cpp:481] Received 
ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:50.864187 18261 status_update_manager_process.hpp:929] 
Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status 
UUID: c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for operation UUID 
ed2820e5-b8f8-4fef-bf2d-cd9862689444 on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.930743 18261 status_update_manager_process.hpp:528] Forwarding 
operation status update OPERATION_FINISHED (Status UUID: 
c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for operation UUID 
ed2820e5-b8f8-4fef-bf2d-cd9862689444 on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.931201 18261 status_update_manager_process.hpp:252] Received 
operation status update acknowledgement (UUID: 
20c2d345-e373-497d-a205-0d157a4444f4) for stream 
dacd81f2-2272-4c62-9dfb-906d9e6d751c
I0718 06:35:50.931270 18261 status_update_manager_process.hpp:929] 
Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 
20c2d345-e373-497d-a205-0d157a4444f4) for operation UUID 
dacd81f2-2272-4c62-9dfb-906d9e6d751c on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.931699 18279 http_connection.hpp:131] Sending 2 call to 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.932663 18263 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.972216 18260 http.cpp:1115] HTTP POST for 
/slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.973232 18257 slave.cpp:8406] Handling resource provider message 
'UPDATE_OPERATION_STATUS: (uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444) for 
framework  (latest state: OPERATION_FINISHED, status update state: 
OPERATION_FINISHED)'
I0718 06:35:50.973431 18257 slave.cpp:8859] Updating the state of operation 
with no ID (uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444) for an operation API 
call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:50.973480 18257 slave.cpp:8613] Forwarding status update of 
operation with no ID (operation_uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444) for 
an operator API call
I0718 06:35:50.973817 18265 master.cpp:12232] Updating the state of operation 
'' (uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444) for an operator API call 
(latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:50.974344 18278 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:50.975754 18273 provider.cpp:481] Received 
ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:51.006047 18261 status_update_manager_process.hpp:490] Cleaning up 
operation status update stream dacd81f2-2272-4c62-9dfb-906d9e6d751c
I0718 06:35:51.006266 18261 status_update_manager_process.hpp:252] Received 
operation status update acknowledgement (UUID: 
c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for stream 
ed2820e5-b8f8-4fef-bf2d-cd9862689444
I0718 06:35:51.006338 18261 status_update_manager_process.hpp:929] 
Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 
c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for operation UUID 
ed2820e5-b8f8-4fef-bf2d-cd9862689444 on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.098153 18261 status_update_manager_process.hpp:490] Cleaning up 
operation status update stream ed2820e5-b8f8-4fef-bf2d-cd9862689444
I0718 06:35:51.161433 18275 process.cpp:3671] Handling HTTP event for process 
'master' with path: '/master/api/v1'
I0718 06:35:51.163033 18265 http.cpp:1115] HTTP POST for /master/api/v1 from 
172.17.0.2:52634
I0718 06:35:51.163265 18265 http.cpp:263] Processing call DESTROY_VOLUMES
I0718 06:35:51.164084 18265 master.cpp:3996] Authorizing principal 
'test-principal' to destroy volumes 
'[{"disk":{"persistence":{"id":"6a9a0667-d9f8-4259-96f2-5bbca5a04aa9","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"},"volume":{"container_path":"volume","mode":"RW"}},"name":"disk","provider_id":{"value":"ab871185-944c-426f-96fa-c6831d8cca77"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0718 06:35:51.166194 18274 master.cpp:12685] Removing offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O4
I0718 06:35:51.166357 18264 sched.cpp:960] Rescinded offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O4
I0718 06:35:51.166435 18264 sched.cpp:971] Scheduler::offerRescinded took 
23141ns
I0718 06:35:51.167208 18278 hierarchical.cpp:1218] Recovered disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test),6a9a0667-d9f8-4259-96f2-5bbca5a04aa9:volume]:2048;
 cpus(allocated: storage/default-role):2; mem(allocated: 
storage/default-role):1024; disk(allocated: storage/default-role):1024; 
ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; 
disk:1024; ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test),6a9a0667-d9f8-4259-96f2-5bbca5a04aa9:volume]:2048,
 allocat
 ed: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:51.167332 18278 hierarchical.cpp:1264] Framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:51.170236 18259 master.cpp:12576] Sending operation '' (uuid: 
499f8347-5392-492a-a035-c566bba26aea) to agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:51.170778 18276 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:51.173758 18267 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:51.173802 18267 provider.cpp:1295] Received DESTROY operation '' 
(uuid: 499f8347-5392-492a-a035-c566bba26aea)
I0718 06:35:51.181913 18277 hierarchical.cpp:1508] Performed allocation for 1 
agents in 1.179524ms
I0718 06:35:51.182560 18268 master.cpp:10393] Sending offers [ 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O5 ] to framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.183188 18265 sched.cpp:934] Scheduler::resourceOffers took 
72338ns
I0718 06:35:51.275490 18280 status_update_manager_process.hpp:152] Received 
operation status update OPERATION_FINISHED (Status UUID: 
a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for operation UUID 
499f8347-5392-492a-a035-c566bba26aea on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.275544 18280 status_update_manager_process.hpp:414] Creating 
operation status update stream 499f8347-5392-492a-a035-c566bba26aea 
checkpoint=true
I0718 06:35:51.275964 18280 status_update_manager_process.hpp:929] 
Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status 
UUID: a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for operation UUID 
499f8347-5392-492a-a035-c566bba26aea on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.342371 18280 status_update_manager_process.hpp:528] Forwarding 
operation status update OPERATION_FINISHED (Status UUID: 
a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for operation UUID 
499f8347-5392-492a-a035-c566bba26aea on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.343181 18264 http_connection.hpp:131] Sending 2 call to 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:51.344146 18262 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:51.347077 18279 process.cpp:3671] Handling HTTP event for process 
'master' with path: '/master/api/v1'
I0718 06:35:51.348814 18275 http.cpp:1115] HTTP POST for /master/api/v1 from 
172.17.0.2:52636
I0718 06:35:51.349077 18275 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0718 06:35:51.349648 18275 master.cpp:3888] Authorizing principal 
'test-principal' to unreserve resources 
'[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1","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":"ab871185-944c-426f-96fa-c6831d8cca77"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0718 06:35:51.351526 18272 master.cpp:12685] Removing offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O5
I0718 06:35:51.351651 18268 sched.cpp:960] Rescinded offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O5
I0718 06:35:51.351732 18268 sched.cpp:971] Scheduler::offerRescinded took 
21680ns
I0718 06:35:51.352244 18277 hierarchical.cpp:1218] Recovered disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048;
 cpus(allocated: storage/default-role):2; mem(allocated: 
storage/default-role):1024; disk(allocated: storage/default-role):1024; 
ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; 
disk:1024; ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048,
 allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework 
f44b3929-d9b5-48
 7c-bc8a-9166548ec65c-0000
I0718 06:35:51.352366 18277 hierarchical.cpp:1264] Framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:51.354652 18265 master.cpp:12576] Sending operation '' (uuid: 
06e3fec6-c318-4e9f-8df9-0437b262e2fd) to agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:51.355171 18264 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:51.358350 18266 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:51.358391 18266 provider.cpp:1295] Received UNRESERVE operation '' 
(uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd)
I0718 06:35:51.358405 18259 hierarchical.cpp:1508] Performed allocation for 1 
agents in 1.704417ms
I0718 06:35:51.359061 18270 master.cpp:10393] Sending offers [ 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O6 ] to framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.359689 18258 sched.cpp:934] Scheduler::resourceOffers took 
76087ns
I0718 06:35:51.384219 18265 http.cpp:1115] HTTP POST for 
/slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:51.385090 18274 slave.cpp:8406] Handling resource provider message 
'UPDATE_OPERATION_STATUS: (uuid: 499f8347-5392-492a-a035-c566bba26aea) for 
framework  (latest state: OPERATION_FINISHED, status update state: 
OPERATION_FINISHED)'
I0718 06:35:51.385257 18274 slave.cpp:8859] Updating the state of operation 
with no ID (uuid: 499f8347-5392-492a-a035-c566bba26aea) for an operation API 
call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:51.385306 18274 slave.cpp:8613] Forwarding status update of 
operation with no ID (operation_uuid: 499f8347-5392-492a-a035-c566bba26aea) for 
an operator API call
I0718 06:35:51.385601 18278 master.cpp:12232] Updating the state of operation 
'' (uuid: 499f8347-5392-492a-a035-c566bba26aea) for an operator API call 
(latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:51.386101 18263 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:51.460168 18258 status_update_manager_process.hpp:152] Received 
operation status update OPERATION_FINISHED (Status UUID: 
1df98887-f366-4fb6-b294-9c299319e7fb) for operation UUID 
06e3fec6-c318-4e9f-8df9-0437b262e2fd on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.460234 18258 status_update_manager_process.hpp:414] Creating 
operation status update stream 06e3fec6-c318-4e9f-8df9-0437b262e2fd 
checkpoint=true
I0718 06:35:51.460268 18266 provider.cpp:481] Received 
ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:51.460696 18258 status_update_manager_process.hpp:929] 
Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status 
UUID: 1df98887-f366-4fb6-b294-9c299319e7fb) for operation UUID 
06e3fec6-c318-4e9f-8df9-0437b262e2fd on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.527329 18258 status_update_manager_process.hpp:528] Forwarding 
operation status update OPERATION_FINISHED (Status UUID: 
1df98887-f366-4fb6-b294-9c299319e7fb) for operation UUID 
06e3fec6-c318-4e9f-8df9-0437b262e2fd on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.528153 18258 status_update_manager_process.hpp:252] Received 
operation status update acknowledgement (UUID: 
a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for stream 
499f8347-5392-492a-a035-c566bba26aea
I0718 06:35:51.528301 18258 status_update_manager_process.hpp:929] 
Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 
a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for operation UUID 
499f8347-5392-492a-a035-c566bba26aea on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.528995 18268 http_connection.hpp:131] Sending 2 call to 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:51.530483 18277 process.cpp:3671] Handling HTTP event for process 
'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:51.569037 18278 http.cpp:1115] HTTP POST for 
/slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:51.570623 18271 slave.cpp:8406] Handling resource provider message 
'UPDATE_OPERATION_STATUS: (uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd) for 
framework  (latest state: OPERATION_FINISHED, status update state: 
OPERATION_FINISHED)'
I0718 06:35:51.570964 18271 slave.cpp:8859] Updating the state of operation 
with no ID (uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd) for an operation API 
call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:51.571045 18271 slave.cpp:8613] Forwarding status update of 
operation with no ID (operation_uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd) for 
an operator API call
I0718 06:35:51.571611 18279 master.cpp:12232] Updating the state of operation 
'' (uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd) for an operator API call 
(latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:51.572477 18273 slave.cpp:4335] Ignoring new checkpointed resources 
and operations identical to the current version
I0718 06:35:51.574707 18267 provider.cpp:481] Received 
ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:51.593834 18258 status_update_manager_process.hpp:490] Cleaning up 
operation status update stream 499f8347-5392-492a-a035-c566bba26aea
I0718 06:35:51.594085 18258 status_update_manager_process.hpp:252] Received 
operation status update acknowledgement (UUID: 
1df98887-f366-4fb6-b294-9c299319e7fb) for stream 
06e3fec6-c318-4e9f-8df9-0437b262e2fd
I0718 06:35:51.594157 18258 status_update_manager_process.hpp:929] 
Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 
1df98887-f366-4fb6-b294-9c299319e7fb) for operation UUID 
06e3fec6-c318-4e9f-8df9-0437b262e2fd on agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.677593 18258 status_update_manager_process.hpp:490] Cleaning up 
operation status update stream 06e3fec6-c318-4e9f-8df9-0437b262e2fd
I0718 06:35:51.746021 18280 master.cpp:1410] Framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 disconnected
I0718 06:35:51.746088 18280 master.cpp:3360] Deactivating framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.746747 18278 hierarchical.cpp:475] Deactivated framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:51.747520 18256 slave.cpp:914] Agent terminating
I0718 06:35:51.748178 18280 master.cpp:12685] Removing offer 
f44b3929-d9b5-487c-bc8a-9166548ec65c-O6
I0718 06:35:51.748332 18280 master.cpp:3337] Disconnecting framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.748487 18280 master.cpp:1425] Giving framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 0ns to failover
I0718 06:35:51.748567 18256 manager.cpp:163] Terminating resource provider 
ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:51.749410 18265 master.cpp:10185] Framework failover timeout, 
removing framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.749460 18265 master.cpp:11184] Removing framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at 
scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
E0718 06:35:51.749918 18263 http_connection.hpp:452] End-Of-File received
I0718 06:35:51.749842 18278 hierarchical.cpp:1218] Recovered disk(allocated: 
storage/default-role)(reservations: 
[(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048;
 cpus(allocated: storage/default-role):2; mem(allocated: 
storage/default-role):1024; disk(allocated: storage/default-role):1024; 
ports(allocated: storage/default-role):[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_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048,
 allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:51.749959 18265 master.cpp:1295] Agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334) disconnected
I0718 06:35:51.749989 18265 master.cpp:3397] Disconnecting agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:51.750077 18265 master.cpp:3416] Deactivating agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 
(2dfcf722f334)
I0718 06:35:51.750087 18278 hierarchical.cpp:1432] Allocation paused
I0718 06:35:51.750622 18278 hierarchical.cpp:417] Removed framework 
f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:51.750686 18263 http_connection.hpp:217] Re-detecting endpoint
I0718 06:35:51.750726 18278 hierarchical.cpp:1442] Allocation resumed
I0718 06:35:51.750818 18278 hierarchical.cpp:799] Agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 deactivated
I0718 06:35:51.751314 18263 http_connection.hpp:338] Ignoring disconnection 
attempt from stale connection
I0718 06:35:51.751423 18263 http_connection.hpp:338] Ignoring disconnection 
attempt from stale connection
I0718 06:35:51.751483 18268 provider.cpp:471] Disconnected from resource 
provider manager
I0718 06:35:51.751526 18263 http_connection.hpp:227] New endpoint detected at 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:51.751689 18268 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0718 06:35:51.753279 18269 containerizer.cpp:2575] Destroying container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 in RUNNING state
I0718 06:35:51.753365 18269 containerizer.cpp:3277] 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
I0718 06:35:51.753995 18269 launcher.cpp:161] Asked to destroy container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:51.754637 18260 http_connection.hpp:283] Connected with the remote 
endpoint at http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:51.755327 18268 provider.cpp:459] Connected to resource provider 
manager
I0718 06:35:51.755766 18276 hierarchical.cpp:1508] Performed allocation for 1 
agents in 314032ns
I0718 06:35:51.756248 18257 http_connection.hpp:131] Sending 1 call to 
http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
E0718 06:35:51.757019 18257 provider.cpp:702] Failed to subscribe resource 
provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Cannot 
process 'SUBSCRIBE' call as the driver is in state SUBSCRIBING
I0718 06:35:51.757030 18281 process.cpp:2781] Returning '404 Not Found' for 
'/slave(1217)/api/v1/resource_provider'
E0718 06:35:51.758173 18263 provider.cpp:702] Failed to subscribe resource 
provider with type 'org.apache.mesos.rp.local.storage' and name 'test': 
Received '404 Not Found' ()
I0718 06:35:51.807391 18258 hierarchical.cpp:1508] Performed allocation for 1 
agents in 230887ns
I0718 06:35:51.857656 18264 containerizer.cpp:3116] Container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 has exited
I0718 06:35:51.858829 18271 hierarchical.cpp:1508] Performed allocation for 1 
agents in 171471ns
I0718 06:35:51.859256 18261 provisioner.cpp:611] Ignoring destroy request for 
unknown container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:51.861692 18267 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'
I0718 06:35:51.861867 18267 service_manager.cpp:723] Disconnected from endpoint 
'unix:///tmp/mesos-csi-h4Grme/endpoint.sock' of CSI plugin container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:51.862133 18274 container_daemon.cpp:121] Launching container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:51.864620 18281 process.cpp:2781] Returning '404 Not Found' for 
'/slave(1217)/api/v1'
I0718 06:35:51.882784 18256 master.cpp:1135] Master terminating
I0718 06:35:51.883532 18267 hierarchical.cpp:775] Removed all filters for agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.883556 18267 hierarchical.cpp:650] Removed agent 
f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
[       OK ] 
CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1
 (2413 ms)
[----------] 50 tests from CSIVersion/StorageLocalResourceProviderTest (92617 
ms total)

[----------] Global test environment tear-down
[==========] 2285 tests from 216 test cases ran. (1119127 ms total)
[  PASSED  ] 2284 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] MasterQuotaTest.RescindOffersEnforcingLimits

 1 FAILED TEST
  YOU HAVE 31 DISABLED TESTS

I0718 06:35:52.002019 18281 process.cpp:935] Stopped the socket accept loop
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-1.9.0/_build'
make: *** [distcheck] Error 1
+ docker rmi --force mesos-1563425573-3280
Untagged: mesos-1563425573-3280:latest
Deleted: sha256:546562f5cce8e09b5a716dfd8a4361c45610b3958b40436c8c30276b47e3bf44
Deleted: sha256:c20594c891010db7b3917f9020fbacc60ae0df324de0a9dc2f2eeaaeabaf1bf1
Deleted: sha256:487151d833d3fa6117e464dfd573f4ca1047438f7343a3d14bea1f5d4740e84f
Deleted: sha256:05d02b964096d746847751222973b1ed9aea73d3ccafa844a920f65869eb50a7
Deleted: sha256:d7d39dc3e707cfc993c915b36304366570326da70a316e2dc28d89b81b65a632
Deleted: sha256:be7708a84c1aae092b08d31fb88759de1ba86645903d7f891f4905b6cd0dc0f1
Deleted: sha256:7a982db81134ab3aebeb59fae010e3ec56f7389739634a47147168c45ca1503d
Deleted: sha256:dec3ca3b8b2d5a340ad991d66c5b3102d5e027c3ffe7a1488272179ff3833edb
Deleted: sha256:b0b02e16c0fe1ada7bf5ba34eec77b63cca3eb673e81e51a0a4a8c2512b9f097
Deleted: sha256:f3c5a53b817a96f2c4a90fd400b81875aec38ec812da39c4e8495652713906d7
Deleted: sha256:3547e653b58dae97f05fba274be08646b47804cb15fbcdb5b60ba881d8b57467
Deleted: sha256:2f9ea2b35a050f1cf6f6581bf6518a66d66cfc56a1fda049e31c5ebfc3fe849f
Deleted: sha256:5e90bad7101bde57928d70f92203f8d3e92b8d712d68057fc850ffa292f566a2
Deleted: sha256:f92887612961e8f2cc27f380f2cd956d6e950da4d7f5fb63ccd68d239487c015
Deleted: sha256:52ca4b32e99828cdb63444aea326cbef29826bd2b89b2b7aa0597b23dd66504b
Deleted: sha256:b217b90e0a05ad8ca33196f8ce977223f53f035adabd6b73cc969831b3698b14
Deleted: sha256:6611a7eb38464c1bb8aed2cf32fa411196c213297a3eb2fec39d93615918133a
Deleted: sha256:748e143689a7c8de494296de8289a08d2c0aeb69a9d592cdf93e952214362a1d
Deleted: sha256:a32e211a7b4cd59ee04160a667da96d311235a985eee9db196a123a79db13283
Deleted: sha256:8ba4ea030d64025b8940970894ad1a81ed999362bfdb9ff0684392eadf018e07
Deleted: sha256:dac6718f792dca8df075b14a39fe174d2115dc4537adbde57608bb670b22f0e4
Deleted: sha256:c9904f99f34eeaec632bcfedd7f16a6ce18c3f8662c2c13106e5579bfdf29e5c
Deleted: sha256:6a45bb833a4e4d466155d722d4cae807411a1374c7763ca25fecb7ccb24a9171
Deleted: sha256:541fd8b1a323ee6bd8d5020ae00ac68767dfe732ff188027eba3c0bd7abc4aa5
Deleted: sha256:c0daf28be9a0f7f4a873144d7b27025713684199443d0cba4aba971867557b62
Deleted: sha256:43acd7175d4acbced855dad4851ae64003b81dde13ac9d6f5d3abae77e4bdde7
Deleted: sha256:f5dc98c1630cab32bedb5aa2c3996b776286f56ab0398a4c7a96bf6e52fd305a
Deleted: sha256:c47811592c5d78ac7e4b506097da9e07ca85b424954a04fc18b13ac86eb65072
Deleted: sha256:2409426bf17e9e3e84263c24411fb1f401ecb306d2585ec5d473801e17ea7c12
Deleted: sha256:ae65454464eda51b40b34c0cc0e170c158446675aafd725a4a594c8132c9e452

Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/2613/console

- Mesos Reviewbot


On July 18, 2019, 10 a.m., Meng Zhu wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71111/
> -----------------------------------------------------------
> 
> (Updated July 18, 2019, 10 a.m.)
> 
> 
> Review request for mesos and Benjamin Mahler.
> 
> 
> Bugs: MESOS-9812
>     https://issues.apache.org/jira/browse/MESOS-9812
> 
> 
> Repository: mesos
> 
> 
> Description
> -------
> 
> Outstanding offers need to be rescinded as needed to ensure
> roles' requested guarantees can be satisfied.
> 
> For simplicity, and also due to the race between the master and
> the allocator, we pessimistically assume that what seems like
> "available" resources in the allocator are all gone. We greedily
> rescind offers until we can satisfy the guarantees.
> 
> Also added a test.
> 
> 
> Diffs
> -----
> 
>   src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125 
>   src/tests/master_quota_tests.cpp 64a9b31a38af23fb16a4afd04f6d3413c7d1ffe9 
> 
> 
> Diff: https://reviews.apache.org/r/71111/diff/1/
> 
> 
> Testing
> -------
> 
> make check
> 
> 
> Thanks,
> 
> Meng Zhu
> 
>

Reply via email to