You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@mesos.apache.org by Joseph Wu <jo...@mesosphere.io> on 2019/08/13 02:35:43 UTC
Review Request 71275: Fixed agent draining when returning from
unreachable state.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71275/
-----------------------------------------------------------
Review request for mesos, Benjamin Bannier, Benno Evers, and Greg Mann.
Bugs: MESOS-9934
https://issues.apache.org/jira/browse/MESOS-9934
Repository: mesos
Description
-------
This logic was missing from the initial implementation of agent
draining. When an agent became unreachable, and then reregistered
with the master, the master would not properly deactivate or drain
the agent.
Diffs
-----
src/master/master.cpp 31c7c97abecb92591369b417e2ef38a99cc09bac
src/tests/api_tests.cpp c2099674e742eaa08134c5e0a7cdab1734808119
Diff: https://reviews.apache.org/r/71275/diff/1/
Testing
-------
make check
Thanks,
Joseph Wu
Re: Review Request 71275: Fixed agent draining when returning from
unreachable state.
Posted by Joseph Wu <jo...@mesosphere.io>.
> On Aug. 13, 2019, 4:11 p.m., Greg Mann wrote:
> > src/tests/api_tests.cpp
> > Lines 5953 (patched)
> > <https://reviews.apache.org/r/71275/diff/2/?file=2160733#file2160733line5953>
> >
> > Is this necessary?
Oh, good catch. This line doesn't add anything, since we don't expect any further updates in this sequence.
I shall delete the line.
- Joseph
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71275/#review217187
-----------------------------------------------------------
On Aug. 13, 2019, 2:13 p.m., Joseph Wu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71275/
> -----------------------------------------------------------
>
> (Updated Aug. 13, 2019, 2:13 p.m.)
>
>
> Review request for mesos, Benjamin Bannier, Benno Evers, and Greg Mann.
>
>
> Bugs: MESOS-9934
> https://issues.apache.org/jira/browse/MESOS-9934
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This logic was missing from the initial implementation of agent
> draining. When an agent became unreachable, and then reregistered
> with the master, the master would not properly deactivate or drain
> the agent.
>
> This also fixes a potential problem with checking the agent
> drain state too early in the case of pending operations.
> Operations are not reported to the master until after the agent
> reregisters, so agents with the RESOURCE_PROVIDER capability
> cannot be considered DRAINED until after the first
> UpdateSlaveMessage has arrived.
>
>
> Diffs
> -----
>
> src/master/master.cpp 31c7c97abecb92591369b417e2ef38a99cc09bac
> src/tests/api_tests.cpp c2099674e742eaa08134c5e0a7cdab1734808119
>
>
> Diff: https://reviews.apache.org/r/71275/diff/2/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Joseph Wu
>
>
Re: Review Request 71275: Fixed agent draining when returning from
unreachable state.
Posted by Greg Mann <gr...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71275/#review217187
-----------------------------------------------------------
Fix it, then Ship it!
src/tests/api_tests.cpp
Lines 5953 (patched)
<https://reviews.apache.org/r/71275/#comment304474>
Is this necessary?
- Greg Mann
On Aug. 13, 2019, 9:13 p.m., Joseph Wu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71275/
> -----------------------------------------------------------
>
> (Updated Aug. 13, 2019, 9:13 p.m.)
>
>
> Review request for mesos, Benjamin Bannier, Benno Evers, and Greg Mann.
>
>
> Bugs: MESOS-9934
> https://issues.apache.org/jira/browse/MESOS-9934
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This logic was missing from the initial implementation of agent
> draining. When an agent became unreachable, and then reregistered
> with the master, the master would not properly deactivate or drain
> the agent.
>
> This also fixes a potential problem with checking the agent
> drain state too early in the case of pending operations.
> Operations are not reported to the master until after the agent
> reregisters, so agents with the RESOURCE_PROVIDER capability
> cannot be considered DRAINED until after the first
> UpdateSlaveMessage has arrived.
>
>
> Diffs
> -----
>
> src/master/master.cpp 31c7c97abecb92591369b417e2ef38a99cc09bac
> src/tests/api_tests.cpp c2099674e742eaa08134c5e0a7cdab1734808119
>
>
> Diff: https://reviews.apache.org/r/71275/diff/2/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Joseph Wu
>
>
Re: Review Request 71275: Fixed agent draining when returning from
unreachable state.
Posted by Joseph Wu <jo...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71275/
-----------------------------------------------------------
(Updated Aug. 13, 2019, 2:13 p.m.)
Review request for mesos, Benjamin Bannier, Benno Evers, and Greg Mann.
Changes
-------
Fixed the problem with marking stuff drained too early if operations exist.
Fixed race in unit test.
Bugs: MESOS-9934
https://issues.apache.org/jira/browse/MESOS-9934
Repository: mesos
Description (updated)
-------
This logic was missing from the initial implementation of agent
draining. When an agent became unreachable, and then reregistered
with the master, the master would not properly deactivate or drain
the agent.
This also fixes a potential problem with checking the agent
drain state too early in the case of pending operations.
Operations are not reported to the master until after the agent
reregisters, so agents with the RESOURCE_PROVIDER capability
cannot be considered DRAINED until after the first
UpdateSlaveMessage has arrived.
Diffs (updated)
-----
src/master/master.cpp 31c7c97abecb92591369b417e2ef38a99cc09bac
src/tests/api_tests.cpp c2099674e742eaa08134c5e0a7cdab1734808119
Diff: https://reviews.apache.org/r/71275/diff/2/
Changes: https://reviews.apache.org/r/71275/diff/1-2/
Testing
-------
make check
Thanks,
Joseph Wu
Re: Review Request 71275: Fixed agent draining when returning from
unreachable state.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71275/#review217167
-----------------------------------------------------------
Bad patch!
Reviews applied: [71275]
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_71275"]
Error:
...<truncated>...
ent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.243963 18630 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 670785ed-72f2-4489-8fb7-18158c3e9339) for operation UUID b211a4e0-d0da-458e-acf5-064b21305ef2 on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.244907 18625 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.246160 18636 process.cpp:3671] Handling HTTP event for process 'slave(1222)' with path: '/slave(1222)/api/v1/resource_provider'
I0813 04:34:17.249538 18631 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:17.251186 18634 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57282
I0813 04:34:17.251458 18634 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0813 04:34:17.252104 18634 master.cpp:3888] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd","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":"b814e382-322a-4e6a-b9ec-69384e0b7818"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0813 04:34:17.254338 18647 master.cpp:12706] Removing offer 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-O5
I0813 04:34:17.254495 18637 sched.cpp:960] Rescinded offer 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-O5
I0813 04:34:17.254575 18637 sched.cpp:971] Scheduler::offerRescinded took 23100ns
I0813 04:34:17.255210 18632 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_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd,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_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd,test)]:2048, allocated: {}) on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 from framework 83a2b4de-3aa8-40
cf-a9bf-5c17535ba026-0000
I0813 04:34:17.255329 18632 hierarchical.cpp:1264] Framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 filtered agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 for 5secs
I0813 04:34:17.257719 18628 master.cpp:12597] Sending operation '' (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) to agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 at slave(1222)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.258285 18625 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:17.261219 18631 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:17.261263 18631 provider.cpp:1295] Received UNRESERVE operation '' (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d)
I0813 04:34:17.270252 18633 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.193565ms
I0813 04:34:17.271003 18626 master.cpp:10414] Sending offers [ 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-O6 ] to framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.271628 18634 sched.cpp:934] Scheduler::resourceOffers took 88629ns
I0813 04:34:17.284301 18640 http.cpp:1115] HTTP POST for /slave(1222)/api/v1/resource_provider from 172.17.0.2:57272
I0813 04:34:17.285513 18628 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: b211a4e0-d0da-458e-acf5-064b21305ef2) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:17.285693 18628 slave.cpp:8870] Updating the state of operation with no ID (uuid: b211a4e0-d0da-458e-acf5-064b21305ef2) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:17.285740 18628 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: b211a4e0-d0da-458e-acf5-064b21305ef2) for an operator API call
I0813 04:34:17.286113 18630 master.cpp:12253] Updating the state of operation '' (uuid: b211a4e0-d0da-458e-acf5-064b21305ef2) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:17.286736 18627 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:17.345436 18634 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for operation UUID 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.345499 18634 status_update_manager_process.hpp:414] Creating operation status update stream 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d checkpoint=true
I0813 04:34:17.345533 18631 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:17.345993 18634 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for operation UUID 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.395702 18634 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for operation UUID 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.396023 18634 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 670785ed-72f2-4489-8fb7-18158c3e9339) for stream b211a4e0-d0da-458e-acf5-064b21305ef2
I0813 04:34:17.396098 18634 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 670785ed-72f2-4489-8fb7-18158c3e9339) for operation UUID b211a4e0-d0da-458e-acf5-064b21305ef2 on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.396472 18645 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.397353 18632 process.cpp:3671] Handling HTTP event for process 'slave(1222)' with path: '/slave(1222)/api/v1/resource_provider'
I0813 04:34:17.436173 18643 http.cpp:1115] HTTP POST for /slave(1222)/api/v1/resource_provider from 172.17.0.2:57272
I0813 04:34:17.437034 18627 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:17.437201 18627 slave.cpp:8870] Updating the state of operation with no ID (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:17.437249 18627 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) for an operator API call
I0813 04:34:17.437570 18635 master.cpp:12253] Updating the state of operation '' (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:17.438050 18629 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:17.439328 18637 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:17.462616 18634 status_update_manager_process.hpp:490] Cleaning up operation status update stream b211a4e0-d0da-458e-acf5-064b21305ef2
I0813 04:34:17.462844 18634 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for stream 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d
I0813 04:34:17.462909 18634 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for operation UUID 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.529805 18634 status_update_manager_process.hpp:490] Cleaning up operation status update stream 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d
I0813 04:34:17.598443 18638 master.cpp:1410] Framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253 disconnected
I0813 04:34:17.598490 18638 master.cpp:3360] Deactivating framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.598876 18630 hierarchical.cpp:475] Deactivated framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000
I0813 04:34:17.599515 18638 master.cpp:12706] Removing offer 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-O6
I0813 04:34:17.599597 18638 master.cpp:3337] Disconnecting framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.599653 18638 master.cpp:1425] Giving framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253 0ns to failover
I0813 04:34:17.599969 18639 slave.cpp:924] Agent terminating
I0813 04:34:17.600468 18630 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd,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_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd,test)]:2048, allocated: {}) on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 from framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000
I0813 04:34:17.600837 18639 manager.cpp:163] Terminating resource provider b814e382-322a-4e6a-b9ec-69384e0b7818
I0813 04:34:17.601088 18634 master.cpp:10206] Framework failover timeout, removing framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.601126 18634 master.cpp:11205] Removing framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.601575 18627 hierarchical.cpp:1432] Allocation paused
E0813 04:34:17.601603 18625 http_connection.hpp:452] End-Of-File received
I0813 04:34:17.601725 18634 master.cpp:1295] Agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 at slave(1222)@172.17.0.2:39253 (21cdb951747c) disconnected
I0813 04:34:17.601763 18634 master.cpp:3397] Disconnecting agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 at slave(1222)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.601904 18634 master.cpp:3416] Deactivating agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 at slave(1222)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.602069 18627 hierarchical.cpp:417] Removed framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000
I0813 04:34:17.602169 18627 hierarchical.cpp:1442] Allocation resumed
I0813 04:34:17.602218 18627 hierarchical.cpp:799] Agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 deactivated
I0813 04:34:17.602424 18625 http_connection.hpp:217] Re-detecting endpoint
I0813 04:34:17.602895 18625 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0813 04:34:17.602969 18625 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0813 04:34:17.603003 18631 provider.cpp:471] Disconnected from resource provider manager
I0813 04:34:17.603142 18625 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.603157 18630 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:17.604630 18643 containerizer.cpp:2616] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0813 04:34:17.604670 18643 containerizer.cpp:3318] 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
I0813 04:34:17.605134 18643 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.606487 18634 hierarchical.cpp:1508] Performed allocation for 1 agents in 153345ns
I0813 04:34:17.606748 18629 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.607357 18647 provider.cpp:459] Connected to resource provider manager
I0813 04:34:17.607986 18630 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.608707 18648 process.cpp:2781] Returning '404 Not Found' for '/slave(1222)/api/v1/resource_provider'
E0813 04:34:17.609805 18637 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0813 04:34:17.657891 18641 hierarchical.cpp:1508] Performed allocation for 1 agents in 221037ns
I0813 04:34:17.709182 18646 containerizer.cpp:3157] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0813 04:34:17.709287 18634 hierarchical.cpp:1508] Performed allocation for 1 agents in 120529ns
I0813 04:34:17.711176 18631 provisioner.cpp:612] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.714207 18627 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'
I0813 04:34:17.714516 18638 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-6dA8Ns/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.714792 18634 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:17.718684 18648 process.cpp:2781] Returning '404 Not Found' for '/slave(1222)/api/v1'
I0813 04:34:17.729594 18623 master.cpp:1135] Master terminating
I0813 04:34:17.730307 18633 hierarchical.cpp:775] Removed all filters for agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.730338 18633 hierarchical.cpp:650] Removed agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v0 (2478 ms)
[ RUN ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1
I0813 04:34:17.748692 18623 cluster.cpp:177] Creating default 'local' authorizer
I0813 04:34:17.753526 18636 master.cpp:440] Master f24ab1c4-6a4c-4059-930e-6d4f0fb7294e (21cdb951747c) started on 172.17.0.2:39253
I0813 04:34:17.753553 18636 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/khWP0G/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/khWP0G/master" --zk_session_timeout="10secs"
I0813 04:34:17.753979 18636 master.cpp:492] Master only allowing authenticated frameworks to register
I0813 04:34:17.753995 18636 master.cpp:498] Master only allowing authenticated agents to register
I0813 04:34:17.754004 18636 master.cpp:504] Master only allowing authenticated HTTP frameworks to register
I0813 04:34:17.754014 18636 credentials.hpp:37] Loading credentials for authentication from '/tmp/khWP0G/credentials'
I0813 04:34:17.754364 18636 master.cpp:548] Using default 'crammd5' authenticator
I0813 04:34:17.754592 18636 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0813 04:34:17.754869 18636 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0813 04:34:17.755071 18636 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0813 04:34:17.755246 18636 master.cpp:629] Authorization enabled
I0813 04:34:17.755671 18647 whitelist_watcher.cpp:77] No whitelist given
I0813 04:34:17.755728 18646 hierarchical.cpp:241] Initialized hierarchical allocator process
I0813 04:34:17.758810 18630 master.cpp:2168] Elected as the leading master!
I0813 04:34:17.758848 18630 master.cpp:1664] Recovering from registrar
I0813 04:34:17.759054 18639 registrar.cpp:339] Recovering registrar
I0813 04:34:17.759925 18639 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0813 04:34:17.760076 18639 registrar.cpp:487] Applied 1 operations in 48580ns; attempting to update the registry
I0813 04:34:17.761001 18639 registrar.cpp:544] Successfully updated the registry in 0ns
I0813 04:34:17.761178 18639 registrar.cpp:416] Successfully recovered registrar
I0813 04:34:17.761688 18638 master.cpp:1817] Recovered 0 agents from the registry (143B); allowing 10mins for agents to reregister
I0813 04:34:17.761711 18643 hierarchical.cpp:280] Skipping recovery of hierarchical allocator: nothing to recover
W0813 04:34:17.767647 18623 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:39253
I0813 04:34:17.769137 18623 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0813 04:34:17.769773 18623 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0813 04:34:17.769804 18623 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0813 04:34:17.769955 18623 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0813 04:34:17.769997 18623 provisioner.cpp:300] Using default backend 'copy'
I0813 04:34:17.772680 18623 cluster.cpp:518] Creating default 'local' authorizer
I0813 04:34:17.775111 18626 slave.cpp:267] Mesos agent started on (1223)@172.17.0.2:39253
I0813 04:34:17.775142 18626 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/khWP0G/0gv59i/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/khWP0G/0gv59i/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/khWP0G/0gv59i/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/khWP0G/0gv59i/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/khWP0G/0gv59i/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/khWP0G/0gv59i/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/khWP0G/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_uqx36T" --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_StorageLocalResourcePr
oviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u" --zk_session_timeout="10secs"
I0813 04:34:17.775565 18626 credentials.hpp:86] Loading credential for authentication from '/tmp/khWP0G/0gv59i/credential'
I0813 04:34:17.775749 18626 slave.cpp:300] Agent using credential for: test-principal
I0813 04:34:17.775774 18626 credentials.hpp:37] Loading credentials for authentication from '/tmp/khWP0G/0gv59i/http_credentials'
I0813 04:34:17.775985 18626 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0813 04:34:17.776424 18626 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0813 04:34:17.778231 18626 slave.cpp:615] 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"}]
I0813 04:34:17.778447 18626 slave.cpp:623] Agent attributes: [ ]
I0813 04:34:17.778463 18626 slave.cpp:632] Agent hostname: 21cdb951747c
I0813 04:34:17.778661 18636 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:17.778698 18624 task_status_update_manager.cpp:181] Pausing sending task status updates
I0813 04:34:17.780036 18628 process.cpp:3671] Handling HTTP event for process 'test-disk-profile-server' with path: '/test-disk-profile-server/profiles'
I0813 04:34:17.780474 18640 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u/meta'
I0813 04:34:17.780761 18644 slave.cpp:7444] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u/meta', beginning agent recovery
I0813 04:34:17.781504 18629 task_status_update_manager.cpp:207] Recovering task status update manager
I0813 04:34:17.782061 18647 containerizer.cpp:821] Recovering Mesos containers
I0813 04:34:17.782502 18647 containerizer.cpp:1157] Recovering isolators
I0813 04:34:17.783591 18639 containerizer.cpp:1196] Recovering provisioner
I0813 04:34:17.784366 18632 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0813 04:34:17.784379 18638 provisioner.cpp:500] Provisioner recovery complete
I0813 04:34:17.785223 18641 composing.cpp:339] Finished recovering all containerizers
I0813 04:34:17.785554 18631 slave.cpp:7908] Recovering executors
I0813 04:34:17.785679 18631 slave.cpp:8061] Finished recovery
I0813 04:34:17.786571 18628 task_status_update_manager.cpp:181] Pausing sending task status updates
I0813 04:34:17.786592 18631 slave.cpp:1351] New master detected at master@172.17.0.2:39253
I0813 04:34:17.786628 18645 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:17.786744 18631 slave.cpp:1416] Detecting new master
I0813 04:34:17.788069 18625 slave.cpp:1443] Authenticating with master master@172.17.0.2:39253
I0813 04:34:17.788190 18625 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I0813 04:34:17.788596 18647 authenticatee.cpp:121] Creating new client SASL connection
I0813 04:34:17.788967 18639 master.cpp:10599] Authenticating slave(1223)@172.17.0.2:39253
I0813 04:34:17.789136 18644 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2078)@172.17.0.2:39253
I0813 04:34:17.789467 18643 authenticator.cpp:98] Creating new server SASL connection
I0813 04:34:17.789785 18632 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0813 04:34:17.789826 18632 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0813 04:34:17.790019 18634 authenticator.cpp:204] Received SASL authentication start
I0813 04:34:17.790110 18634 authenticator.cpp:326] Authentication requires more steps
I0813 04:34:17.790261 18638 authenticatee.cpp:259] Received SASL authentication step
I0813 04:34:17.790410 18642 authenticator.cpp:232] Received SASL authentication step
I0813 04:34:17.790452 18642 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '21cdb951747c' server FQDN: '21cdb951747c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0813 04:34:17.790477 18642 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0813 04:34:17.790520 18642 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0813 04:34:17.790552 18642 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '21cdb951747c' server FQDN: '21cdb951747c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0813 04:34:17.790567 18642 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0813 04:34:17.790577 18642 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0813 04:34:17.790593 18642 authenticator.cpp:318] Authentication success
I0813 04:34:17.790745 18629 authenticatee.cpp:299] Authentication success
I0813 04:34:17.790853 18636 master.cpp:10631] Successfully authenticated principal 'test-principal' at slave(1223)@172.17.0.2:39253
I0813 04:34:17.790884 18630 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2078)@172.17.0.2:39253
I0813 04:34:17.791323 18642 slave.cpp:1543] Successfully authenticated with master master@172.17.0.2:39253
I0813 04:34:17.791723 18642 slave.cpp:1993] Will retry registration in 3.382499ms if necessary
I0813 04:34:17.791899 18624 master.cpp:7086] Received register agent message from slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.792188 18624 master.cpp:4202] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
I0813 04:34:17.792904 18631 master.cpp:7153] Authorized registration of agent at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.793010 18631 master.cpp:7265] Registering agent at slave(1223)@172.17.0.2:39253 (21cdb951747c) with id f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:17.793686 18626 registrar.cpp:487] Applied 1 operations in 225083ns; attempting to update the registry
I0813 04:34:17.794433 18626 registrar.cpp:544] Successfully updated the registry in 0ns
I0813 04:34:17.794641 18643 master.cpp:7313] Admitted agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.795509 18643 master.cpp:7358] Registered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0813 04:34:17.795743 18634 slave.cpp:1576] Registered with master master@172.17.0.2:39253; given agent ID f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:17.795738 18638 hierarchical.cpp:617] Added agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 (21cdb951747c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0813 04:34:17.795879 18636 task_status_update_manager.cpp:188] Resuming sending task status updates
I0813 04:34:17.796193 18638 hierarchical.cpp:1508] Performed allocation for 1 agents in 218362ns
I0813 04:34:17.796393 18634 slave.cpp:1611] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u/meta/slaves/f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0/slave.info'
I0813 04:34:17.796461 18633 status_update_manager_process.hpp:385] Resuming operation status update manager
I0813 04:34:17.797752 18634 slave.cpp:1663] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"e3fG3GOvQ1GnR6gd1CbNIA=="},"slave_id":{"value":"f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0"},"update_oversubscribed_resources":false}
I0813 04:34:17.798491 18634 master.cpp:8478] Ignoring update on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c) as it reports no changes
I0813 04:34:17.802696 18644 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1'
I0813 04:34:17.803879 18638 http.cpp:1115] HTTP POST for /slave(1223)/api/v1 from 172.17.0.2:57292
I0813 04:34:17.804428 18638 http.cpp:2146] Processing GET_CONTAINERS call
I0813 04:34:17.810011 18625 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:17.812438 18644 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1'
I0813 04:34:17.813477 18638 http.cpp:1115] HTTP POST for /slave(1223)/api/v1 from 172.17.0.2:57294
I0813 04:34:17.814363 18638 http.cpp:2606] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:17.815304 18638 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:17.816012 18642 containerizer.cpp:1392] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.817294 18642 containerizer.cpp:1570] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_uqx36T/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0813 04:34:17.817338 18642 containerizer.cpp:3318] 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
I0813 04:34:17.820214 18645 containerizer.cpp:2096] 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_6zr205","--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_Aro23u/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-BIGnGV/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperat
ionsWithResourceProviderResources_v1_Aro23u/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="90" --pipe_write="91" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_uqx36T/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0813 04:34:17.829296 18645 launcher.cpp:145] Forked child with pid '32722' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:17.830283 18645 containerizer.cpp:3318] 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
I0813 04:34:17.831810 18645 containerizer.cpp:3318] 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
I0813 04:34:17.832181 18641 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_Aro23u/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.833590 18627 containerizer.cpp:3318] 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
I0813 04:34:17.836459 18624 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'
I0813 04:34:17.836720 18630 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-BIGnGV/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.948248 18636 hierarchical.cpp:1508] Performed allocation for 1 agents in 223770ns
I0813 04:34:17.999405 18646 hierarchical.cpp:1508] Performed allocation for 1 agents in 204141ns
I0813 04:34:18.051379 18631 hierarchical.cpp:1508] Performed allocation for 1 agents in 208377ns
I0813 04:34:18.102716 18639 hierarchical.cpp:1508] Performed allocation for 1 agents in 211120ns
I0813 04:34:18.154326 18633 hierarchical.cpp:1508] Performed allocation for 1 agents in 214549ns
I0813 04:34:18.205924 18628 hierarchical.cpp:1508] Performed allocation for 1 agents in 217216ns
I0813 04:34:18.221554 18640 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-BIGnGV/endpoint.sock' with CSI v1
I0813 04:34:18.238724 32726 test_csi_plugin.cpp:909] ProbeRequest '{}'
I0813 04:34:18.240700 18625 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:18.243366 32726 test_csi_plugin.cpp:895] GetPluginCapabilitiesRequest '{}'
I0813 04:34:18.243993 18629 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1'
I0813 04:34:18.245250 18638 http.cpp:1115] HTTP POST for /slave(1223)/api/v1 from 172.17.0.2:57296
I0813 04:34:18.246078 18638 http.cpp:2824] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:18.247340 32727 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0813 04:34:18.247717 32726 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0813 04:34:18.249001 18626 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0813 04:34:18.250159 18626 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0813 04:34:18.252321 32728 test_csi_plugin.cpp:1105] ControllerGetCapabilitiesRequest '{}'
I0813 04:34:18.255445 32727 test_csi_plugin.cpp:1241] NodeGetCapabilitiesRequest '{}'
I0813 04:34:18.257421 18640 hierarchical.cpp:1508] Performed allocation for 1 agents in 213788ns
I0813 04:34:18.258231 32727 test_csi_plugin.cpp:1255] NodeGetInfoRequest '{}'
I0813 04:34:18.260118 18630 provider.cpp:659] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0813 04:34:18.260254 18639 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:18.260746 18632 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.264117 18641 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.264796 18634 provider.cpp:459] Connected to resource provider manager
I0813 04:34:18.265545 18642 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.266813 18637 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.268532 18630 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57300
I0813 04:34:18.269197 18643 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_6zr205","--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"}
I0813 04:34:18.304049 18641 slave.cpp:8417] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"0e40be87-7324-473f-a67a-3f3738b71e68"},"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_6zr205","--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"}'
I0813 04:34:18.305979 18637 provider.cpp:481] Received SUBSCRIBED event
I0813 04:34:18.306016 18637 provider.cpp:1255] Subscribed with ID 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:18.306955 18639 status_update_manager_process.hpp:314] Recovering operation status update manager
I0813 04:34:18.309096 18630 hierarchical.cpp:1508] Performed allocation for 1 agents in 211322ns
I0813 04:34:18.348292 32727 test_csi_plugin.cpp:1050] ListVolumesRequest '{}'
I0813 04:34:18.350456 18628 provider.cpp:2145] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.350715 18628 provider.cpp:745] Resource provider 0e40be87-7324-473f-a67a-3f3738b71e68 is in READY state
I0813 04:34:18.350785 18634 status_update_manager_process.hpp:385] Resuming operation status update manager
I0813 04:34:18.350818 18627 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.351613 18642 provider.cpp:1181] Updating profiles { test } for resource provider 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:18.352520 18632 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.354053 18628 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:18.354535 18631 manager.cpp:1039] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:18.354792 18645 slave.cpp:8417] Handling resource provider message 'UPDATE_STATE: 0e40be87-7324-473f-a67a-3f3738b71e68 {}'
I0813 04:34:18.354899 18645 slave.cpp:8537] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0813 04:34:18.356658 18647 hierarchical.cpp:753] Grew agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 by {} (total), { } (used)
I0813 04:34:18.357072 18647 hierarchical.cpp:710] Agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 (21cdb951747c) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0813 04:34:18.357012 32728 test_csi_plugin.cpp:1078] GetCapacityRequest '{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
W0813 04:34:18.358176 18623 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:39253
I0813 04:34:18.359503 18623 sched.cpp:239] Version: 1.9.0
I0813 04:34:18.360389 18635 sched.cpp:343] New master detected at master@172.17.0.2:39253
I0813 04:34:18.360538 18635 sched.cpp:408] Authenticating with master master@172.17.0.2:39253
I0813 04:34:18.360563 18635 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0813 04:34:18.360975 18641 authenticatee.cpp:121] Creating new client SASL connection
I0813 04:34:18.361431 18642 master.cpp:10599] Authenticating scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.361483 18636 hierarchical.cpp:1508] Performed allocation for 1 agents in 204392ns
I0813 04:34:18.361532 18631 provider.cpp:933] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to the total resources
I0813 04:34:18.361640 18639 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2079)@172.17.0.2:39253
I0813 04:34:18.361970 18637 authenticator.cpp:98] Creating new server SASL connection
I0813 04:34:18.362267 18630 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0813 04:34:18.362303 18630 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0813 04:34:18.362458 18624 authenticator.cpp:204] Received SASL authentication start
I0813 04:34:18.362537 18624 authenticator.cpp:326] Authentication requires more steps
I0813 04:34:18.362684 18625 authenticatee.cpp:259] Received SASL authentication step
I0813 04:34:18.362877 18645 authenticator.cpp:232] Received SASL authentication step
I0813 04:34:18.362926 18645 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '21cdb951747c' server FQDN: '21cdb951747c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0813 04:34:18.362944 18645 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0813 04:34:18.362998 18645 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0813 04:34:18.363026 18645 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '21cdb951747c' server FQDN: '21cdb951747c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0813 04:34:18.363039 18645 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0813 04:34:18.363049 18645 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0813 04:34:18.363068 18645 authenticator.cpp:318] Authentication success
I0813 04:34:18.363180 18640 authenticatee.cpp:299] Authentication success
I0813 04:34:18.363329 18647 master.cpp:10631] Successfully authenticated principal 'test-principal' at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.363374 18646 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2079)@172.17.0.2:39253
I0813 04:34:18.363592 18632 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:39253
I0813 04:34:18.363624 18632 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:39253
I0813 04:34:18.363804 18632 sched.cpp:870] Will retry registration in 763.266716ms if necessary
I0813 04:34:18.364063 18628 master.cpp:2908] Received SUBSCRIBE call for framework 'default' at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.364104 18628 master.cpp:2240] Authorizing framework principal 'test-principal' to receive offers for roles '{ storage/default-role }'
I0813 04:34:18.364770 18633 master.cpp:2995] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0813 04:34:18.367379 18633 master.cpp:10829] Adding framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 with roles { } suppressed
I0813 04:34:18.367918 18634 sched.cpp:751] Framework registered with f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.367981 18634 sched.cpp:770] Scheduler::registered took 32301ns
I0813 04:34:18.368413 18638 hierarchical.cpp:368] Added framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.369690 18638 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.098467ms
I0813 04:34:18.370221 18639 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O0 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.371130 18639 sched.cpp:934] Scheduler::resourceOffers took 120882ns
I0813 04:34:18.371498 18630 master.cpp:6222] Processing DECLINE call for offers: [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O0 ] for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 with 5 seconds filter
I0813 04:34:18.372113 18630 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O0
I0813 04:34:18.372779 18624 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 f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.372856 18624 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:18.404388 18631 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 f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.404840 18625 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.405937 18643 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.444804 18628 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:18.445397 18635 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":"0e40be87-7324-473f-a67a-3f3738b71e68"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]' and 0 operations from resource provider 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:18.446030 18641 slave.cpp:8417] Handling resource provider message 'UPDATE_STATE: 0e40be87-7324-473f-a67a-3f3738b71e68 disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0813 04:34:18.446211 18641 slave.cpp:8537] 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
I0813 04:34:18.448508 18636 hierarchical.cpp:710] Agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 (21cdb951747c) 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
I0813 04:34:18.449787 18636 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.083167ms
I0813 04:34:18.450403 18638 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O1 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.451004 18637 sched.cpp:934] Scheduler::resourceOffers took 78886ns
I0813 04:34:18.458451 18624 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O1
I0813 04:34:18.458873 18624 master.cpp:4739] Processing ACCEPT call for offers: [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O1 ] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.458974 18624 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'
I0813 04:34:18.459141 18647 hierarchical.cpp:1508] Performed allocation for 1 agents in 391078ns
I0813 04:34:18.460032 18626 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 f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:18.460613 18626 master.cpp:12597] Sending operation '' (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:18.460922 18644 hierarchical.cpp:1432] Allocation paused
I0813 04:34:18.461131 18646 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:18.461973 18644 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 f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.462069 18644 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:18.462307 18644 hierarchical.cpp:1442] Allocation resumed
I0813 04:34:18.463635 18636 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:18.463680 18636 provider.cpp:1295] Received CREATE_DISK operation '' (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1)
I0813 04:34:18.510624 18637 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.510836 18637 hierarchical.cpp:1508] Performed allocation for 1 agents in 723596ns
I0813 04:34:18.514060 18630 v1_volume_manager.cpp:293] Creating volume with name '47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1'
I0813 04:34:18.517231 32728 test_csi_plugin.cpp:922] CreateVolumeRequest '{"name":"47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1","capacityRange":{"requiredBytes":"2147483648","limitBytes":"2147483648"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0813 04:34:18.562494 18643 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.562656 18643 hierarchical.cpp:1508] Performed allocation for 1 agents in 771110ns
I0813 04:34:18.599231 18640 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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048' for operation (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1)
I0813 04:34:18.613935 18626 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.614044 18626 hierarchical.cpp:1508] Performed allocation for 1 agents in 432431ns
I0813 04:34:18.649343 18646 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: c360435f-4183-4365-8d7c-59dc46868af2) for operation UUID 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 of framework 'f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000' on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.649418 18646 status_update_manager_process.hpp:414] Creating operation status update stream 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 checkpoint=true
I0813 04:34:18.649960 18646 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: c360435f-4183-4365-8d7c-59dc46868af2) for operation UUID 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 of framework 'f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000' on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.665710 18628 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.665820 18628 hierarchical.cpp:1508] Performed allocation for 1 agents in 430888ns
I0813 04:34:18.699678 18646 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: c360435f-4183-4365-8d7c-59dc46868af2) for operation UUID 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 of framework 'f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000' on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.700685 18635 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.702090 18642 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.717278 18633 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.717399 18633 hierarchical.cpp:1508] Performed allocation for 1 agents in 514989ns
I0813 04:34:18.740574 18625 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:18.741647 18631 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:18.741855 18631 slave.cpp:8870] Updating the state of operation with no ID (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:18.742300 18631 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.742691 18647 master.cpp:12253] Updating the state of operation '' (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:18.743880 18626 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:18.744619 18643 hierarchical.cpp:956] Updated allocation of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048
I0813 04:34:18.745296 18643 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.745900 18642 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:18.746098 18627 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: c360435f-4183-4365-8d7c-59dc46868af2) for stream 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1
I0813 04:34:18.746178 18627 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: c360435f-4183-4365-8d7c-59dc46868af2) for operation UUID 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 of framework 'f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000' on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.769824 18637 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.207385ms
I0813 04:34:18.770484 18636 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O2 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.771304 18639 sched.cpp:934] Scheduler::resourceOffers took 125286ns
I0813 04:34:18.775043 18645 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:18.777855 18644 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57302
I0813 04:34:18.778266 18644 http.cpp:263] Processing call RESERVE_RESOURCES
I0813 04:34:18.779333 18644 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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048'
I0813 04:34:18.781965 18642 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O2
I0813 04:34:18.782205 18636 sched.cpp:960] Rescinded offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O2
I0813 04:34:18.782299 18636 sched.cpp:971] Scheduler::offerRescinded took 26180ns
I0813 04:34:18.782961 18637 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.783083 18637 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:18.785688 18630 master.cpp:12597] Sending operation '' (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:18.786293 18624 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:18.789042 18645 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:18.789088 18645 provider.cpp:1295] Received RESERVE operation '' (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3)
I0813 04:34:18.791811 18627 status_update_manager_process.hpp:490] Cleaning up operation status update stream 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1
I0813 04:34:18.876521 18644 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for operation UUID 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.876596 18644 status_update_manager_process.hpp:414] Creating operation status update stream 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 checkpoint=true
I0813 04:34:18.877171 18644 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for operation UUID 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.960275 18644 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for operation UUID 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.978217 18643 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.979097 18636 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.982515 18642 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.498403ms
I0813 04:34:18.983301 18637 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O3 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.984042 18639 sched.cpp:934] Scheduler::resourceOffers took 90479ns
I0813 04:34:18.987092 18647 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:18.989111 18646 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57304
I0813 04:34:18.989389 18646 http.cpp:263] Processing call CREATE_VOLUMES
I0813 04:34:18.990239 18646 master.cpp:3951] Authorizing principal 'test-principal' to create volumes '[{"disk":{"persistence":{"id":"0038cadf-7d10-4293-ad12-8c411e2977fe","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1","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":"0e40be87-7324-473f-a67a-3f3738b71e68"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0813 04:34:18.992439 18635 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O3
I0813 04:34:18.992592 18644 sched.cpp:960] Rescinded offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O3
I0813 04:34:18.992686 18644 sched.cpp:971] Scheduler::offerRescinded took 35689ns
I0813 04:34:18.993207 18627 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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-40
59-930e-6d4f0fb7294e-0000
I0813 04:34:18.993324 18627 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:18.996218 18645 master.cpp:12597] Sending operation '' (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:18.996809 18633 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:18.999714 18640 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:18.999758 18640 provider.cpp:1295] Received CREATE operation '' (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62)
I0813 04:34:19.005604 18628 master.cpp:6415] Processing REVIVE call for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:19.006007 18646 hierarchical.cpp:1365] Unsuppressed offers for roles { storage/default-role } of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:19.006036 18646 hierarchical.cpp:1387] Revived roles { storage/default-role } of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:19.007249 18646 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.087091ms
I0813 04:34:19.007642 18646 hierarchical.cpp:1508] Performed allocation for 1 agents in 196434ns
I0813 04:34:19.007895 18634 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O4 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:19.008472 18644 sched.cpp:934] Scheduler::resourceOffers took 77198ns
I0813 04:34:19.016407 18642 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:19.017457 18637 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:19.017637 18637 slave.cpp:8870] Updating the state of operation with no ID (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:19.017685 18637 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) for an operator API call
I0813 04:34:19.018080 18630 master.cpp:12253] Updating the state of operation '' (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:19.018678 18625 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.087033 18644 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for operation UUID a97086da-ebda-4eee-9c47-5d1c93c7ef62 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.087096 18644 status_update_manager_process.hpp:414] Creating operation status update stream a97086da-ebda-4eee-9c47-5d1c93c7ef62 checkpoint=true
I0813 04:34:19.087167 18640 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:19.087543 18644 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for operation UUID a97086da-ebda-4eee-9c47-5d1c93c7ef62 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.137336 18644 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for operation UUID a97086da-ebda-4eee-9c47-5d1c93c7ef62 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.137708 18644 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for stream 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3
I0813 04:34:19.137774 18644 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for operation UUID 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.138382 18627 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:19.139437 18636 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:19.180692 18647 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:19.181620 18631 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:19.181824 18631 slave.cpp:8870] Updating the state of operation with no ID (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:19.181875 18631 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) for an operator API call
I0813 04:34:19.182258 18625 master.cpp:12253] Updating the state of operation '' (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:19.182818 18624 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.184587 18645 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:19.204213 18644 status_update_manager_process.hpp:490] Cleaning up operation status update stream 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3
I0813 04:34:19.204457 18644 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for stream a97086da-ebda-4eee-9c47-5d1c93c7ef62
I0813 04:34:19.204531 18644 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for operation UUID a97086da-ebda-4eee-9c47-5d1c93c7ef62 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.288046 18644 status_update_manager_process.hpp:490] Cleaning up operation status update stream a97086da-ebda-4eee-9c47-5d1c93c7ef62
I0813 04:34:19.351306 18638 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:19.352680 18628 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57306
I0813 04:34:19.352941 18628 http.cpp:263] Processing call DESTROY_VOLUMES
I0813 04:34:19.353834 18628 master.cpp:3996] Authorizing principal 'test-principal' to destroy volumes '[{"disk":{"persistence":{"id":"0038cadf-7d10-4293-ad12-8c411e2977fe","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1","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":"0e40be87-7324-473f-a67a-3f3738b71e68"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0813 04:34:19.356122 18626 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O4
I0813 04:34:19.356324 18646 sched.cpp:960] Rescinded offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O4
I0813 04:34:19.356423 18646 sched.cpp:971] Scheduler::offerRescinded took 31188ns
I0813 04:34:19.357362 18634 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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test),0038cadf-7d10-4293-ad12-8c411e2977fe: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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test),0038cadf-7d10-4293-ad12-8c411e2977fe:volume]:2048, allocat
ed: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:19.357498 18634 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:19.360716 18635 master.cpp:12597] Sending operation '' (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:19.361254 18636 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.364428 18630 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:19.364470 18630 provider.cpp:1295] Received DESTROY operation '' (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29)
I0813 04:34:19.372229 18625 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.348466ms
I0813 04:34:19.372895 18641 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O5 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:19.373582 18628 sched.cpp:934] Scheduler::resourceOffers took 81611ns
I0813 04:34:19.465837 18632 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for operation UUID ea7a307a-fe22-4390-9de4-8211e4d6cd29 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.465900 18632 status_update_manager_process.hpp:414] Creating operation status update stream ea7a307a-fe22-4390-9de4-8211e4d6cd29 checkpoint=true
I0813 04:34:19.466353 18632 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for operation UUID ea7a307a-fe22-4390-9de4-8211e4d6cd29 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.516028 18632 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for operation UUID ea7a307a-fe22-4390-9de4-8211e4d6cd29 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.516904 18646 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:19.517889 18627 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:19.520985 18640 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:19.523831 18637 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57308
I0813 04:34:19.524152 18637 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0813 04:34:19.524909 18637 master.cpp:3888] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1","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":"0e40be87-7324-473f-a67a-3f3738b71e68"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0813 04:34:19.527194 18638 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O5
I0813 04:34:19.527559 18625 sched.cpp:960] Rescinded offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O5
I0813 04:34:19.527642 18625 sched.cpp:971] Scheduler::offerRescinded took 25788ns
I0813 04:34:19.527976 18629 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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-40
59-930e-6d4f0fb7294e-0000
I0813 04:34:19.528108 18629 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:19.530511 18641 master.cpp:12597] Sending operation '' (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:19.531071 18632 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.533725 18640 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:19.533771 18640 provider.cpp:1295] Received UNRESERVE operation '' (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b)
I0813 04:34:19.542205 18631 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.281993ms
I0813 04:34:19.542845 18637 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O6 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:19.543473 18647 sched.cpp:934] Scheduler::resourceOffers took 86871ns
I0813 04:34:19.556469 18624 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:19.557502 18630 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:19.557672 18630 slave.cpp:8870] Updating the state of operation with no ID (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:19.557720 18630 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) for an operator API call
I0813 04:34:19.558008 18632 master.cpp:12253] Updating the state of operation '' (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:19.558583 18627 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.634044 18647 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for operation UUID 832dfe96-bab8-4da6-b7ab-7ffa8f41666b on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.634109 18647 status_update_manager_process.hpp:414] Creating operation status update stream 832dfe96-bab8-4da6-b7ab-7ffa8f41666b checkpoint=true
I0813 04:34:19.634131 18640 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:19.634572 18647 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for operation UUID 832dfe96-bab8-4da6-b7ab-7ffa8f41666b on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.684286 18647 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for operation UUID 832dfe96-bab8-4da6-b7ab-7ffa8f41666b on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.684617 18647 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for stream ea7a307a-fe22-4390-9de4-8211e4d6cd29
I0813 04:34:19.684684 18647 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for operation UUID ea7a307a-fe22-4390-9de4-8211e4d6cd29 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.685215 18625 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:19.686074 18641 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:19.724195 18635 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:19.725098 18627 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:19.725311 18627 slave.cpp:8870] Updating the state of operation with no ID (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:19.725380 18627 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) for an operator API call
I0813 04:34:19.725754 18644 master.cpp:12253] Updating the state of operation '' (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:19.726296 18642 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.727577 18638 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:19.734469 18647 status_update_manager_process.hpp:490] Cleaning up operation status update stream ea7a307a-fe22-4390-9de4-8211e4d6cd29
I0813 04:34:19.734683 18647 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for stream 832dfe96-bab8-4da6-b7ab-7ffa8f41666b
I0813 04:34:19.734748 18647 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for operation UUID 832dfe96-bab8-4da6-b7ab-7ffa8f41666b on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.810040 18647 status_update_manager_process.hpp:490] Cleaning up operation status update stream 832dfe96-bab8-4da6-b7ab-7ffa8f41666b
I0813 04:34:20.253628 18630 master.cpp:1410] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 disconnected
I0813 04:34:20.253667 18630 master.cpp:3360] Deactivating framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:20.254077 18632 hierarchical.cpp:475] Deactivated framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:20.254431 18636 slave.cpp:924] Agent terminating
I0813 04:34:20.255311 18636 manager.cpp:163] Terminating resource provider 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:20.255450 18632 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:20.255693 18630 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O6
I0813 04:34:20.255789 18630 master.cpp:3337] Disconnecting framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:20.255848 18630 master.cpp:1425] Giving framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 0ns to failover
I0813 04:34:20.256047 18630 master.cpp:1295] Agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c) disconnected
I0813 04:34:20.256072 18630 master.cpp:3397] Disconnecting agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:20.256148 18630 master.cpp:3416] Deactivating agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
E0813 04:34:20.256196 18646 http_connection.hpp:452] End-Of-File received
I0813 04:34:20.256253 18635 hierarchical.cpp:799] Agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 deactivated
I0813 04:34:20.256557 18627 master.cpp:10206] Framework failover timeout, removing framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:20.256587 18627 master.cpp:11205] Removing framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:20.256640 18646 http_connection.hpp:217] Re-detecting endpoint
I0813 04:34:20.257026 18639 hierarchical.cpp:1432] Allocation paused
I0813 04:34:20.257095 18646 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0813 04:34:20.257148 18646 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0813 04:34:20.257180 18640 provider.cpp:471] Disconnected from resource provider manager
I0813 04:34:20.257217 18646 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:20.257352 18641 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:20.257491 18639 hierarchical.cpp:417] Removed framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:20.257544 18639 hierarchical.cpp:1442] Allocation resumed
I0813 04:34:20.258575 18624 containerizer.cpp:2616] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0813 04:34:20.258621 18624 containerizer.cpp:3318] 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
I0813 04:34:20.259114 18624 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:20.260483 18643 hierarchical.cpp:1508] Performed allocation for 1 agents in 133988ns
I0813 04:34:20.260932 18644 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:20.261404 18639 provider.cpp:459] Connected to resource provider manager
I0813 04:34:20.261981 18629 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:20.262692 18648 process.cpp:2781] Returning '404 Not Found' for '/slave(1223)/api/v1/resource_provider'
E0813 04:34:20.263932 18626 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0813 04:34:20.311816 18645 hierarchical.cpp:1508] Performed allocation for 1 agents in 193337ns
I0813 04:34:20.363159 18643 hierarchical.cpp:1508] Performed allocation for 1 agents in 117863ns
I0813 04:34:20.363723 18631 containerizer.cpp:3157] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0813 04:34:20.365234 18647 provisioner.cpp:612] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:20.367848 18637 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'
I0813 04:34:20.368058 18630 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-BIGnGV/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:20.368281 18633 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:20.371042 18648 process.cpp:2781] Returning '404 Not Found' for '/slave(1223)/api/v1'
I0813 04:34:20.381745 18623 master.cpp:1135] Master terminating
I0813 04:34:20.382470 18643 hierarchical.cpp:775] Removed all filters for agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:20.382498 18643 hierarchical.cpp:650] Removed agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2647 ms)
[----------] 50 tests from CSIVersion/StorageLocalResourceProviderTest (91038 ms total)
[----------] Global test environment tear-down
[==========] 2299 tests from 218 test cases ran. (1106641 ms total)
[ PASSED ] 2297 tests.
[ FAILED ] 2 tests, listed below:
[ FAILED ] ContentType/MasterAPITest.DrainAgentUnreachable/0, where GetParam() = application/x-protobuf
[ FAILED ] ContentType/MasterAPITest.DrainAgentUnreachable/1, where GetParam() = application/json
2 FAILED TESTS
YOU HAVE 32 DISABLED TESTS
I0813 04:34:20.478269 18648 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-1565665126-12204
Untagged: mesos-1565665126-12204:latest
Deleted: sha256:59a6a63322f9fadc34fcdcff17187ece3d5db6f2ebc62d8afe96d5d84c6353fe
Deleted: sha256:6353e75916fd1aba963515a12c8578c4c2ea581e3486306cf60241e2219a7875
Deleted: sha256:a9f64911d726e01b29d04f3cbc3709e63015a1718e7d5d9e4729f375d22b9560
Deleted: sha256:bf273c548ece74eea01b2bda00a50b6d64903d4cde37bf98140b4c9cd8a1da20
Deleted: sha256:74b9062ddaa2c13b1086512dbe7c8959d4e9a15858ce4ac8c9ef7419ec5b7473
Deleted: sha256:d8510608752cf4bdf7368e8d045a2909749de012e41b78fb076e51200586b629
Deleted: sha256:b856e9ff11316730929234629562bddf52c04735267a99bee0283c9ebfd81e25
Deleted: sha256:86434bc4db7619f8a5826acd284fd831bc269549d257773967b12294ae9e2fb5
Deleted: sha256:f4931af89aa1c6215e3370aa36f58b7b42fda1765b6b86b4180d9af90dcad520
Deleted: sha256:952fba26ca565a954dac3c04f52a4121f0cb96696479a42e1995164081b33000
Deleted: sha256:4a0277a30402ba57ba23f1785897433161d396da47e00e22c2e9eb74a60c72fe
Deleted: sha256:5463ba01857b88a15400288bc37acff6a045b98172957805db0c72ed70c5e3ba
Deleted: sha256:1ae0764e5cb5abf5e5555ee8666cb7f5704448bd0f521c9f6af1025de9798bd1
Deleted: sha256:765c0b5bae8a8b04c490c988bf27f7d362f064af801d906b3e9d280dc6bb2e03
Deleted: sha256:12b8d56703286efcc38016fdb05b25d8df2bb4062b44c2389c577fdfc23011ce
Deleted: sha256:a6c6ccfda2eba5413f9a902eb939e22abf139c4e73319ef56b585f0c791d9bb6
Deleted: sha256:418a13dc5c03fc44bc8f1a2df629abc974027c2db1fa10bcb4fe11b6fd658cd5
Deleted: sha256:96c4ddafb5b2384b443e1384d3d4f8a8a17872b5b68902917e12ee47aeba6ca4
Deleted: sha256:e3487baa8b2e1e86f1fe9480e0cf329e5e2938123a14bd60a6b1ee275322ebb8
Deleted: sha256:c894c0e3864b23198b9c77c166e2e9bc67526ef03e5c8ccd927eecaedd29ce76
Deleted: sha256:1a6d82161096ecd1bf02720268cb1a47bbae59cd7afb16987231755e02eaff9e
Deleted: sha256:7f87f78750c90dfd9615d73a23b50d62fb80d6be4a75df1a0368581d2a52015d
Deleted: sha256:c2e1276856cb4d5c3187700f933157fc165817262108867b905d320d3cb3734c
Deleted: sha256:372cd4896252d735a49467b0ded35f97fd22289e697c5a8cb915d298bf8a71a5
Deleted: sha256:38fd8d3cbb93f70deb02ad10111edf2c3527c79e814041eb1f6805a03210ccc2
Deleted: sha256:194ccf793826c500b3369f77af6da2591b559eb71baa5de9cbac49919b53871e
Deleted: sha256:fe5264f0d14a383f465695af065b906cb644151a8d00c65ea7e364441d497617
Deleted: sha256:770339a42712a6fb2ac175e635abadb0848ab8e317e7a9458055433d90bfb06c
Deleted: sha256:3f835a937e6b4b20cc3aadef5be17f4a264cf5c650bf85b1b39ff3ccfcaf76c2
Deleted: sha256:67bfbe9ecea2b0aac5d1d7acd752fd16c025732d8dd2fc18e46bd1cd0d7dbd90
Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/3125/console
- Mesos Reviewbot
On Aug. 13, 2019, 2:35 a.m., Joseph Wu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71275/
> -----------------------------------------------------------
>
> (Updated Aug. 13, 2019, 2:35 a.m.)
>
>
> Review request for mesos, Benjamin Bannier, Benno Evers, and Greg Mann.
>
>
> Bugs: MESOS-9934
> https://issues.apache.org/jira/browse/MESOS-9934
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This logic was missing from the initial implementation of agent
> draining. When an agent became unreachable, and then reregistered
> with the master, the master would not properly deactivate or drain
> the agent.
>
>
> Diffs
> -----
>
> src/master/master.cpp 31c7c97abecb92591369b417e2ef38a99cc09bac
> src/tests/api_tests.cpp c2099674e742eaa08134c5e0a7cdab1734808119
>
>
> Diff: https://reviews.apache.org/r/71275/diff/1/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Joseph Wu
>
>
Re: Review Request 71275: Fixed agent draining when returning from
unreachable state.
Posted by Greg Mann <gr...@mesosphere.io>.
> On Aug. 13, 2019, 1:10 p.m., Benno Evers wrote:
> > src/master/master.cpp
> > Lines 7959 (patched)
> > <https://reviews.apache.org/r/71275/diff/1/?file=2160640#file2160640line7959>
> >
> > Can we already decide at this point if the agent is drained? E.g. `checkAndTransitionDrainingAgent()` seems to look at pending operations, which only get sent in the first `UpdateSlaveMessage` after the reregistration is completed.
Good catch Benno - this is also an issue with the existing reregistration code in `___reregisterSlave()`. Unfortunately it's even more annoying than waiting for the first `UpdateSlaveMessage`, since it's possible that resource providers may subscribe with the agent later on. Not yet sure what the best way to handle this is.
- Greg
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71275/#review217177
-----------------------------------------------------------
On Aug. 13, 2019, 2:35 a.m., Joseph Wu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71275/
> -----------------------------------------------------------
>
> (Updated Aug. 13, 2019, 2:35 a.m.)
>
>
> Review request for mesos, Benjamin Bannier, Benno Evers, and Greg Mann.
>
>
> Bugs: MESOS-9934
> https://issues.apache.org/jira/browse/MESOS-9934
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This logic was missing from the initial implementation of agent
> draining. When an agent became unreachable, and then reregistered
> with the master, the master would not properly deactivate or drain
> the agent.
>
>
> Diffs
> -----
>
> src/master/master.cpp 31c7c97abecb92591369b417e2ef38a99cc09bac
> src/tests/api_tests.cpp c2099674e742eaa08134c5e0a7cdab1734808119
>
>
> Diff: https://reviews.apache.org/r/71275/diff/1/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Joseph Wu
>
>
Re: Review Request 71275: Fixed agent draining when returning from
unreachable state.
Posted by Benno Evers <be...@mesosphere.com>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71275/#review217177
-----------------------------------------------------------
src/master/master.cpp
Lines 7959 (patched)
<https://reviews.apache.org/r/71275/#comment304448>
Can we already decide at this point if the agent is drained? E.g. `checkAndTransitionDrainingAgent()` seems to look at pending operations, which only get sent in the first `UpdateSlaveMessage` after the reregistration is completed.
- Benno Evers
On Aug. 13, 2019, 2:35 a.m., Joseph Wu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71275/
> -----------------------------------------------------------
>
> (Updated Aug. 13, 2019, 2:35 a.m.)
>
>
> Review request for mesos, Benjamin Bannier, Benno Evers, and Greg Mann.
>
>
> Bugs: MESOS-9934
> https://issues.apache.org/jira/browse/MESOS-9934
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This logic was missing from the initial implementation of agent
> draining. When an agent became unreachable, and then reregistered
> with the master, the master would not properly deactivate or drain
> the agent.
>
>
> Diffs
> -----
>
> src/master/master.cpp 31c7c97abecb92591369b417e2ef38a99cc09bac
> src/tests/api_tests.cpp c2099674e742eaa08134c5e0a7cdab1734808119
>
>
> Diff: https://reviews.apache.org/r/71275/diff/1/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Joseph Wu
>
>