You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@mesos.apache.org by Benjamin Bannier <bb...@apache.org> on 2019/06/26 23:55:12 UTC
Review Request 70960: Added test for agent to leave draining state on
its own.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/
-----------------------------------------------------------
Review request for mesos, Greg Mann and Joseph Wu.
Bugs: MESOS-9860
https://issues.apache.org/jira/browse/MESOS-9860
Repository: mesos
Description
-------
This patch adds a test which confirms that the agent leaves a draining
state on its own once all frameworks on the agent have no more pending
tasks and all their executors have neither launched or queued tasks.
The test uses the fact that the agent rejects task launches while
draining.
Diffs
-----
src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
Diff: https://reviews.apache.org/r/70960/diff/1/
Testing
-------
`make check`
Thanks,
Benjamin Bannier
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Benjamin Bannier <bb...@apache.org>.
> On June 28, 2019, 6:05 a.m., Greg Mann wrote:
> > src/tests/slave_tests.cpp
> > Lines 12365-12366 (patched)
> > <https://reviews.apache.org/r/70960/diff/3/?file=2152674#file2152674line12365>
> >
> > Nit: indentation.
I was using an incorrect `clang-format` (upstream instead of our patched version). I have reformatted all changes in this chain.
- Benjamin
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/#review216219
-----------------------------------------------------------
On June 28, 2019, 11:27 a.m., Benjamin Bannier wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/70960/
> -----------------------------------------------------------
>
> (Updated June 28, 2019, 11:27 a.m.)
>
>
> Review request for mesos, Greg Mann and Joseph Wu.
>
>
> Bugs: MESOS-9860
> https://issues.apache.org/jira/browse/MESOS-9860
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds a test which confirms that the agent leaves a draining
> state on its own once all frameworks on the agent have no more pending
> tasks and all their executors have neither launched or queued tasks.
>
> The test uses the fact that the agent rejects task launches while
> draining.
>
>
> Diffs
> -----
>
> src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
>
>
> Diff: https://reviews.apache.org/r/70960/diff/4/
>
>
> Testing
> -------
>
> `make check`
>
>
> Thanks,
>
> Benjamin Bannier
>
>
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Greg Mann <gr...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/#review216219
-----------------------------------------------------------
Fix it, then Ship it!
src/tests/slave_tests.cpp
Lines 12365-12366 (patched)
<https://reviews.apache.org/r/70960/#comment303328>
Nit: indentation.
src/tests/slave_tests.cpp
Lines 12371-12372 (patched)
<https://reviews.apache.org/r/70960/#comment303329>
Nit: indentation.
- Greg Mann
On June 27, 2019, 11:11 p.m., Benjamin Bannier wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/70960/
> -----------------------------------------------------------
>
> (Updated June 27, 2019, 11:11 p.m.)
>
>
> Review request for mesos, Greg Mann and Joseph Wu.
>
>
> Bugs: MESOS-9860
> https://issues.apache.org/jira/browse/MESOS-9860
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds a test which confirms that the agent leaves a draining
> state on its own once all frameworks on the agent have no more pending
> tasks and all their executors have neither launched or queued tasks.
>
> The test uses the fact that the agent rejects task launches while
> draining.
>
>
> Diffs
> -----
>
> src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
>
>
> Diff: https://reviews.apache.org/r/70960/diff/3/
>
>
> Testing
> -------
>
> `make check`
>
>
> Thanks,
>
> Benjamin Bannier
>
>
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/#review216500
-----------------------------------------------------------
Bad patch!
Reviews applied: [70822, 70839, 70834, 70835, 70836, 70899, 70900, 70901, 70903, 70904, 70906, 70907, 70936, 70958, 70959, 70960]
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_70960"]
Error:
...<truncated>...
rOperationsWithResourceProviderResources_v0_lv1KXi/2GB-c6b345fa-5b35-4878-837b-5a4c59d9b4dc,test)]:2048, allocated: {}) on agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0 from framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000
I0710 20:50:55.278487 18285 hierarchical.cpp:1264] Framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000 filtered agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0 for 5secs
I0710 20:50:55.280719 18280 master.cpp:12361] Sending operation '' (uuid: 6a3648f1-7d50-402f-bf46-da66c8c4b071) to agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0 at slave(1206)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:55.281229 18269 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:55.283566 18264 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.090114ms
I0710 20:50:55.283691 18279 provider.cpp:481] Received APPLY_OPERATION event
I0710 20:50:55.283728 18279 provider.cpp:1295] Received UNRESERVE operation '' (uuid: 6a3648f1-7d50-402f-bf46-da66c8c4b071)
I0710 20:50:55.284237 18276 master.cpp:10195] Sending offers [ 42f89090-73ba-4432-bc19-4b81bc70b0d4-O6 ] to framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000 (default) at scheduler-50e8ad20-f69c-4a0e-8a57-a8c43544c191@172.17.0.2:35051
I0710 20:50:55.284814 18277 sched.cpp:934] Scheduler::resourceOffers took 74991ns
I0710 20:50:55.307996 18275 http.cpp:1115] HTTP POST for /slave(1206)/api/v1/resource_provider from 172.17.0.2:47190
I0710 20:50:55.308835 18263 slave.cpp:8395] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: e5a4c8b5-da58-4673-a11e-439cd71c02fc) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 20:50:55.308989 18263 slave.cpp:8848] Updating the state of operation with no ID (uuid: e5a4c8b5-da58-4673-a11e-439cd71c02fc) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 20:50:55.309039 18263 slave.cpp:8602] Forwarding status update of operation with no ID (operation_uuid: e5a4c8b5-da58-4673-a11e-439cd71c02fc) for an operator API call
I0710 20:50:55.309415 18269 master.cpp:12017] Updating the state of operation '' (uuid: e5a4c8b5-da58-4673-a11e-439cd71c02fc) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 20:50:55.310154 18269 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:55.535017 18277 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: c58d4b22-ac3c-42a5-9e5a-ffc0cb9993eb) for operation UUID 6a3648f1-7d50-402f-bf46-da66c8c4b071 on agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0
I0710 20:50:55.535095 18277 status_update_manager_process.hpp:414] Creating operation status update stream 6a3648f1-7d50-402f-bf46-da66c8c4b071 checkpoint=true
I0710 20:50:55.535154 18279 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 20:50:55.535501 18277 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: c58d4b22-ac3c-42a5-9e5a-ffc0cb9993eb) for operation UUID 6a3648f1-7d50-402f-bf46-da66c8c4b071 on agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0
I0710 20:50:55.676519 18277 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: c58d4b22-ac3c-42a5-9e5a-ffc0cb9993eb) for operation UUID 6a3648f1-7d50-402f-bf46-da66c8c4b071 on agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0
I0710 20:50:55.676914 18277 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 25653fcb-24c7-4814-b338-e6173b9b0136) for stream e5a4c8b5-da58-4673-a11e-439cd71c02fc
I0710 20:50:55.676985 18277 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 25653fcb-24c7-4814-b338-e6173b9b0136) for operation UUID e5a4c8b5-da58-4673-a11e-439cd71c02fc on agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0
I0710 20:50:55.677397 18266 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:35051/slave(1206)/api/v1/resource_provider
I0710 20:50:55.678514 18280 process.cpp:3671] Handling HTTP event for process 'slave(1206)' with path: '/slave(1206)/api/v1/resource_provider'
I0710 20:50:55.716593 18283 http.cpp:1115] HTTP POST for /slave(1206)/api/v1/resource_provider from 172.17.0.2:47190
I0710 20:50:55.717583 18265 slave.cpp:8395] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 6a3648f1-7d50-402f-bf46-da66c8c4b071) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 20:50:55.717810 18265 slave.cpp:8848] Updating the state of operation with no ID (uuid: 6a3648f1-7d50-402f-bf46-da66c8c4b071) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 20:50:55.717859 18265 slave.cpp:8602] Forwarding status update of operation with no ID (operation_uuid: 6a3648f1-7d50-402f-bf46-da66c8c4b071) for an operator API call
I0710 20:50:55.718227 18274 master.cpp:12017] Updating the state of operation '' (uuid: 6a3648f1-7d50-402f-bf46-da66c8c4b071) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 20:50:55.718842 18282 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:55.720202 18272 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 20:50:55.793180 18277 status_update_manager_process.hpp:490] Cleaning up operation status update stream e5a4c8b5-da58-4673-a11e-439cd71c02fc
I0710 20:50:55.793509 18277 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: c58d4b22-ac3c-42a5-9e5a-ffc0cb9993eb) for stream 6a3648f1-7d50-402f-bf46-da66c8c4b071
I0710 20:50:55.793597 18277 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: c58d4b22-ac3c-42a5-9e5a-ffc0cb9993eb) for operation UUID 6a3648f1-7d50-402f-bf46-da66c8c4b071 on agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0
I0710 20:50:55.943130 18277 status_update_manager_process.hpp:490] Cleaning up operation status update stream 6a3648f1-7d50-402f-bf46-da66c8c4b071
I0710 20:50:56.085870 18263 master.cpp:1410] Framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000 (default) at scheduler-50e8ad20-f69c-4a0e-8a57-a8c43544c191@172.17.0.2:35051 disconnected
I0710 20:50:56.085943 18263 master.cpp:3342] Deactivating framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000 (default) at scheduler-50e8ad20-f69c-4a0e-8a57-a8c43544c191@172.17.0.2:35051
I0710 20:50:56.086359 18268 hierarchical.cpp:475] Deactivated framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000
I0710 20:50:56.086840 18261 slave.cpp:914] Agent terminating
I0710 20:50:56.086931 18263 master.cpp:12470] Removing offer 42f89090-73ba-4432-bc19-4b81bc70b0d4-O6
I0710 20:50:56.087013 18263 master.cpp:3319] Disconnecting framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000 (default) at scheduler-50e8ad20-f69c-4a0e-8a57-a8c43544c191@172.17.0.2:35051
I0710 20:50:56.087069 18263 master.cpp:1425] Giving framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000 (default) at scheduler-50e8ad20-f69c-4a0e-8a57-a8c43544c191@172.17.0.2:35051 0ns to failover
I0710 20:50:56.087582 18261 manager.cpp:163] Terminating resource provider 964f40b7-8b00-4a87-9b7e-4bb7695ba96f
I0710 20:50:56.087683 18268 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_lv1KXi/2GB-c6b345fa-5b35-4878-837b-5a4c59d9b4dc,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_lv1KXi/2GB-c6b345fa-5b35-4878-837b-5a4c59d9b4dc,test)]:2048, allocated: {}) on agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0 from framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000
I0710 20:50:56.087990 18284 master.cpp:1295] Agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0 at slave(1206)@172.17.0.2:35051 (f57a0dc1c520) disconnected
I0710 20:50:56.088017 18284 master.cpp:3379] Disconnecting agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0 at slave(1206)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:56.088088 18284 master.cpp:3398] Deactivating agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0 at slave(1206)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:56.088199 18281 hierarchical.cpp:799] Agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0 deactivated
I0710 20:50:56.088286 18284 master.cpp:9987] Framework failover timeout, removing framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000 (default) at scheduler-50e8ad20-f69c-4a0e-8a57-a8c43544c191@172.17.0.2:35051
I0710 20:50:56.088315 18284 master.cpp:10979] Removing framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000 (default) at scheduler-50e8ad20-f69c-4a0e-8a57-a8c43544c191@172.17.0.2:35051
E0710 20:50:56.088641 18262 http_connection.hpp:452] End-Of-File received
I0710 20:50:56.088687 18271 hierarchical.cpp:1432] Allocation paused
I0710 20:50:56.089040 18271 hierarchical.cpp:417] Removed framework 42f89090-73ba-4432-bc19-4b81bc70b0d4-0000
I0710 20:50:56.089045 18262 http_connection.hpp:217] Re-detecting endpoint
I0710 20:50:56.089092 18271 hierarchical.cpp:1442] Allocation resumed
I0710 20:50:56.089491 18262 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0710 20:50:56.089542 18262 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0710 20:50:56.089587 18272 provider.cpp:471] Disconnected from resource provider manager
I0710 20:50:56.089614 18262 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35051/slave(1206)/api/v1/resource_provider
I0710 20:50:56.089720 18275 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 20:50:56.090915 18283 containerizer.cpp:2575] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0710 20:50:56.090950 18283 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING
I0710 20:50:56.091313 18283 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 20:50:56.092586 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 189218ns
I0710 20:50:56.092767 18273 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35051/slave(1206)/api/v1/resource_provider
I0710 20:50:56.093230 18272 provider.cpp:459] Connected to resource provider manager
I0710 20:50:56.093766 18275 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:35051/slave(1206)/api/v1/resource_provider
I0710 20:50:56.094405 18286 process.cpp:2781] Returning '404 Not Found' for '/slave(1206)/api/v1/resource_provider'
E0710 20:50:56.095435 18262 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0710 20:50:56.144166 18284 hierarchical.cpp:1508] Performed allocation for 1 agents in 144715ns
I0710 20:50:56.194214 18265 containerizer.cpp:3116] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0710 20:50:56.195478 18266 provisioner.cpp:609] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 20:50:56.195859 18263 hierarchical.cpp:1508] Performed allocation for 1 agents in 164919ns
I0710 20:50:56.197788 18278 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'
I0710 20:50:56.197957 18284 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-awZbph/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 20:50:56.198179 18277 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 20:50:56.200906 18286 process.cpp:2781] Returning '404 Not Found' for '/slave(1206)/api/v1'
I0710 20:50:56.209467 18261 master.cpp:1135] Master terminating
I0710 20:50:56.210031 18276 hierarchical.cpp:775] Removed all filters for agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0
I0710 20:50:56.210057 18276 hierarchical.cpp:650] Removed agent 42f89090-73ba-4432-bc19-4b81bc70b0d4-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v0 (4245 ms)
[ RUN ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1
I0710 20:50:56.223038 18261 cluster.cpp:176] Creating default 'local' authorizer
I0710 20:50:56.227464 18277 master.cpp:440] Master 65248d47-75df-4772-b399-2edfaf9fa351 (f57a0dc1c520) started on 172.17.0.2:35051
I0710 20:50:56.227491 18277 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/S3XoIi/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/S3XoIi/master" --zk_session_timeout="10secs"
I0710 20:50:56.227905 18277 master.cpp:492] Master only allowing authenticated frameworks to register
I0710 20:50:56.227921 18277 master.cpp:498] Master only allowing authenticated agents to register
I0710 20:50:56.227939 18277 master.cpp:504] Master only allowing authenticated HTTP frameworks to register
I0710 20:50:56.227952 18277 credentials.hpp:37] Loading credentials for authentication from '/tmp/S3XoIi/credentials'
I0710 20:50:56.228255 18277 master.cpp:548] Using default 'crammd5' authenticator
I0710 20:50:56.228449 18277 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0710 20:50:56.228685 18277 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0710 20:50:56.228853 18277 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0710 20:50:56.229017 18277 master.cpp:629] Authorization enabled
I0710 20:50:56.229398 18269 hierarchical.cpp:241] Initialized hierarchical allocator process
I0710 20:50:56.229403 18266 whitelist_watcher.cpp:77] No whitelist given
I0710 20:50:56.232514 18275 master.cpp:2150] Elected as the leading master!
I0710 20:50:56.232553 18275 master.cpp:1664] Recovering from registrar
I0710 20:50:56.232733 18273 registrar.cpp:339] Recovering registrar
I0710 20:50:56.233469 18273 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0710 20:50:56.233618 18273 registrar.cpp:487] Applied 1 operations in 48804ns; attempting to update the registry
I0710 20:50:56.234289 18273 registrar.cpp:544] Successfully updated the registry in 0ns
I0710 20:50:56.234437 18273 registrar.cpp:416] Successfully recovered registrar
I0710 20:50:56.234932 18283 hierarchical.cpp:280] Skipping recovery of hierarchical allocator: nothing to recover
I0710 20:50:56.234938 18270 master.cpp:1799] Recovered 0 agents from the registry (143B); allowing 10mins for agents to reregister
W0710 20:50:56.240447 18261 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:35051
I0710 20:50:56.241603 18261 containerizer.cpp:314] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0710 20:50:56.242110 18261 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0710 20:50:56.242274 18261 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0710 20:50:56.242310 18261 provisioner.cpp:298] Using default backend 'copy'
I0710 20:50:56.244531 18261 cluster.cpp:510] Creating default 'local' authorizer
I0710 20:50:56.247314 18264 slave.cpp:265] Mesos agent started on (1207)@172.17.0.2:35051
I0710 20:50:56.247340 18264 slave.cpp:266] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/S3XoIi/9DP5eM/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/S3XoIi/9DP5eM/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/S3XoIi/9DP5eM/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/S3XoIi/9DP5eM/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/S3XoIi/9DP5eM/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/S3XoIi/9DP5eM/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/S3XoIi/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_MoeMlU" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsW
ithResourceProviderResources_v1_a26ss2" --zk_session_timeout="10secs"
I0710 20:50:56.247731 18264 credentials.hpp:86] Loading credential for authentication from '/tmp/S3XoIi/9DP5eM/credential'
I0710 20:50:56.247896 18264 slave.cpp:298] Agent using credential for: test-principal
I0710 20:50:56.247917 18264 credentials.hpp:37] Loading credentials for authentication from '/tmp/S3XoIi/9DP5eM/http_credentials'
I0710 20:50:56.248109 18264 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0710 20:50:56.248463 18264 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0710 20:50:56.249984 18264 slave.cpp:613] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0710 20:50:56.250169 18264 slave.cpp:621] Agent attributes: [ ]
I0710 20:50:56.250181 18264 slave.cpp:630] Agent hostname: f57a0dc1c520
I0710 20:50:56.250365 18277 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 20:50:56.250387 18276 task_status_update_manager.cpp:181] Pausing sending task status updates
I0710 20:50:56.251089 18275 process.cpp:3671] Handling HTTP event for process 'test-disk-profile-server' with path: '/test-disk-profile-server/profiles'
I0710 20:50:56.251828 18267 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_a26ss2/meta'
I0710 20:50:56.252090 18271 slave.cpp:7422] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_a26ss2/meta', beginning agent recovery
I0710 20:50:56.252727 18283 task_status_update_manager.cpp:207] Recovering task status update manager
I0710 20:50:56.253175 18266 containerizer.cpp:796] Recovering Mesos containers
I0710 20:50:56.253464 18266 containerizer.cpp:1122] Recovering isolators
I0710 20:50:56.254214 18267 containerizer.cpp:1161] Recovering provisioner
I0710 20:50:56.254875 18273 provisioner.cpp:498] Provisioner recovery complete
I0710 20:50:56.254881 18272 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0710 20:50:56.255565 18276 composing.cpp:339] Finished recovering all containerizers
I0710 20:50:56.255833 18278 slave.cpp:7886] Recovering executors
I0710 20:50:56.255937 18278 slave.cpp:8039] Finished recovery
I0710 20:50:56.256711 18262 task_status_update_manager.cpp:181] Pausing sending task status updates
I0710 20:50:56.256734 18266 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 20:50:56.256742 18279 slave.cpp:1333] New master detected at master@172.17.0.2:35051
I0710 20:50:56.256862 18279 slave.cpp:1398] Detecting new master
I0710 20:50:56.258103 18275 slave.cpp:1425] Authenticating with master master@172.17.0.2:35051
I0710 20:50:56.258198 18275 slave.cpp:1434] Using default CRAM-MD5 authenticatee
I0710 20:50:56.258508 18280 authenticatee.cpp:121] Creating new client SASL connection
I0710 20:50:56.258858 18267 master.cpp:10380] Authenticating slave(1207)@172.17.0.2:35051
I0710 20:50:56.259011 18264 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2057)@172.17.0.2:35051
I0710 20:50:56.259268 18272 authenticator.cpp:98] Creating new server SASL connection
I0710 20:50:56.259510 18270 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0710 20:50:56.259536 18270 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0710 20:50:56.259660 18273 authenticator.cpp:204] Received SASL authentication start
I0710 20:50:56.259732 18273 authenticator.cpp:326] Authentication requires more steps
I0710 20:50:56.259865 18274 authenticatee.cpp:259] Received SASL authentication step
I0710 20:50:56.260010 18271 authenticator.cpp:232] Received SASL authentication step
I0710 20:50:56.260046 18271 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f57a0dc1c520' server FQDN: 'f57a0dc1c520' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0710 20:50:56.260059 18271 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0710 20:50:56.260099 18271 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0710 20:50:56.260120 18271 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f57a0dc1c520' server FQDN: 'f57a0dc1c520' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0710 20:50:56.260133 18271 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0710 20:50:56.260143 18271 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0710 20:50:56.260159 18271 authenticator.cpp:318] Authentication success
I0710 20:50:56.260255 18269 authenticatee.cpp:299] Authentication success
I0710 20:50:56.260366 18282 master.cpp:10412] Successfully authenticated principal 'test-principal' at slave(1207)@172.17.0.2:35051
I0710 20:50:56.260428 18265 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2057)@172.17.0.2:35051
I0710 20:50:56.260689 18283 slave.cpp:1525] Successfully authenticated with master master@172.17.0.2:35051
I0710 20:50:56.261056 18283 slave.cpp:1975] Will retry registration in 9.277086ms if necessary
I0710 20:50:56.261242 18285 master.cpp:6900] Received register agent message from slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:56.261520 18285 master.cpp:4099] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
I0710 20:50:56.262298 18279 master.cpp:6967] Authorized registration of agent at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:56.262384 18279 master.cpp:7082] Registering agent at slave(1207)@172.17.0.2:35051 (f57a0dc1c520) with id 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:56.262979 18281 registrar.cpp:487] Applied 1 operations in 176062ns; attempting to update the registry
I0710 20:50:56.263628 18281 registrar.cpp:544] Successfully updated the registry in 0ns
I0710 20:50:56.263788 18272 master.cpp:7130] Admitted agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:56.264437 18272 master.cpp:7175] Registered agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0710 20:50:56.264559 18274 hierarchical.cpp:617] Added agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 (f57a0dc1c520) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0710 20:50:56.264595 18270 slave.cpp:1558] Registered with master master@172.17.0.2:35051; given agent ID 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:56.264742 18282 task_status_update_manager.cpp:188] Resuming sending task status updates
I0710 20:50:56.264874 18274 hierarchical.cpp:1508] Performed allocation for 1 agents in 126929ns
I0710 20:50:56.265063 18270 slave.cpp:1593] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_a26ss2/meta/slaves/65248d47-75df-4772-b399-2edfaf9fa351-S0/slave.info'
I0710 20:50:56.265121 18263 status_update_manager_process.hpp:385] Resuming operation status update manager
I0710 20:50:56.266147 18270 slave.cpp:1645] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"1X5HCOplQVCUVhR8VSxSqQ=="},"slave_id":{"value":"65248d47-75df-4772-b399-2edfaf9fa351-S0"},"update_oversubscribed_resources":false}
I0710 20:50:56.266892 18283 master.cpp:8261] Ignoring update on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520) as it reports no changes
I0710 20:50:56.271023 18273 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1'
I0710 20:50:56.272044 18284 http.cpp:1115] HTTP POST for /slave(1207)/api/v1 from 172.17.0.2:47210
I0710 20:50:56.272498 18284 http.cpp:2131] Processing GET_CONTAINERS call
I0710 20:50:56.277418 18281 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 20:50:56.279500 18273 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1'
I0710 20:50:56.280278 18284 http.cpp:1115] HTTP POST for /slave(1207)/api/v1 from 172.17.0.2:47212
I0710 20:50:56.280999 18284 http.cpp:2497] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 20:50:56.281697 18276 http.cpp:2601] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_a26ss2/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 20:50:56.282256 18285 containerizer.cpp:1357] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 20:50:56.283278 18285 containerizer.cpp:1529] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_MoeMlU/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0710 20:50:56.283315 18285 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING
I0710 20:50:56.285907 18280 containerizer.cpp:2055] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_YGpbza","--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_a26ss2/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-iu4P5f/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperat
ionsWithResourceProviderResources_v1_a26ss2/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="87" --pipe_write="88" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_MoeMlU/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0710 20:50:56.293263 18280 launcher.cpp:145] Forked child with pid '32145' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 20:50:56.293972 18280 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING
I0710 20:50:56.295344 18280 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING
I0710 20:50:56.295732 18282 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_a26ss2/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 20:50:56.297245 18273 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING
I0710 20:50:56.299974 18283 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'
I0710 20:50:56.300228 18262 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-iu4P5f/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 20:50:56.666755 18277 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-iu4P5f/endpoint.sock' with CSI v1
I0710 20:50:56.667317 18267 hierarchical.cpp:1508] Performed allocation for 1 agents in 220931ns
I0710 20:50:56.681488 32149 test_csi_plugin.cpp:909] ProbeRequest '{}'
I0710 20:50:56.683311 18263 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 20:50:56.685719 32149 test_csi_plugin.cpp:895] GetPluginCapabilitiesRequest '{}'
I0710 20:50:56.686406 18285 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1'
I0710 20:50:56.687543 18271 http.cpp:1115] HTTP POST for /slave(1207)/api/v1 from 172.17.0.2:47214
I0710 20:50:56.688026 18271 http.cpp:2715] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 20:50:56.688964 32150 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0710 20:50:56.689293 32149 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0710 20:50:56.690759 18283 v1_volume_manager.cpp:648] NODE_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0710 20:50:56.691218 18283 v1_volume_manager.cpp:648] CONTROLLER_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0710 20:50:56.693176 32151 test_csi_plugin.cpp:1105] ControllerGetCapabilitiesRequest '{}'
I0710 20:50:56.695785 32151 test_csi_plugin.cpp:1241] NodeGetCapabilitiesRequest '{}'
I0710 20:50:56.699008 32149 test_csi_plugin.cpp:1255] NodeGetInfoRequest '{}'
I0710 20:50:56.700698 18265 provider.cpp:659] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0710 20:50:56.700806 18269 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 20:50:56.701205 18274 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:50:56.703624 18284 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:50:56.704128 18264 provider.cpp:459] Connected to resource provider manager
I0710 20:50:56.704658 18280 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:50:56.705579 18262 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1/resource_provider'
I0710 20:50:56.707028 18265 http.cpp:1115] HTTP POST for /slave(1207)/api/v1/resource_provider from 172.17.0.2:47218
I0710 20:50:56.707707 18270 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_YGpbza","--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"}
I0710 20:50:56.719189 18285 hierarchical.cpp:1508] Performed allocation for 1 agents in 176389ns
I0710 20:50:56.752454 18277 slave.cpp:8395] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"09e12a57-4915-45f0-a57a-d566945df88f"},"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_YGpbza","--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"}'
I0710 20:50:56.753775 18273 provider.cpp:481] Received SUBSCRIBED event
I0710 20:50:56.753806 18273 provider.cpp:1255] Subscribed with ID 09e12a57-4915-45f0-a57a-d566945df88f
I0710 20:50:56.754488 18282 status_update_manager_process.hpp:314] Recovering operation status update manager
I0710 20:50:56.769989 18274 hierarchical.cpp:1508] Performed allocation for 1 agents in 171624ns
I0710 20:50:56.820739 18283 hierarchical.cpp:1508] Performed allocation for 1 agents in 96088ns
I0710 20:50:56.872210 18276 hierarchical.cpp:1508] Performed allocation for 1 agents in 96043ns
I0710 20:50:56.887363 32151 test_csi_plugin.cpp:1050] ListVolumesRequest '{}'
I0710 20:50:56.889412 18272 provider.cpp:2145] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:56.889637 18272 provider.cpp:745] Resource provider 09e12a57-4915-45f0-a57a-d566945df88f is in READY state
I0710 20:50:56.889693 18262 status_update_manager_process.hpp:385] Resuming operation status update manager
I0710 20:50:56.889688 18271 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:50:56.890267 18269 provider.cpp:1181] Updating profiles { test } for resource provider 09e12a57-4915-45f0-a57a-d566945df88f
I0710 20:50:56.891175 18276 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1/resource_provider'
I0710 20:50:56.892951 18280 http.cpp:1115] HTTP POST for /slave(1207)/api/v1/resource_provider from 172.17.0.2:47216
I0710 20:50:56.893383 18262 manager.cpp:1039] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 09e12a57-4915-45f0-a57a-d566945df88f
I0710 20:50:56.893569 18272 slave.cpp:8395] Handling resource provider message 'UPDATE_STATE: 09e12a57-4915-45f0-a57a-d566945df88f {}'
I0710 20:50:56.893676 18272 slave.cpp:8515] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0710 20:50:56.894304 32151 test_csi_plugin.cpp:1078] GetCapacityRequest '{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0710 20:50:56.895278 18282 hierarchical.cpp:753] Grew agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 by {} (total), { } (used)
I0710 20:50:56.895654 18282 hierarchical.cpp:710] Agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 (f57a0dc1c520) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
W0710 20:50:56.896421 18261 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:35051
I0710 20:50:56.897513 18261 sched.cpp:239] Version: 1.9.0
I0710 20:50:56.898378 18277 sched.cpp:343] New master detected at master@172.17.0.2:35051
I0710 20:50:56.898566 18277 sched.cpp:408] Authenticating with master master@172.17.0.2:35051
I0710 20:50:56.898592 18277 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0710 20:50:56.898579 18279 provider.cpp:933] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to the total resources
I0710 20:50:56.898990 18265 authenticatee.cpp:121] Creating new client SASL connection
I0710 20:50:56.899391 18262 hierarchical.cpp:1508] Performed allocation for 1 agents in 255655ns
I0710 20:50:56.899391 18277 master.cpp:10380] Authenticating scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:56.899602 18263 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2058)@172.17.0.2:35051
I0710 20:50:56.899942 18274 authenticator.cpp:98] Creating new server SASL connection
I0710 20:50:56.900245 18283 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0710 20:50:56.900285 18283 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0710 20:50:56.900418 18266 authenticator.cpp:204] Received SASL authentication start
I0710 20:50:56.900487 18266 authenticator.cpp:326] Authentication requires more steps
I0710 20:50:56.900610 18266 authenticatee.cpp:259] Received SASL authentication step
I0710 20:50:56.900743 18273 authenticator.cpp:232] Received SASL authentication step
I0710 20:50:56.900785 18273 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f57a0dc1c520' server FQDN: 'f57a0dc1c520' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0710 20:50:56.900811 18273 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0710 20:50:56.900877 18273 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0710 20:50:56.900913 18273 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'f57a0dc1c520' server FQDN: 'f57a0dc1c520' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0710 20:50:56.900930 18273 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0710 20:50:56.900944 18273 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0710 20:50:56.900969 18273 authenticator.cpp:318] Authentication success
I0710 20:50:56.901073 18269 authenticatee.cpp:299] Authentication success
I0710 20:50:56.901191 18282 master.cpp:10412] Successfully authenticated principal 'test-principal' at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:56.901263 18276 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2058)@172.17.0.2:35051
I0710 20:50:56.901490 18268 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:35051
I0710 20:50:56.901515 18268 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:35051
I0710 20:50:56.901669 18268 sched.cpp:870] Will retry registration in 1.459374146secs if necessary
I0710 20:50:56.901870 18275 master.cpp:2890] Received SUBSCRIBE call for framework 'default' at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:56.901907 18275 master.cpp:2222] Authorizing framework principal 'test-principal' to receive offers for roles '{ storage/default-role }'
I0710 20:50:56.902546 18281 master.cpp:2977] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0710 20:50:56.905334 18281 master.cpp:10610] Adding framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051 with roles { } suppressed
I0710 20:50:56.905874 18265 sched.cpp:751] Framework registered with 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:56.905930 18265 sched.cpp:770] Scheduler::registered took 27554ns
I0710 20:50:56.906386 18264 hierarchical.cpp:368] Added framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:56.907783 18264 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.226074ms
I0710 20:50:56.908385 18263 master.cpp:10195] Sending offers [ 65248d47-75df-4772-b399-2edfaf9fa351-O0 ] to framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:56.909152 18274 sched.cpp:934] Scheduler::resourceOffers took 170003ns
I0710 20:50:56.909588 18283 master.cpp:6119] Processing DECLINE call for offers: [ 65248d47-75df-4772-b399-2edfaf9fa351-O0 ] for framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051 with 5 seconds filter
I0710 20:50:56.910190 18283 master.cpp:12470] Removing offer 65248d47-75df-4772-b399-2edfaf9fa351-O0
I0710 20:50:56.910672 18270 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 65248d47-75df-4772-b399-2edfaf9fa351-S0 from framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:56.910739 18270 hierarchical.cpp:1264] Framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 filtered agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for 5secs
I0710 20:50:57.009912 18279 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 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:57.010349 18266 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:50:57.011420 18282 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1/resource_provider'
I0710 20:50:57.052387 18275 http.cpp:1115] HTTP POST for /slave(1207)/api/v1/resource_provider from 172.17.0.2:47216
I0710 20:50:57.052928 18280 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":"09e12a57-4915-45f0-a57a-d566945df88f"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]' and 0 operations from resource provider 09e12a57-4915-45f0-a57a-d566945df88f
I0710 20:50:57.053421 18272 slave.cpp:8395] Handling resource provider message 'UPDATE_STATE: 09e12a57-4915-45f0-a57a-d566945df88f disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0710 20:50:57.053647 18272 slave.cpp:8515] 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
I0710 20:50:57.056066 18262 hierarchical.cpp:710] Agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 (f57a0dc1c520) 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
I0710 20:50:57.057581 18262 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.288175ms
I0710 20:50:57.058254 18264 master.cpp:10195] Sending offers [ 65248d47-75df-4772-b399-2edfaf9fa351-O1 ] to framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:57.058892 18263 sched.cpp:934] Scheduler::resourceOffers took 81197ns
I0710 20:50:57.063830 18270 master.cpp:12470] Removing offer 65248d47-75df-4772-b399-2edfaf9fa351-O1
I0710 20:50:57.064184 18270 master.cpp:4636] Processing ACCEPT call for offers: [ 65248d47-75df-4772-b399-2edfaf9fa351-O1 ] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520) for framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:57.064288 18270 master.cpp:4009] 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'
I0710 20:50:57.064352 18284 hierarchical.cpp:1508] Performed allocation for 1 agents in 233760ns
I0710 20:50:57.065209 18269 master.cpp:5911] 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 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051 to agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:57.065726 18269 master.cpp:12361] Sending operation '' (uuid: 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f) to agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:57.065999 18276 hierarchical.cpp:1432] Allocation paused
I0710 20:50:57.066243 18285 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:57.067140 18276 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 65248d47-75df-4772-b399-2edfaf9fa351-S0 from framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.067227 18276 hierarchical.cpp:1264] Framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 filtered agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for 5secs
I0710 20:50:57.067441 18276 hierarchical.cpp:1442] Allocation resumed
I0710 20:50:57.068131 18262 provider.cpp:481] Received APPLY_OPERATION event
I0710 20:50:57.068176 18262 provider.cpp:1295] Received CREATE_DISK operation '' (uuid: 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f)
I0710 20:50:57.115154 18263 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.115262 18263 hierarchical.cpp:1508] Performed allocation for 1 agents in 469888ns
I0710 20:50:57.166455 18274 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.166549 18274 hierarchical.cpp:1508] Performed allocation for 1 agents in 375458ns
I0710 20:50:57.193665 18266 v1_volume_manager.cpp:292] Creating volume with name '1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f'
I0710 20:50:57.197044 32149 test_csi_plugin.cpp:922] CreateVolumeRequest '{"name":"1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f","capacityRange":{"requiredBytes":"2147483648","limitBytes":"2147483648"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0710 20:50:57.217389 18273 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.217487 18273 hierarchical.cpp:1508] Performed allocation for 1 agents in 370478ns
I0710 20:50:57.268903 18285 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.269008 18285 hierarchical.cpp:1508] Performed allocation for 1 agents in 390582ns
I0710 20:50:57.319869 18268 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.319972 18268 hierarchical.cpp:1508] Performed allocation for 1 agents in 382191ns
I0710 20:50:57.371347 18272 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.371443 18272 hierarchical.cpp:1508] Performed allocation for 1 agents in 401725ns
I0710 20:50:57.422367 18271 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.422473 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 386445ns
I0710 20:50:57.460754 18276 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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test)]:2048' for operation (uuid: 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f)
I0710 20:50:57.473856 18281 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.473966 18281 hierarchical.cpp:1508] Performed allocation for 1 agents in 395260ns
I0710 20:50:57.524873 18280 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.524972 18280 hierarchical.cpp:1508] Performed allocation for 1 agents in 453605ns
I0710 20:50:57.576243 18264 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.576345 18264 hierarchical.cpp:1508] Performed allocation for 1 agents in 384670ns
I0710 20:50:57.593618 18263 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: c79088e4-f77b-4947-b4d6-aecbdf20934b) for operation UUID 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f of framework '65248d47-75df-4772-b399-2edfaf9fa351-0000' on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:57.593700 18263 status_update_manager_process.hpp:414] Creating operation status update stream 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f checkpoint=true
I0710 20:50:57.594101 18263 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: c79088e4-f77b-4947-b4d6-aecbdf20934b) for operation UUID 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f of framework '65248d47-75df-4772-b399-2edfaf9fa351-0000' on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:57.627226 18283 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.627342 18283 hierarchical.cpp:1508] Performed allocation for 1 agents in 399523ns
I0710 20:50:57.678989 18284 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.679092 18284 hierarchical.cpp:1508] Performed allocation for 1 agents in 408642ns
I0710 20:50:57.726843 18263 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: c79088e4-f77b-4947-b4d6-aecbdf20934b) for operation UUID 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f of framework '65248d47-75df-4772-b399-2edfaf9fa351-0000' on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:57.727879 18279 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:50:57.729792 18282 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1/resource_provider'
I0710 20:50:57.731683 18273 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for role storage/default-role of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.731777 18273 hierarchical.cpp:1508] Performed allocation for 1 agents in 370421ns
I0710 20:50:57.768651 18271 http.cpp:1115] HTTP POST for /slave(1207)/api/v1/resource_provider from 172.17.0.2:47216
I0710 20:50:57.769663 18281 slave.cpp:8395] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f) for framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 20:50:57.769902 18281 slave.cpp:8848] Updating the state of operation with no ID (uuid: 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f) for framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 20:50:57.770300 18281 slave.cpp:8602] Forwarding status update of operation with no ID (operation_uuid: 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f) for framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.770648 18264 master.cpp:12017] Updating the state of operation '' (uuid: 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f) for framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 20:50:57.771682 18274 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:57.772275 18283 hierarchical.cpp:956] Updated allocation of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 on agent 65248d47-75df-4772-b399-2edfaf9fa351-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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test)]:2048
I0710 20:50:57.772861 18283 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test)]:2048, allocated: {}) on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 from framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.773175 18273 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 20:50:57.773351 18285 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: c79088e4-f77b-4947-b4d6-aecbdf20934b) for stream 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f
I0710 20:50:57.773465 18285 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: c79088e4-f77b-4947-b4d6-aecbdf20934b) for operation UUID 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f of framework '65248d47-75df-4772-b399-2edfaf9fa351-0000' on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:57.784418 18268 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.336836ms
I0710 20:50:57.785081 18275 master.cpp:10195] Sending offers [ 65248d47-75df-4772-b399-2edfaf9fa351-O2 ] to framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:57.785784 18272 sched.cpp:934] Scheduler::resourceOffers took 121316ns
I0710 20:50:57.789141 18264 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0710 20:50:57.790752 18270 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:47220
I0710 20:50:57.790988 18270 http.cpp:263] Processing call RESERVE_RESOURCES
I0710 20:50:57.791680 18270 master.cpp:3721] 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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test)]:2048'
I0710 20:50:57.793232 18269 master.cpp:12470] Removing offer 65248d47-75df-4772-b399-2edfaf9fa351-O2
I0710 20:50:57.793380 18275 sched.cpp:960] Rescinded offer 65248d47-75df-4772-b399-2edfaf9fa351-O2
I0710 20:50:57.793457 18275 sched.cpp:971] Scheduler::offerRescinded took 24449ns
I0710 20:50:57.794047 18268 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test)]:2048, allocated: {}) on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 from framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:57.794157 18268 hierarchical.cpp:1264] Framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 filtered agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for 5secs
I0710 20:50:57.796809 18272 master.cpp:12361] Sending operation '' (uuid: 2860371e-563d-4faf-a648-e112d9424e49) to agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:57.797294 18271 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:57.800647 18267 provider.cpp:481] Received APPLY_OPERATION event
I0710 20:50:57.800688 18267 provider.cpp:1295] Received RESERVE operation '' (uuid: 2860371e-563d-4faf-a648-e112d9424e49)
I0710 20:50:57.909994 18285 status_update_manager_process.hpp:490] Cleaning up operation status update stream 1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f
I0710 20:50:58.344890 18283 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: f0a4f8b4-ac72-4c27-86c5-0a7e5b18e726) for operation UUID 2860371e-563d-4faf-a648-e112d9424e49 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:58.344983 18283 status_update_manager_process.hpp:414] Creating operation status update stream 2860371e-563d-4faf-a648-e112d9424e49 checkpoint=true
I0710 20:50:58.345948 18283 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: f0a4f8b4-ac72-4c27-86c5-0a7e5b18e726) for operation UUID 2860371e-563d-4faf-a648-e112d9424e49 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:58.476711 18283 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: f0a4f8b4-ac72-4c27-86c5-0a7e5b18e726) for operation UUID 2860371e-563d-4faf-a648-e112d9424e49 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:58.477599 18270 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:50:58.478819 18275 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1/resource_provider'
I0710 20:50:58.482208 18269 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.358989ms
I0710 20:50:58.482928 18268 master.cpp:10195] Sending offers [ 65248d47-75df-4772-b399-2edfaf9fa351-O3 ] to framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:58.483752 18277 sched.cpp:934] Scheduler::resourceOffers took 90977ns
I0710 20:50:58.487025 18278 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0710 20:50:58.488874 18284 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:47222
I0710 20:50:58.489150 18284 http.cpp:263] Processing call CREATE_VOLUMES
I0710 20:50:58.489950 18284 master.cpp:3848] Authorizing principal 'test-principal' to create volumes '[{"disk":{"persistence":{"id":"b96a736e-0c3a-43b8-80e7-41fab69c4c4a","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f","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":"09e12a57-4915-45f0-a57a-d566945df88f"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0710 20:50:58.491914 18263 master.cpp:12470] Removing offer 65248d47-75df-4772-b399-2edfaf9fa351-O3
I0710 20:50:58.492058 18283 sched.cpp:960] Rescinded offer 65248d47-75df-4772-b399-2edfaf9fa351-O3
I0710 20:50:58.492131 18283 sched.cpp:971] Scheduler::offerRescinded took 22415ns
I0710 20:50:58.492789 18285 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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test)]:2048, allocated: {}) on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 from framework 65248d47-75df-47
72-b399-2edfaf9fa351-0000
I0710 20:50:58.492926 18285 hierarchical.cpp:1264] Framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 filtered agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for 5secs
I0710 20:50:58.495357 18267 master.cpp:12361] Sending operation '' (uuid: 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0) to agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:58.495872 18270 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:58.499199 18278 provider.cpp:481] Received APPLY_OPERATION event
I0710 20:50:58.499243 18278 provider.cpp:1295] Received CREATE operation '' (uuid: 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0)
I0710 20:50:58.505499 18264 master.cpp:6233] Processing REVIVE call for framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:58.505864 18284 hierarchical.cpp:1365] Unsuppressed offers for roles { storage/default-role } of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:58.505889 18284 hierarchical.cpp:1387] Revived roles { storage/default-role } of framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:58.506964 18284 hierarchical.cpp:1508] Performed allocation for 1 agents in 961060ns
I0710 20:50:58.507297 18284 hierarchical.cpp:1508] Performed allocation for 1 agents in 169630ns
I0710 20:50:58.507494 18262 master.cpp:10195] Sending offers [ 65248d47-75df-4772-b399-2edfaf9fa351-O4 ] to framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:58.508028 18283 sched.cpp:934] Scheduler::resourceOffers took 76841ns
I0710 20:50:58.516237 18273 http.cpp:1115] HTTP POST for /slave(1207)/api/v1/resource_provider from 172.17.0.2:47216
I0710 20:50:58.517189 18270 slave.cpp:8395] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 2860371e-563d-4faf-a648-e112d9424e49) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 20:50:58.517367 18270 slave.cpp:8848] Updating the state of operation with no ID (uuid: 2860371e-563d-4faf-a648-e112d9424e49) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 20:50:58.517415 18270 slave.cpp:8602] Forwarding status update of operation with no ID (operation_uuid: 2860371e-563d-4faf-a648-e112d9424e49) for an operator API call
I0710 20:50:58.517851 18272 master.cpp:12017] Updating the state of operation '' (uuid: 2860371e-563d-4faf-a648-e112d9424e49) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 20:50:58.518456 18276 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:58.785261 18283 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 37ea8cf2-8de5-4af6-993e-e8a4424da0a4) for operation UUID 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:58.785344 18283 status_update_manager_process.hpp:414] Creating operation status update stream 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0 checkpoint=true
I0710 20:50:58.785420 18278 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 20:50:58.785665 18283 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 37ea8cf2-8de5-4af6-993e-e8a4424da0a4) for operation UUID 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:58.934996 18283 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 37ea8cf2-8de5-4af6-993e-e8a4424da0a4) for operation UUID 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:58.935364 18283 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: f0a4f8b4-ac72-4c27-86c5-0a7e5b18e726) for stream 2860371e-563d-4faf-a648-e112d9424e49
I0710 20:50:58.935433 18283 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: f0a4f8b4-ac72-4c27-86c5-0a7e5b18e726) for operation UUID 2860371e-563d-4faf-a648-e112d9424e49 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:58.936640 18285 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:50:58.937646 18267 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1/resource_provider'
I0710 20:50:58.976214 18281 http.cpp:1115] HTTP POST for /slave(1207)/api/v1/resource_provider from 172.17.0.2:47216
I0710 20:50:58.977146 18270 slave.cpp:8395] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 20:50:58.977353 18270 slave.cpp:8848] Updating the state of operation with no ID (uuid: 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 20:50:58.977414 18270 slave.cpp:8602] Forwarding status update of operation with no ID (operation_uuid: 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0) for an operator API call
I0710 20:50:58.977802 18280 master.cpp:12017] Updating the state of operation '' (uuid: 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 20:50:58.978296 18274 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:58.979766 18282 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 20:50:59.102850 18283 status_update_manager_process.hpp:490] Cleaning up operation status update stream 2860371e-563d-4faf-a648-e112d9424e49
I0710 20:50:59.103119 18283 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 37ea8cf2-8de5-4af6-993e-e8a4424da0a4) for stream 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0
I0710 20:50:59.103209 18283 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 37ea8cf2-8de5-4af6-993e-e8a4424da0a4) for operation UUID 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:59.235214 18283 status_update_manager_process.hpp:490] Cleaning up operation status update stream 2c7c6f14-6c9e-455c-81f4-ca6754a4fad0
I0710 20:50:59.373472 18268 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0710 20:50:59.375262 18280 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:47224
I0710 20:50:59.375520 18280 http.cpp:263] Processing call DESTROY_VOLUMES
I0710 20:50:59.376358 18280 master.cpp:3893] Authorizing principal 'test-principal' to destroy volumes '[{"disk":{"persistence":{"id":"b96a736e-0c3a-43b8-80e7-41fab69c4c4a","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f","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":"09e12a57-4915-45f0-a57a-d566945df88f"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0710 20:50:59.379122 18279 master.cpp:12470] Removing offer 65248d47-75df-4772-b399-2edfaf9fa351-O4
I0710 20:50:59.379302 18284 sched.cpp:960] Rescinded offer 65248d47-75df-4772-b399-2edfaf9fa351-O4
I0710 20:50:59.379390 18284 sched.cpp:971] Scheduler::offerRescinded took 29110ns
I0710 20:50:59.380219 18266 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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test),b96a736e-0c3a-43b8-80e7-41fab69c4c4a: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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test),b96a736e-0c3a-43b8-80e7-41fab69c4c4a:volume]:2048, allocat
ed: {}) on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 from framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:50:59.380362 18266 hierarchical.cpp:1264] Framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 filtered agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for 5secs
I0710 20:50:59.383323 18262 master.cpp:12361] Sending operation '' (uuid: 8c721031-7606-4f32-92f8-0abe7826c0e3) to agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:59.384011 18275 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:59.387217 18276 provider.cpp:481] Received APPLY_OPERATION event
I0710 20:50:59.387269 18276 provider.cpp:1295] Received DESTROY operation '' (uuid: 8c721031-7606-4f32-92f8-0abe7826c0e3)
I0710 20:50:59.392731 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.215063ms
I0710 20:50:59.393419 18264 master.cpp:10195] Sending offers [ 65248d47-75df-4772-b399-2edfaf9fa351-O5 ] to framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:59.394062 18280 sched.cpp:934] Scheduler::resourceOffers took 78609ns
I0710 20:50:59.627032 18274 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: d89c9933-4a2d-470e-b010-f13279dbff28) for operation UUID 8c721031-7606-4f32-92f8-0abe7826c0e3 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:59.627174 18274 status_update_manager_process.hpp:414] Creating operation status update stream 8c721031-7606-4f32-92f8-0abe7826c0e3 checkpoint=true
I0710 20:50:59.627616 18274 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: d89c9933-4a2d-470e-b010-f13279dbff28) for operation UUID 8c721031-7606-4f32-92f8-0abe7826c0e3 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:59.768448 18274 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: d89c9933-4a2d-470e-b010-f13279dbff28) for operation UUID 8c721031-7606-4f32-92f8-0abe7826c0e3 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:50:59.770143 18284 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:50:59.771734 18263 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1/resource_provider'
I0710 20:50:59.775410 18267 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0710 20:50:59.777084 18268 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:47226
I0710 20:50:59.777336 18268 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0710 20:50:59.778350 18268 master.cpp:3785] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f","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":"09e12a57-4915-45f0-a57a-d566945df88f"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0710 20:50:59.780325 18281 master.cpp:12470] Removing offer 65248d47-75df-4772-b399-2edfaf9fa351-O5
I0710 20:50:59.780529 18264 sched.cpp:960] Rescinded offer 65248d47-75df-4772-b399-2edfaf9fa351-O5
I0710 20:50:59.780632 18264 sched.cpp:971] Scheduler::offerRescinded took 44513ns
I0710 20:50:59.781224 18271 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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test)]:2048, allocated: {}) on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 from framework 65248d47-75df-47
72-b399-2edfaf9fa351-0000
I0710 20:50:59.781342 18271 hierarchical.cpp:1264] Framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 filtered agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 for 5secs
I0710 20:50:59.783830 18280 master.cpp:12361] Sending operation '' (uuid: d57f6701-25f0-4380-be93-2c66abea78d7) to agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:50:59.784294 18279 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:50:59.786692 18277 provider.cpp:481] Received APPLY_OPERATION event
I0710 20:50:59.786728 18277 provider.cpp:1295] Received UNRESERVE operation '' (uuid: d57f6701-25f0-4380-be93-2c66abea78d7)
I0710 20:50:59.796056 18272 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.057398ms
I0710 20:50:59.796897 18268 master.cpp:10195] Sending offers [ 65248d47-75df-4772-b399-2edfaf9fa351-O6 ] to framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:50:59.797457 18269 sched.cpp:934] Scheduler::resourceOffers took 72269ns
I0710 20:50:59.812366 18276 http.cpp:1115] HTTP POST for /slave(1207)/api/v1/resource_provider from 172.17.0.2:47216
I0710 20:50:59.813323 18280 slave.cpp:8395] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 8c721031-7606-4f32-92f8-0abe7826c0e3) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 20:50:59.813490 18280 slave.cpp:8848] Updating the state of operation with no ID (uuid: 8c721031-7606-4f32-92f8-0abe7826c0e3) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 20:50:59.813539 18280 slave.cpp:8602] Forwarding status update of operation with no ID (operation_uuid: 8c721031-7606-4f32-92f8-0abe7826c0e3) for an operator API call
I0710 20:50:59.813902 18279 master.cpp:12017] Updating the state of operation '' (uuid: 8c721031-7606-4f32-92f8-0abe7826c0e3) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 20:50:59.814424 18263 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:51:00.043592 18269 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 788d7cf8-9afd-4eea-bb18-a1059c127272) for operation UUID d57f6701-25f0-4380-be93-2c66abea78d7 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:51:00.043658 18269 status_update_manager_process.hpp:414] Creating operation status update stream d57f6701-25f0-4380-be93-2c66abea78d7 checkpoint=true
I0710 20:51:00.043704 18277 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 20:51:00.043962 18269 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 788d7cf8-9afd-4eea-bb18-a1059c127272) for operation UUID d57f6701-25f0-4380-be93-2c66abea78d7 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:51:00.176789 18269 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 788d7cf8-9afd-4eea-bb18-a1059c127272) for operation UUID d57f6701-25f0-4380-be93-2c66abea78d7 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:51:00.177088 18269 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: d89c9933-4a2d-470e-b010-f13279dbff28) for stream 8c721031-7606-4f32-92f8-0abe7826c0e3
I0710 20:51:00.177162 18269 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: d89c9933-4a2d-470e-b010-f13279dbff28) for operation UUID 8c721031-7606-4f32-92f8-0abe7826c0e3 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:51:00.177534 18270 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:51:00.179298 18265 process.cpp:3671] Handling HTTP event for process 'slave(1207)' with path: '/slave(1207)/api/v1/resource_provider'
I0710 20:51:00.216171 18262 http.cpp:1115] HTTP POST for /slave(1207)/api/v1/resource_provider from 172.17.0.2:47216
I0710 20:51:00.217026 18263 slave.cpp:8395] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: d57f6701-25f0-4380-be93-2c66abea78d7) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 20:51:00.217185 18263 slave.cpp:8848] Updating the state of operation with no ID (uuid: d57f6701-25f0-4380-be93-2c66abea78d7) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 20:51:00.217228 18263 slave.cpp:8602] Forwarding status update of operation with no ID (operation_uuid: d57f6701-25f0-4380-be93-2c66abea78d7) for an operator API call
I0710 20:51:00.217568 18283 master.cpp:12017] Updating the state of operation '' (uuid: d57f6701-25f0-4380-be93-2c66abea78d7) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 20:51:00.218058 18275 slave.cpp:4328] Ignoring new checkpointed resources and operations identical to the current version
I0710 20:51:00.219285 18271 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 20:51:00.326791 18269 status_update_manager_process.hpp:490] Cleaning up operation status update stream 8c721031-7606-4f32-92f8-0abe7826c0e3
I0710 20:51:00.327008 18269 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 788d7cf8-9afd-4eea-bb18-a1059c127272) for stream d57f6701-25f0-4380-be93-2c66abea78d7
I0710 20:51:00.327088 18269 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 788d7cf8-9afd-4eea-bb18-a1059c127272) for operation UUID d57f6701-25f0-4380-be93-2c66abea78d7 on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:51:00.476686 18269 status_update_manager_process.hpp:490] Cleaning up operation status update stream d57f6701-25f0-4380-be93-2c66abea78d7
I0710 20:51:00.627524 18274 master.cpp:1410] Framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051 disconnected
I0710 20:51:00.627565 18274 master.cpp:3342] Deactivating framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:51:00.627910 18262 hierarchical.cpp:475] Deactivated framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:51:00.628433 18274 master.cpp:12470] Removing offer 65248d47-75df-4772-b399-2edfaf9fa351-O6
I0710 20:51:00.628507 18274 master.cpp:3319] Disconnecting framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:51:00.628559 18274 master.cpp:1425] Giving framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051 0ns to failover
I0710 20:51:00.628573 18275 slave.cpp:914] Agent terminating
I0710 20:51:00.629402 18262 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,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_YGpbza/2GB-1cfcf6b8-5ca8-4330-b9b3-e0f8d506bb8f,test)]:2048, allocated: {}) on agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 from framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:51:00.629518 18275 manager.cpp:163] Terminating resource provider 09e12a57-4915-45f0-a57a-d566945df88f
I0710 20:51:00.629895 18276 master.cpp:1295] Agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520) disconnected
I0710 20:51:00.629926 18276 master.cpp:3379] Disconnecting agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:51:00.630005 18276 master.cpp:3398] Deactivating agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 at slave(1207)@172.17.0.2:35051 (f57a0dc1c520)
I0710 20:51:00.630185 18276 master.cpp:9987] Framework failover timeout, removing framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
I0710 20:51:00.630209 18285 hierarchical.cpp:799] Agent 65248d47-75df-4772-b399-2edfaf9fa351-S0 deactivated
I0710 20:51:00.630218 18276 master.cpp:10979] Removing framework 65248d47-75df-4772-b399-2edfaf9fa351-0000 (default) at scheduler-92f7980b-d157-4cb6-8556-e1a8c84114fa@172.17.0.2:35051
E0710 20:51:00.630502 18263 http_connection.hpp:452] End-Of-File received
I0710 20:51:00.630646 18282 hierarchical.cpp:1432] Allocation paused
I0710 20:51:00.631000 18263 http_connection.hpp:217] Re-detecting endpoint
I0710 20:51:00.631044 18282 hierarchical.cpp:417] Removed framework 65248d47-75df-4772-b399-2edfaf9fa351-0000
I0710 20:51:00.631117 18282 hierarchical.cpp:1442] Allocation resumed
I0710 20:51:00.631399 18263 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0710 20:51:00.631469 18263 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0710 20:51:00.631510 18270 provider.cpp:471] Disconnected from resource provider manager
I0710 20:51:00.631546 18263 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:51:00.631683 18281 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 20:51:00.632858 18285 containerizer.cpp:2575] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0710 20:51:00.632890 18285 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING
I0710 20:51:00.633224 18285 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 20:51:00.634177 18268 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:51:00.634726 18277 provider.cpp:459] Connected to resource provider manager
I0710 20:51:00.635166 18281 hierarchical.cpp:1508] Performed allocation for 1 agents in 140633ns
I0710 20:51:00.635354 18262 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:35051/slave(1207)/api/v1/resource_provider
I0710 20:51:00.636003 18286 process.cpp:2781] Returning '404 Not Found' for '/slave(1207)/api/v1/resource_provider'
E0710 20:51:00.636970 18263 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0710 20:51:00.686970 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 203621ns
I0710 20:51:00.737010 18276 containerizer.cpp:3116] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0710 20:51:00.738468 18274 hierarchical.cpp:1508] Performed allocation for 1 agents in 105565ns
I0710 20:51:00.738492 18268 provisioner.cpp:609] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 20:51:00.742202 18285 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'
I0710 20:51:00.742439 18284 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-iu4P5f/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 20:51:00.742678 18266 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 20:51:00.745251 18286 process.cpp:2781] Returning '404 Not Found' for '/slave(1207)/api/v1'
I0710 20:51:00.754606 18262 master.cpp:1135] Master terminating
I0710 20:51:00.755199 18279 hierarchical.cpp:775] Removed all filters for agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
I0710 20:51:00.755224 18279 hierarchical.cpp:650] Removed agent 65248d47-75df-4772-b399-2edfaf9fa351-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (4543 ms)
[----------] 50 tests from CSIVersion/StorageLocalResourceProviderTest (113921 ms total)
[----------] Global test environment tear-down
[==========] 2271 tests from 216 test cases ran. (1195146 ms total)
[ PASSED ] 2270 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] SlaveTest.AgentFailoverHTTPExecutorUsingResourceProviderResources
1 FAILED TEST
YOU HAVE 31 DISABLED TESTS
I0710 20:51:00.841161 18286 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-1562785753-14097
Untagged: mesos-1562785753-14097:latest
Deleted: sha256:8a0f4483a6f5df2e5188e26e6905b7b3cc0eb8174547e78244de1253cce93844
Deleted: sha256:8f67c1e7c02e0d17e1bd119cbd05c5b87ade660fe0c88ef6bbdd0421e4802bc8
Deleted: sha256:65e406c7fbfe136fbe06134136aa5b052522615cff60ac04d6eb10fc68f55602
Deleted: sha256:941f436b24ef4773fe8d84bb45e061563fe32bbd03f4dac92ebf0e28f29a9535
Deleted: sha256:728d747e8c3bdfa2244e043e50da9db63663b18f83e9d48ff7686358f2e6420d
Deleted: sha256:4f8e017f32249111c8f09a1ef5383b8a23be2a95925486b0dc45776a5ab97161
Deleted: sha256:a07fb43fe50b2d6eb0b937bde8faa22c20036e42e09603fe62ce755ff1fa4d99
Deleted: sha256:b7c00ac309b1d00216a45e5fa5733f72e044f2ff2e24f70cb9e806644af1fb1e
Deleted: sha256:e93cdf7d9e42dc453159ea24ef953a068ef972e3af49cc1895ea50aeebaf9414
Deleted: sha256:ea82218ba563b867f1eda1380617a534c5158ab0852a89da8d4e39f2b46fd482
Deleted: sha256:40b1061591fe08ba6d503dbc2bda3ecc9b159188418a9cdf4b47fb5c867a7500
Deleted: sha256:f18f573899109dfcb6f5ce7a44c8290cd6d04405b639d2691061696b71d7a662
Deleted: sha256:a22f132fbee329c72b11c591fcf847f9988a3f985ada03882835f5ad4a30097b
Deleted: sha256:9d318c6f03c83ee48ff7fc422e4589d197e30590f376aa42a343ebd4c463f0fe
Deleted: sha256:26beb45dd28a0d8411b0f6d8de15b51bbf1aae23a93ae200b8601c61a9381511
Deleted: sha256:0f35fb838a3ae843aac9e958ff170e7c2a1d9495643b81113a77221328604a6a
Deleted: sha256:6793b741e4e867fc8c34fd72105abde63efe2864a1c8e00fb4d64c97d3050db6
Deleted: sha256:b5b4bef207a5db297ca29477e07ebfeb99814e228fe73fbb9552620d6158b812
Deleted: sha256:c6ce4d66d80ccd1a11d81b938ed8da725ed402179cc835a779a4a44da77dc485
Deleted: sha256:83b03b9b5086e44cd6dbd3c288ad68e75836c90daea18c25ba6c0423cf2c8929
Deleted: sha256:625385551cb29560304fdae65a0e87360b6db99c14cd64a8cecc070f0494376d
Deleted: sha256:616d4f966cbd20717089b097f6730569e8160658d2d28ff7af376f2844cecef6
Deleted: sha256:1fb98464c6765c1796909fe4d20d1b18a6525efc8fe95f8310697ba3a7901c2e
Deleted: sha256:03bd51806e2706bfd9567a614e41f2755654625df8e440f8a1c5bae1d9d393bf
Deleted: sha256:05c50b3fcc07b2c27e6f13e96cc7937bfaae2026bdaec15c9ca79e43538ff8ea
Deleted: sha256:cc8e67acdf3c1ad9a75d4b73bfc9a93237439a0f499b842f1754a1155f75d120
Deleted: sha256:f4fb122b5f8fce20a9891d0966b5c47382923ccb096967043c1294b16bc2ce1e
Deleted: sha256:6bb58222d152e1cca3dd786caffd409fa32c5f5e845a1ba1115b463afb24518e
Deleted: sha256:a919fd442a950167377a2f16c9b242aa7a56f33cb1e446600e4e994967f2b05d
Deleted: sha256:3bda89c820ca95303bd11c228ad14017ef596352698fa6eaaf9bbe25e8659fab
Deleted: sha256:2c5e00d77a67934d5e39493477f262b878f127b9c01b491f06d8f06f78819578
Deleted: sha256:664a2bb343be8b1a691e0ce9c563ee654c30a1c694dc1b25ebb5467fa3d074fd
Deleted: sha256:4ac0c5a114c714b429ff471f5415974618e0b6fc743070d445cd0e2ac586cc7b
Deleted: sha256:5f200444c0009c41eb39bc1cf37a5b3c2e953478f2f373c5a1873dee820e0ced
Deleted: sha256:b057ab380990c219581e3b074919413ebe31079cbd0d615f63872c471b4dc633
Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/2479/console
- Mesos Reviewbot
On June 28, 2019, 9:27 a.m., Benjamin Bannier wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/70960/
> -----------------------------------------------------------
>
> (Updated June 28, 2019, 9:27 a.m.)
>
>
> Review request for mesos, Greg Mann and Joseph Wu.
>
>
> Bugs: MESOS-9860
> https://issues.apache.org/jira/browse/MESOS-9860
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds a test which confirms that the agent leaves a draining
> state on its own once all frameworks on the agent have no more pending
> tasks and all their executors have neither launched or queued tasks.
>
> The test uses the fact that the agent rejects task launches while
> draining.
>
>
> Diffs
> -----
>
> src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
>
>
> Diff: https://reviews.apache.org/r/70960/diff/4/
>
>
> Testing
> -------
>
> `make check`
>
>
> Thanks,
>
> Benjamin Bannier
>
>
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/#review216582
-----------------------------------------------------------
Patch looks great!
Reviews applied: [70822, 70839, 70834, 70835, 70836, 70899, 70900, 70901, 70903, 70904, 70906, 70907, 70936, 70958, 70959, 70960]
Passed command: 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
- Mesos Reviewbot
On June 28, 2019, 2:27 a.m., Benjamin Bannier wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/70960/
> -----------------------------------------------------------
>
> (Updated June 28, 2019, 2:27 a.m.)
>
>
> Review request for mesos, Greg Mann and Joseph Wu.
>
>
> Bugs: MESOS-9860
> https://issues.apache.org/jira/browse/MESOS-9860
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds a test which confirms that the agent leaves a draining
> state on its own once all frameworks on the agent have no more pending
> tasks and all their executors have neither launched or queued tasks.
>
> The test uses the fact that the agent rejects task launches while
> draining.
>
>
> Diffs
> -----
>
> src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
>
>
> Diff: https://reviews.apache.org/r/70960/diff/4/
>
>
> Testing
> -------
>
> `make check`
>
>
> Thanks,
>
> Benjamin Bannier
>
>
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/#review216434
-----------------------------------------------------------
Patch looks great!
Reviews applied: [70822, 70839, 70834, 70835, 70836, 70899, 70900, 70901, 70903, 70904, 70906, 70907, 70936, 70958, 70959, 70960]
Passed command: 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
- Mesos Reviewbot
On June 28, 2019, 2:27 a.m., Benjamin Bannier wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/70960/
> -----------------------------------------------------------
>
> (Updated June 28, 2019, 2:27 a.m.)
>
>
> Review request for mesos, Greg Mann and Joseph Wu.
>
>
> Bugs: MESOS-9860
> https://issues.apache.org/jira/browse/MESOS-9860
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds a test which confirms that the agent leaves a draining
> state on its own once all frameworks on the agent have no more pending
> tasks and all their executors have neither launched or queued tasks.
>
> The test uses the fact that the agent rejects task launches while
> draining.
>
>
> Diffs
> -----
>
> src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
>
>
> Diff: https://reviews.apache.org/r/70960/diff/4/
>
>
> Testing
> -------
>
> `make check`
>
>
> Thanks,
>
> Benjamin Bannier
>
>
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Benjamin Bannier <bb...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/
-----------------------------------------------------------
(Updated June 28, 2019, 11:27 a.m.)
Review request for mesos, Greg Mann and Joseph Wu.
Changes
-------
Fix formatting
Bugs: MESOS-9860
https://issues.apache.org/jira/browse/MESOS-9860
Repository: mesos
Description
-------
This patch adds a test which confirms that the agent leaves a draining
state on its own once all frameworks on the agent have no more pending
tasks and all their executors have neither launched or queued tasks.
The test uses the fact that the agent rejects task launches while
draining.
Diffs (updated)
-----
src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
Diff: https://reviews.apache.org/r/70960/diff/4/
Changes: https://reviews.apache.org/r/70960/diff/3-4/
Testing
-------
`make check`
Thanks,
Benjamin Bannier
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Benjamin Bannier <bb...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/
-----------------------------------------------------------
(Updated June 28, 2019, 1:11 a.m.)
Review request for mesos, Greg Mann and Joseph Wu.
Changes
-------
Rebase for changes in previous patch, make non-flaky
Bugs: MESOS-9860
https://issues.apache.org/jira/browse/MESOS-9860
Repository: mesos
Description
-------
This patch adds a test which confirms that the agent leaves a draining
state on its own once all frameworks on the agent have no more pending
tasks and all their executors have neither launched or queued tasks.
The test uses the fact that the agent rejects task launches while
draining.
Diffs (updated)
-----
src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
Diff: https://reviews.apache.org/r/70960/diff/3/
Changes: https://reviews.apache.org/r/70960/diff/2-3/
Testing
-------
`make check`
Thanks,
Benjamin Bannier
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Benjamin Bannier <bb...@apache.org>.
> On June 27, 2019, 10:34 p.m., Greg Mann wrote:
> > src/tests/slave_tests.cpp
> > Lines 12362-12369 (patched)
> > <https://reviews.apache.org/r/70960/diff/2/?file=2152614#file2152614line12362>
> >
> > I'm not sure why we would receive multiple TASK_LOST updates? I would expect just one.
> >
> > In any case, it seems perhaps easier to read if the test registers an expectation of the TASK_LOST update and AWAITs on that, then only once that is satisfied, registers the expectation for the TASK_KILLED retry, advances the clock, and awaits on that. WDYT?
The test was rewritten and does not rely on resent status updates anymore. We do not handle multiple updates anymore.
- Benjamin
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/#review216203
-----------------------------------------------------------
On June 28, 2019, 1:11 a.m., Benjamin Bannier wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/70960/
> -----------------------------------------------------------
>
> (Updated June 28, 2019, 1:11 a.m.)
>
>
> Review request for mesos, Greg Mann and Joseph Wu.
>
>
> Bugs: MESOS-9860
> https://issues.apache.org/jira/browse/MESOS-9860
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds a test which confirms that the agent leaves a draining
> state on its own once all frameworks on the agent have no more pending
> tasks and all their executors have neither launched or queued tasks.
>
> The test uses the fact that the agent rejects task launches while
> draining.
>
>
> Diffs
> -----
>
> src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
>
>
> Diff: https://reviews.apache.org/r/70960/diff/3/
>
>
> Testing
> -------
>
> `make check`
>
>
> Thanks,
>
> Benjamin Bannier
>
>
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Greg Mann <gr...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/#review216203
-----------------------------------------------------------
src/tests/slave_tests.cpp
Lines 12362-12369 (patched)
<https://reviews.apache.org/r/70960/#comment303286>
I'm not sure why we would receive multiple TASK_LOST updates? I would expect just one.
In any case, it seems perhaps easier to read if the test registers an expectation of the TASK_LOST update and AWAITs on that, then only once that is satisfied, registers the expectation for the TASK_KILLED retry, advances the clock, and awaits on that. WDYT?
- Greg Mann
On June 26, 2019, 11:55 p.m., Benjamin Bannier wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/70960/
> -----------------------------------------------------------
>
> (Updated June 26, 2019, 11:55 p.m.)
>
>
> Review request for mesos, Greg Mann and Joseph Wu.
>
>
> Bugs: MESOS-9860
> https://issues.apache.org/jira/browse/MESOS-9860
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds a test which confirms that the agent leaves a draining
> state on its own once all frameworks on the agent have no more pending
> tasks and all their executors have neither launched or queued tasks.
>
> The test uses the fact that the agent rejects task launches while
> draining.
>
>
> Diffs
> -----
>
> src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
>
>
> Diff: https://reviews.apache.org/r/70960/diff/2/
>
>
> Testing
> -------
>
> `make check`
>
>
> Thanks,
>
> Benjamin Bannier
>
>
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Benjamin Bannier <bb...@apache.org>.
> On June 27, 2019, 5:29 p.m., Benjamin Bannier wrote:
> > src/tests/slave_tests.cpp
> > Lines 12362-12369 (patched)
> > <https://reviews.apache.org/r/70960/diff/2/?file=2152614#file2152614line12362>
> >
> > This block doesn't work reliably. On when running on Linux I seem to get a resend `lostUpdate` with decent reliability while on macos `lostUpdate` is immediately followed by `killedUpdate1`.
> >
> > Any idea what I am missing?
The test was rewritten to not trigger resent status updates anymore, and seems to work reliably now.
- Benjamin
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/#review216198
-----------------------------------------------------------
On June 28, 2019, 1:11 a.m., Benjamin Bannier wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/70960/
> -----------------------------------------------------------
>
> (Updated June 28, 2019, 1:11 a.m.)
>
>
> Review request for mesos, Greg Mann and Joseph Wu.
>
>
> Bugs: MESOS-9860
> https://issues.apache.org/jira/browse/MESOS-9860
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds a test which confirms that the agent leaves a draining
> state on its own once all frameworks on the agent have no more pending
> tasks and all their executors have neither launched or queued tasks.
>
> The test uses the fact that the agent rejects task launches while
> draining.
>
>
> Diffs
> -----
>
> src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
>
>
> Diff: https://reviews.apache.org/r/70960/diff/3/
>
>
> Testing
> -------
>
> `make check`
>
>
> Thanks,
>
> Benjamin Bannier
>
>
Re: Review Request 70960: Added test for agent to leave draining
state on its own.
Posted by Benjamin Bannier <bb...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/70960/#review216198
-----------------------------------------------------------
src/tests/slave_tests.cpp
Lines 12362-12369 (patched)
<https://reviews.apache.org/r/70960/#comment303282>
This block doesn't work reliably. On when running on Linux I seem to get a resend `lostUpdate` with decent reliability while on macos `lostUpdate` is immediately followed by `killedUpdate1`.
Any idea what I am missing?
- Benjamin Bannier
On June 27, 2019, 1:55 a.m., Benjamin Bannier wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/70960/
> -----------------------------------------------------------
>
> (Updated June 27, 2019, 1:55 a.m.)
>
>
> Review request for mesos, Greg Mann and Joseph Wu.
>
>
> Bugs: MESOS-9860
> https://issues.apache.org/jira/browse/MESOS-9860
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds a test which confirms that the agent leaves a draining
> state on its own once all frameworks on the agent have no more pending
> tasks and all their executors have neither launched or queued tasks.
>
> The test uses the fact that the agent rejects task launches while
> draining.
>
>
> Diffs
> -----
>
> src/tests/slave_tests.cpp 7ba2df9fef9966cd09e0af3f4ef3bb260b6167f6
>
>
> Diff: https://reviews.apache.org/r/70960/diff/2/
>
>
> Testing
> -------
>
> `make check`
>
>
> Thanks,
>
> Benjamin Bannier
>
>