You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@mesos.apache.org by Meng Zhu <mz...@mesosphere.io> on 2019/07/18 04:30:20 UTC
Review Request 71111: Added offer rescind logic for guarantees
enforcement.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/
-----------------------------------------------------------
Review request for mesos and Benjamin Mahler.
Bugs: MESOS-9812
https://issues.apache.org/jira/browse/MESOS-9812
Repository: mesos
Description
-------
Outstanding offers need to be rescinded as needed to ensure
roles' requested guarantees can be satisfied.
For simplicity, and also due to the race between the master and
the allocator, we pessimistically assume that what seems like
"available" resources in the allocator are all gone. We greedily
rescind offers until we can satisfy the guarantees.
Also added a test.
Diffs
-----
src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125
src/tests/master_quota_tests.cpp 64a9b31a38af23fb16a4afd04f6d3413c7d1ffe9
Diff: https://reviews.apache.org/r/71111/diff/1/
Testing
-------
make check
Thanks,
Meng Zhu
Re: Review Request 71111: Added offer rescind logic for guarantees
enforcement.
Posted by Benjamin Mahler <bm...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/#review216817
-----------------------------------------------------------
Fix it, then Ship it!
Ditto here, could you add the caveat about the under-rescind to the commit description?
src/master/quota_handler.cpp
Lines 662-667 (patched)
<https://reviews.apache.org/r/71111/#comment304067>
Thanks!
src/tests/master_quota_tests.cpp
Lines 1733 (patched)
<https://reviews.apache.org/r/71111/#comment304069>
Do you mean Offered here?
src/tests/master_quota_tests.cpp
Lines 1735-1736 (patched)
<https://reviews.apache.org/r/71111/#comment304070>
This seems a bit weak as a test? But I suppose we don't want to write a test that's revealing the quirks of the current under/over rescind implementation?
src/tests/master_quota_tests.cpp
Lines 1736 (patched)
<https://reviews.apache.org/r/71111/#comment304068>
Outstanding
- Benjamin Mahler
On July 23, 2019, 8:39 p.m., Meng Zhu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71111/
> -----------------------------------------------------------
>
> (Updated July 23, 2019, 8:39 p.m.)
>
>
> Review request for mesos, Andrei Sekretenko and Benjamin Mahler.
>
>
> Bugs: MESOS-9812
> https://issues.apache.org/jira/browse/MESOS-9812
>
>
> Repository: mesos
>
>
> Description
> -------
>
> Outstanding offers need to be rescinded as needed to ensure
> roles' requested guarantees can be satisfied.
>
> For simplicity, and also due to the race between the master and
> the allocator, we pessimistically assume that what seems like
> "available" resources in the allocator are all gone. We greedily
> rescind offers until we can satisfy the guarantees.
>
> Also added a test.
>
>
> Diffs
> -----
>
> src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125
> src/tests/master_quota_tests.cpp 8105765172f17f3ea50aa09bc66fede8d21365ab
>
>
> Diff: https://reviews.apache.org/r/71111/diff/4/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Meng Zhu
>
>
Re: Review Request 71111: Added offer rescind logic for guarantees
enforcement.
Posted by Meng Zhu <mz...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/
-----------------------------------------------------------
(Updated July 23, 2019, 1:39 p.m.)
Review request for mesos, Andrei Sekretenko and Benjamin Mahler.
Changes
-------
Added more comments about the best-effort rescinding approach.
Bugs: MESOS-9812
https://issues.apache.org/jira/browse/MESOS-9812
Repository: mesos
Description
-------
Outstanding offers need to be rescinded as needed to ensure
roles' requested guarantees can be satisfied.
For simplicity, and also due to the race between the master and
the allocator, we pessimistically assume that what seems like
"available" resources in the allocator are all gone. We greedily
rescind offers until we can satisfy the guarantees.
Also added a test.
Diffs (updated)
-----
src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125
src/tests/master_quota_tests.cpp 8105765172f17f3ea50aa09bc66fede8d21365ab
Diff: https://reviews.apache.org/r/71111/diff/4/
Changes: https://reviews.apache.org/r/71111/diff/3-4/
Testing
-------
make check
Thanks,
Meng Zhu
Re: Review Request 71111: Added offer rescind logic for guarantees
enforcement.
Posted by Meng Zhu <mz...@mesosphere.io>.
> On July 18, 2019, 3:56 a.m., Andrei Sekretenko wrote:
> > src/master/quota_handler.cpp
> > Lines 664 (patched)
> > <https://reviews.apache.org/r/71111/diff/1/?file=2155880#file2155880line664>
> >
> > Does this mean that we might rescind an offer even if `consumption + offered` for the offer's role is within guarantees of that role?
> >
> > If yes - do we really have to be THAT greedy?...
>
> Andrei Sekretenko wrote:
> Edit: s/is within guarantees/is going to be within guarantees/
Yes, it is inaccurate. But calculating a more correct amount would be expensive. And I do not feel it is necessary. See more details in my message in the public slack: https://mesos.slack.com/archives/C1NEKP60K/p1563498805199200
- Meng
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/#review216717
-----------------------------------------------------------
On July 17, 2019, 9:30 p.m., Meng Zhu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71111/
> -----------------------------------------------------------
>
> (Updated July 17, 2019, 9:30 p.m.)
>
>
> Review request for mesos, Andrei Sekretenko and Benjamin Mahler.
>
>
> Bugs: MESOS-9812
> https://issues.apache.org/jira/browse/MESOS-9812
>
>
> Repository: mesos
>
>
> Description
> -------
>
> Outstanding offers need to be rescinded as needed to ensure
> roles' requested guarantees can be satisfied.
>
> For simplicity, and also due to the race between the master and
> the allocator, we pessimistically assume that what seems like
> "available" resources in the allocator are all gone. We greedily
> rescind offers until we can satisfy the guarantees.
>
> Also added a test.
>
>
> Diffs
> -----
>
> src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125
> src/tests/master_quota_tests.cpp 64a9b31a38af23fb16a4afd04f6d3413c7d1ffe9
>
>
> Diff: https://reviews.apache.org/r/71111/diff/2/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Meng Zhu
>
>
Re: Review Request 71111: Added offer rescind logic for guarantees
enforcement.
Posted by Andrei Sekretenko <as...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/#review216717
-----------------------------------------------------------
src/master/quota_handler.cpp
Lines 664 (patched)
<https://reviews.apache.org/r/71111/#comment303907>
Does this mean that we might rescind an offer even if `consumption + offered` for the offer's role is within guarantees of that role?
If yes - do we really have to be THAT greedy?...
- Andrei Sekretenko
On July 18, 2019, 4:30 a.m., Meng Zhu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71111/
> -----------------------------------------------------------
>
> (Updated July 18, 2019, 4:30 a.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-9812
> https://issues.apache.org/jira/browse/MESOS-9812
>
>
> Repository: mesos
>
>
> Description
> -------
>
> Outstanding offers need to be rescinded as needed to ensure
> roles' requested guarantees can be satisfied.
>
> For simplicity, and also due to the race between the master and
> the allocator, we pessimistically assume that what seems like
> "available" resources in the allocator are all gone. We greedily
> rescind offers until we can satisfy the guarantees.
>
> Also added a test.
>
>
> Diffs
> -----
>
> src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125
> src/tests/master_quota_tests.cpp 64a9b31a38af23fb16a4afd04f6d3413c7d1ffe9
>
>
> Diff: https://reviews.apache.org/r/71111/diff/1/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Meng Zhu
>
>
Re: Review Request 71111: Added offer rescind logic for guarantees
enforcement.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/#review216745
-----------------------------------------------------------
Patch looks great!
Reviews applied: [71109, 71110, 71061, 71068, 71111]
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 July 18, 2019, 4:30 a.m., Meng Zhu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71111/
> -----------------------------------------------------------
>
> (Updated July 18, 2019, 4:30 a.m.)
>
>
> Review request for mesos, Andrei Sekretenko and Benjamin Mahler.
>
>
> Bugs: MESOS-9812
> https://issues.apache.org/jira/browse/MESOS-9812
>
>
> Repository: mesos
>
>
> Description
> -------
>
> Outstanding offers need to be rescinded as needed to ensure
> roles' requested guarantees can be satisfied.
>
> For simplicity, and also due to the race between the master and
> the allocator, we pessimistically assume that what seems like
> "available" resources in the allocator are all gone. We greedily
> rescind offers until we can satisfy the guarantees.
>
> Also added a test.
>
>
> Diffs
> -----
>
> src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125
> src/tests/master_quota_tests.cpp 64a9b31a38af23fb16a4afd04f6d3413c7d1ffe9
>
>
> Diff: https://reviews.apache.org/r/71111/diff/2/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Meng Zhu
>
>
Re: Review Request 71111: Added offer rescind logic for guarantees
enforcement.
Posted by Meng Zhu <mz...@mesosphere.io>.
> On July 18, 2019, 10:32 a.m., Benjamin Mahler wrote:
> > src/master/quota_handler.cpp
> > Lines 651 (patched)
> > <https://reviews.apache.org/r/71111/diff/2/?file=2156187#file2156187line651>
> >
> > Ditto last review, but in this case the presence of reservations in both leads to an under-rescind, which seems less acceptable vs an over-rescind?
Given that we are being very pessimistic here (assuming no available resources), we are more likely to over rescind than under. Hopefully, it is OK. See my comment in previous patch as well.
> On July 18, 2019, 10:32 a.m., Benjamin Mahler wrote:
> > src/tests/master_quota_tests.cpp
> > Lines 1691-1693 (patched)
> > <https://reviews.apache.org/r/71111/diff/2/?file=2156188#file2156188line1691>
> >
> > Ditto, probably want to pull out the test to ease reviewing?
This is a small patch. Would prefer to keep the test with it.
- Meng
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/#review216737
-----------------------------------------------------------
On July 17, 2019, 9:30 p.m., Meng Zhu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71111/
> -----------------------------------------------------------
>
> (Updated July 17, 2019, 9:30 p.m.)
>
>
> Review request for mesos, Andrei Sekretenko and Benjamin Mahler.
>
>
> Bugs: MESOS-9812
> https://issues.apache.org/jira/browse/MESOS-9812
>
>
> Repository: mesos
>
>
> Description
> -------
>
> Outstanding offers need to be rescinded as needed to ensure
> roles' requested guarantees can be satisfied.
>
> For simplicity, and also due to the race between the master and
> the allocator, we pessimistically assume that what seems like
> "available" resources in the allocator are all gone. We greedily
> rescind offers until we can satisfy the guarantees.
>
> Also added a test.
>
>
> Diffs
> -----
>
> src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125
> src/tests/master_quota_tests.cpp 64a9b31a38af23fb16a4afd04f6d3413c7d1ffe9
>
>
> Diff: https://reviews.apache.org/r/71111/diff/2/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Meng Zhu
>
>
Re: Review Request 71111: Added offer rescind logic for guarantees
enforcement.
Posted by Benjamin Mahler <bm...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/#review216737
-----------------------------------------------------------
src/master/quota_handler.cpp
Lines 651 (patched)
<https://reviews.apache.org/r/71111/#comment303924>
Ditto last review, but in this case the presence of reservations in both leads to an under-rescind, which seems less acceptable vs an over-rescind?
src/tests/master_quota_tests.cpp
Lines 1691-1693 (patched)
<https://reviews.apache.org/r/71111/#comment303925>
Ditto, probably want to pull out the test to ease reviewing?
- Benjamin Mahler
On July 18, 2019, 4:30 a.m., Meng Zhu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71111/
> -----------------------------------------------------------
>
> (Updated July 18, 2019, 4:30 a.m.)
>
>
> Review request for mesos, Andrei Sekretenko and Benjamin Mahler.
>
>
> Bugs: MESOS-9812
> https://issues.apache.org/jira/browse/MESOS-9812
>
>
> Repository: mesos
>
>
> Description
> -------
>
> Outstanding offers need to be rescinded as needed to ensure
> roles' requested guarantees can be satisfied.
>
> For simplicity, and also due to the race between the master and
> the allocator, we pessimistically assume that what seems like
> "available" resources in the allocator are all gone. We greedily
> rescind offers until we can satisfy the guarantees.
>
> Also added a test.
>
>
> Diffs
> -----
>
> src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125
> src/tests/master_quota_tests.cpp 64a9b31a38af23fb16a4afd04f6d3413c7d1ffe9
>
>
> Diff: https://reviews.apache.org/r/71111/diff/2/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Meng Zhu
>
>
Re: Review Request 71111: Added offer rescind logic for guarantees
enforcement.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71111/#review216711
-----------------------------------------------------------
Bad patch!
Reviews applied: [71109, 71110, 71061, 71068, 71111]
Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:14.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/docker-build.sh 2>&1 | tee build_71111"]
Error:
...<truncated>...
b-ade3-31adcc3bff52 on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:48.936278 18267 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
I0718 06:35:48.937249 18275 process.cpp:3671] Handling HTTP event for process 'slave(1216)' with path: '/slave(1216)/api/v1/resource_provider'
I0718 06:35:48.940191 18257 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0718 06:35:48.941807 18280 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:52610
I0718 06:35:48.942044 18280 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0718 06:35:48.942693 18280 master.cpp:3888] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"8e9395d9-3d92-4641-876e-2a95f843d191"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0718 06:35:48.944628 18263 master.cpp:12685] Removing offer 58665dec-7eb8-49bb-ad94-85d02ec4f434-O5
I0718 06:35:48.944752 18276 sched.cpp:960] Rescinded offer 58665dec-7eb8-49bb-ad94-85d02ec4f434-O5
I0718 06:35:48.944823 18276 sched.cpp:971] Scheduler::offerRescinded took 21015ns
I0718 06:35:48.945453 18259 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a,test)]:2048, allocated: {}) on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 from framework 58665dec-7eb8-49
bb-ad94-85d02ec4f434-0000
I0718 06:35:48.945569 18259 hierarchical.cpp:1264] Framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 filtered agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 for 5secs
I0718 06:35:48.948091 18273 master.cpp:12576] Sending operation '' (uuid: 32631748-d534-4830-af5b-2860ca4a04ce) to agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 at slave(1216)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:48.948653 18267 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:48.951097 18279 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.161105ms
I0718 06:35:48.951505 18262 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:48.951555 18262 provider.cpp:1295] Received UNRESERVE operation '' (uuid: 32631748-d534-4830-af5b-2860ca4a04ce)
I0718 06:35:48.951690 18260 master.cpp:10393] Sending offers [ 58665dec-7eb8-49bb-ad94-85d02ec4f434-O6 ] to framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
I0718 06:35:48.952296 18261 sched.cpp:934] Scheduler::resourceOffers took 77288ns
I0718 06:35:48.976239 18268 http.cpp:1115] HTTP POST for /slave(1216)/api/v1/resource_provider from 172.17.0.2:52600
I0718 06:35:48.977198 18271 slave.cpp:8406] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: d9520b5c-c932-4e3b-ade3-31adcc3bff52) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0718 06:35:48.977396 18271 slave.cpp:8859] Updating the state of operation with no ID (uuid: d9520b5c-c932-4e3b-ade3-31adcc3bff52) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:48.977449 18271 slave.cpp:8613] Forwarding status update of operation with no ID (operation_uuid: d9520b5c-c932-4e3b-ade3-31adcc3bff52) for an operator API call
I0718 06:35:48.977864 18272 master.cpp:12232] Updating the state of operation '' (uuid: d9520b5c-c932-4e3b-ade3-31adcc3bff52) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:48.978397 18275 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:49.053128 18261 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: ee21e755-02b8-4795-8df7-ca8c77ebabe3) for operation UUID 32631748-d534-4830-af5b-2860ca4a04ce on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.053190 18261 status_update_manager_process.hpp:414] Creating operation status update stream 32631748-d534-4830-af5b-2860ca4a04ce checkpoint=true
I0718 06:35:49.053222 18262 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:49.053681 18261 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: ee21e755-02b8-4795-8df7-ca8c77ebabe3) for operation UUID 32631748-d534-4830-af5b-2860ca4a04ce on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.119984 18261 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: ee21e755-02b8-4795-8df7-ca8c77ebabe3) for operation UUID 32631748-d534-4830-af5b-2860ca4a04ce on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.120317 18261 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 815ffb76-1d43-4a60-9368-d331b763824a) for stream d9520b5c-c932-4e3b-ade3-31adcc3bff52
I0718 06:35:49.120391 18261 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 815ffb76-1d43-4a60-9368-d331b763824a) for operation UUID d9520b5c-c932-4e3b-ade3-31adcc3bff52 on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.120766 18276 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
I0718 06:35:49.121618 18269 process.cpp:3671] Handling HTTP event for process 'slave(1216)' with path: '/slave(1216)/api/v1/resource_provider'
I0718 06:35:49.160171 18272 http.cpp:1115] HTTP POST for /slave(1216)/api/v1/resource_provider from 172.17.0.2:52600
I0718 06:35:49.161003 18275 slave.cpp:8406] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 32631748-d534-4830-af5b-2860ca4a04ce) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0718 06:35:49.161162 18275 slave.cpp:8859] Updating the state of operation with no ID (uuid: 32631748-d534-4830-af5b-2860ca4a04ce) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:49.161221 18275 slave.cpp:8613] Forwarding status update of operation with no ID (operation_uuid: 32631748-d534-4830-af5b-2860ca4a04ce) for an operator API call
I0718 06:35:49.161540 18265 master.cpp:12232] Updating the state of operation '' (uuid: 32631748-d534-4830-af5b-2860ca4a04ce) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:49.162003 18266 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:49.163297 18263 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:49.186823 18261 status_update_manager_process.hpp:490] Cleaning up operation status update stream d9520b5c-c932-4e3b-ade3-31adcc3bff52
I0718 06:35:49.187043 18261 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: ee21e755-02b8-4795-8df7-ca8c77ebabe3) for stream 32631748-d534-4830-af5b-2860ca4a04ce
I0718 06:35:49.187108 18261 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: ee21e755-02b8-4795-8df7-ca8c77ebabe3) for operation UUID 32631748-d534-4830-af5b-2860ca4a04ce on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.270552 18261 status_update_manager_process.hpp:490] Cleaning up operation status update stream 32631748-d534-4830-af5b-2860ca4a04ce
I0718 06:35:49.330803 18277 master.cpp:1410] Framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893 disconnected
I0718 06:35:49.330852 18277 master.cpp:3360] Deactivating framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
I0718 06:35:49.331161 18272 hierarchical.cpp:475] Deactivated framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000
I0718 06:35:49.331636 18264 slave.cpp:914] Agent terminating
I0718 06:35:49.331769 18277 master.cpp:12685] Removing offer 58665dec-7eb8-49bb-ad94-85d02ec4f434-O6
I0718 06:35:49.331845 18277 master.cpp:3337] Disconnecting framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
I0718 06:35:49.331902 18277 master.cpp:1425] Giving framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893 0ns to failover
I0718 06:35:49.332553 18264 manager.cpp:163] Terminating resource provider 8e9395d9-3d92-4641-876e-2a95f843d191
I0718 06:35:49.332798 18272 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_z6gmBZ/2GB-fe75e496-5c41-4dee-b8cd-8a7e5df5283a,test)]:2048, allocated: {}) on agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 from framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000
I0718 06:35:49.332942 18268 master.cpp:1295] Agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 at slave(1216)@172.17.0.2:42893 (2dfcf722f334) disconnected
I0718 06:35:49.332975 18268 master.cpp:3397] Disconnecting agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 at slave(1216)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:49.333076 18268 master.cpp:3416] Deactivating agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 at slave(1216)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:49.333236 18263 hierarchical.cpp:799] Agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0 deactivated
I0718 06:35:49.333317 18268 master.cpp:10185] Framework failover timeout, removing framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
I0718 06:35:49.333348 18268 master.cpp:11184] Removing framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000 (default) at scheduler-4cf5ae9f-d24d-4eae-88a0-dbf9626d4e8c@172.17.0.2:42893
E0718 06:35:49.333554 18257 http_connection.hpp:452] End-Of-File received
I0718 06:35:49.333743 18279 hierarchical.cpp:1432] Allocation paused
I0718 06:35:49.334012 18257 http_connection.hpp:217] Re-detecting endpoint
I0718 06:35:49.334133 18279 hierarchical.cpp:417] Removed framework 58665dec-7eb8-49bb-ad94-85d02ec4f434-0000
I0718 06:35:49.334301 18279 hierarchical.cpp:1442] Allocation resumed
I0718 06:35:49.334461 18257 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0718 06:35:49.334540 18257 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0718 06:35:49.334599 18262 provider.cpp:471] Disconnected from resource provider manager
I0718 06:35:49.334620 18257 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
I0718 06:35:49.334723 18262 status_update_manager_process.hpp:379] Pausing operation status update manager
I0718 06:35:49.336087 18263 containerizer.cpp:2575] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0718 06:35:49.336127 18263 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING
I0718 06:35:49.336532 18263 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.337605 18280 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
I0718 06:35:49.338202 18259 provider.cpp:459] Connected to resource provider manager
I0718 06:35:49.338624 18262 hierarchical.cpp:1508] Performed allocation for 1 agents in 171742ns
I0718 06:35:49.338865 18269 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:42893/slave(1216)/api/v1/resource_provider
E0718 06:35:49.339365 18269 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Cannot process 'SUBSCRIBE' call as the driver is in state SUBSCRIBING
I0718 06:35:49.339617 18281 process.cpp:2781] Returning '404 Not Found' for '/slave(1216)/api/v1/resource_provider'
E0718 06:35:49.340737 18257 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0718 06:35:49.389438 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 119409ns
I0718 06:35:49.440466 18266 containerizer.cpp:3116] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0718 06:35:49.440948 18267 hierarchical.cpp:1508] Performed allocation for 1 agents in 118003ns
I0718 06:35:49.441980 18279 provisioner.cpp:611] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.444370 18274 container_daemon.cpp:189] Invoking post-stop hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.444556 18271 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-xn82K9/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.444809 18277 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.447003 18281 process.cpp:2781] Returning '404 Not Found' for '/slave(1216)/api/v1'
I0718 06:35:49.462693 18256 master.cpp:1135] Master terminating
I0718 06:35:49.463418 18263 hierarchical.cpp:775] Removed all filters for agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
I0718 06:35:49.463449 18263 hierarchical.cpp:650] Removed agent 58665dec-7eb8-49bb-ad94-85d02ec4f434-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v0 (2347 ms)
[ RUN ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1
I0718 06:35:49.487236 18256 cluster.cpp:176] Creating default 'local' authorizer
I0718 06:35:49.493167 18268 master.cpp:440] Master f44b3929-d9b5-487c-bc8a-9166548ec65c (2dfcf722f334) started on 172.17.0.2:42893
I0718 06:35:49.493196 18268 master.cpp:443] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/afMihM/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca
table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/mesos/mesos-1.9.0/_inst/share/mesos/webui" --work_dir="/tmp/afMihM/master" --zk_session_timeout="10secs"
I0718 06:35:49.493587 18268 master.cpp:492] Master only allowing authenticated frameworks to register
I0718 06:35:49.493602 18268 master.cpp:498] Master only allowing authenticated agents to register
I0718 06:35:49.493609 18268 master.cpp:504] Master only allowing authenticated HTTP frameworks to register
I0718 06:35:49.493618 18268 credentials.hpp:37] Loading credentials for authentication from '/tmp/afMihM/credentials'
I0718 06:35:49.493932 18268 master.cpp:548] Using default 'crammd5' authenticator
I0718 06:35:49.494132 18268 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0718 06:35:49.494351 18268 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0718 06:35:49.494525 18268 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0718 06:35:49.494688 18268 master.cpp:629] Authorization enabled
I0718 06:35:49.495096 18258 hierarchical.cpp:241] Initialized hierarchical allocator process
I0718 06:35:49.495121 18266 whitelist_watcher.cpp:77] No whitelist given
I0718 06:35:49.498165 18262 master.cpp:2168] Elected as the leading master!
I0718 06:35:49.498209 18262 master.cpp:1664] Recovering from registrar
I0718 06:35:49.498469 18257 registrar.cpp:339] Recovering registrar
I0718 06:35:49.499452 18257 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0718 06:35:49.499619 18257 registrar.cpp:487] Applied 1 operations in 49105ns; attempting to update the registry
I0718 06:35:49.500439 18257 registrar.cpp:544] Successfully updated the registry in 0ns
I0718 06:35:49.500612 18257 registrar.cpp:416] Successfully recovered registrar
I0718 06:35:49.501106 18277 master.cpp:1817] Recovered 0 agents from the registry (143B); allowing 10mins for agents to reregister
I0718 06:35:49.501122 18276 hierarchical.cpp:280] Skipping recovery of hierarchical allocator: nothing to recover
W0718 06:35:49.510432 18256 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:42893
I0718 06:35:49.511931 18256 containerizer.cpp:314] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0718 06:35:49.512583 18256 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0718 06:35:49.512614 18256 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0718 06:35:49.512758 18256 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0718 06:35:49.512816 18256 provisioner.cpp:300] Using default backend 'copy'
I0718 06:35:49.515456 18256 cluster.cpp:510] Creating default 'local' authorizer
I0718 06:35:49.517908 18280 slave.cpp:265] Mesos agent started on (1217)@172.17.0.2:42893
I0718 06:35:49.517946 18280 slave.cpp:266] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/afMihM/LJ1J7u/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_destroy_timeout="1mins" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/afMihM/LJ1J7u/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_profile_adaptor="org_apache_mesos_UriDiskProfileAdaptor" --disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" --docker_kill_orphans="true"
--docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/afMihM/LJ1J7u/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/afMihM/LJ1J7u/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/afMihM/LJ1J7u/frameworks" --gc_delay="1weeks" --gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/afMihM/LJ1J7u/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.9.0/_build/src" --logbufsecs="0" --
logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/afMihM/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_oAuNTO" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsW
ithResourceProviderResources_v1_ikcSF8" --zk_session_timeout="10secs"
I0718 06:35:49.518683 18280 credentials.hpp:86] Loading credential for authentication from '/tmp/afMihM/LJ1J7u/credential'
I0718 06:35:49.518950 18280 slave.cpp:298] Agent using credential for: test-principal
I0718 06:35:49.518985 18280 credentials.hpp:37] Loading credentials for authentication from '/tmp/afMihM/LJ1J7u/http_credentials'
I0718 06:35:49.519269 18280 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0718 06:35:49.519717 18280 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0718 06:35:49.521451 18280 slave.cpp:613] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0718 06:35:49.521661 18280 slave.cpp:621] Agent attributes: [ ]
I0718 06:35:49.521677 18280 slave.cpp:630] Agent hostname: 2dfcf722f334
I0718 06:35:49.521881 18279 task_status_update_manager.cpp:181] Pausing sending task status updates
I0718 06:35:49.521966 18274 status_update_manager_process.hpp:379] Pausing operation status update manager
I0718 06:35:49.522753 18270 process.cpp:3671] Handling HTTP event for process 'test-disk-profile-server' with path: '/test-disk-profile-server/profiles'
I0718 06:35:49.523643 18259 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/meta'
I0718 06:35:49.523870 18270 slave.cpp:7433] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/meta', beginning agent recovery
I0718 06:35:49.524508 18257 task_status_update_manager.cpp:207] Recovering task status update manager
I0718 06:35:49.524986 18263 containerizer.cpp:796] Recovering Mesos containers
I0718 06:35:49.525370 18263 containerizer.cpp:1122] Recovering isolators
I0718 06:35:49.526113 18259 containerizer.cpp:1161] Recovering provisioner
I0718 06:35:49.526892 18267 provisioner.cpp:500] Provisioner recovery complete
I0718 06:35:49.526926 18258 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0718 06:35:49.527727 18269 composing.cpp:339] Finished recovering all containerizers
I0718 06:35:49.528043 18268 slave.cpp:7897] Recovering executors
I0718 06:35:49.528167 18268 slave.cpp:8050] Finished recovery
I0718 06:35:49.528998 18273 task_status_update_manager.cpp:181] Pausing sending task status updates
I0718 06:35:49.529022 18280 status_update_manager_process.hpp:379] Pausing operation status update manager
I0718 06:35:49.529038 18268 slave.cpp:1340] New master detected at master@172.17.0.2:42893
I0718 06:35:49.529153 18268 slave.cpp:1405] Detecting new master
I0718 06:35:49.530478 18263 slave.cpp:1432] Authenticating with master master@172.17.0.2:42893
I0718 06:35:49.530588 18263 slave.cpp:1441] Using default CRAM-MD5 authenticatee
I0718 06:35:49.530939 18266 authenticatee.cpp:121] Creating new client SASL connection
I0718 06:35:49.531298 18259 master.cpp:10578] Authenticating slave(1217)@172.17.0.2:42893
I0718 06:35:49.531458 18261 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2067)@172.17.0.2:42893
I0718 06:35:49.531769 18260 authenticator.cpp:98] Creating new server SASL connection
I0718 06:35:49.532027 18270 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0718 06:35:49.532060 18270 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0718 06:35:49.532186 18270 authenticator.cpp:204] Received SASL authentication start
I0718 06:35:49.532263 18270 authenticator.cpp:326] Authentication requires more steps
I0718 06:35:49.532397 18267 authenticatee.cpp:259] Received SASL authentication step
I0718 06:35:49.532549 18277 authenticator.cpp:232] Received SASL authentication step
I0718 06:35:49.532588 18277 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2dfcf722f334' server FQDN: '2dfcf722f334' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0718 06:35:49.532601 18277 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0718 06:35:49.532647 18277 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0718 06:35:49.532673 18277 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2dfcf722f334' server FQDN: '2dfcf722f334' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0718 06:35:49.532685 18277 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0718 06:35:49.532693 18277 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0718 06:35:49.532711 18277 authenticator.cpp:318] Authentication success
I0718 06:35:49.532845 18275 authenticatee.cpp:299] Authentication success
I0718 06:35:49.532934 18276 master.cpp:10610] Successfully authenticated principal 'test-principal' at slave(1217)@172.17.0.2:42893
I0718 06:35:49.532964 18257 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2067)@172.17.0.2:42893
I0718 06:35:49.533296 18265 slave.cpp:1532] Successfully authenticated with master master@172.17.0.2:42893
I0718 06:35:49.533687 18265 slave.cpp:1982] Will retry registration in 14.219294ms if necessary
I0718 06:35:49.533859 18264 master.cpp:7086] Received register agent message from slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:49.534157 18264 master.cpp:4202] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
I0718 06:35:49.534883 18273 master.cpp:7153] Authorized registration of agent at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:49.534976 18273 master.cpp:7265] Registering agent at slave(1217)@172.17.0.2:42893 (2dfcf722f334) with id f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:49.535847 18268 registrar.cpp:487] Applied 1 operations in 346039ns; attempting to update the registry
I0718 06:35:49.536739 18268 registrar.cpp:544] Successfully updated the registry in 0ns
I0718 06:35:49.536936 18259 master.cpp:7313] Admitted agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:49.537765 18259 master.cpp:7358] Registered agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0718 06:35:49.537971 18260 hierarchical.cpp:617] Added agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 (2dfcf722f334) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0718 06:35:49.537988 18258 slave.cpp:1565] Registered with master master@172.17.0.2:42893; given agent ID f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:49.538180 18267 task_status_update_manager.cpp:188] Resuming sending task status updates
I0718 06:35:49.538328 18260 hierarchical.cpp:1508] Performed allocation for 1 agents in 144421ns
I0718 06:35:49.538522 18258 slave.cpp:1600] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/meta/slaves/f44b3929-d9b5-487c-bc8a-9166548ec65c-S0/slave.info'
I0718 06:35:49.538590 18277 status_update_manager_process.hpp:385] Resuming operation status update manager
I0718 06:35:49.539849 18258 slave.cpp:1652] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"Gnc6CnPVSvK5CEN7Jq8Esw=="},"slave_id":{"value":"f44b3929-d9b5-487c-bc8a-9166548ec65c-S0"},"update_oversubscribed_resources":false}
I0718 06:35:49.540607 18258 master.cpp:8457] Ignoring update on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334) as it reports no changes
I0718 06:35:49.544711 18263 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1'
I0718 06:35:49.545956 18260 http.cpp:1115] HTTP POST for /slave(1217)/api/v1 from 172.17.0.2:52620
I0718 06:35:49.546427 18260 http.cpp:2131] Processing GET_CONTAINERS call
I0718 06:35:49.552007 18271 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.554302 18261 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1'
I0718 06:35:49.555373 18260 http.cpp:1115] HTTP POST for /slave(1217)/api/v1 from 172.17.0.2:52622
I0718 06:35:49.556149 18260 http.cpp:2497] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.557004 18269 http.cpp:2601] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.557669 18272 containerizer.cpp:1357] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.558848 18272 containerizer.cpp:1529] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_oAuNTO/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0718 06:35:49.558892 18272 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING
I0718 06:35:49.561774 18273 containerizer.cpp:2055] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"},{"name":"CSI_ENDPOINT","type":"VALUE","value":"unix:///tmp/mesos-csi-h4Grme/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperat
ionsWithResourceProviderResources_v1_ikcSF8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="89" --pipe_write="90" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_oAuNTO/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0718 06:35:49.571067 18273 launcher.cpp:145] Forked child with pid '32265' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.571827 18273 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING
I0718 06:35:49.573238 18273 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING
I0718 06:35:49.573511 18273 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ikcSF8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.574594 18273 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING
I0718 06:35:49.577538 18257 container_daemon.cpp:140] Invoking post-start hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.577924 18269 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-h4Grme/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:49.703343 18278 hierarchical.cpp:1508] Performed allocation for 1 agents in 211596ns
I0718 06:35:49.754878 18259 hierarchical.cpp:1508] Performed allocation for 1 agents in 212471ns
I0718 06:35:49.806216 18265 hierarchical.cpp:1508] Performed allocation for 1 agents in 115730ns
I0718 06:35:49.857538 18272 hierarchical.cpp:1508] Performed allocation for 1 agents in 110070ns
I0718 06:35:49.908625 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 202178ns
I0718 06:35:49.945896 18273 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-h4Grme/endpoint.sock' with CSI v1
I0718 06:35:49.960067 18270 hierarchical.cpp:1508] Performed allocation for 1 agents in 110587ns
I0718 06:35:49.962503 32269 test_csi_plugin.cpp:909] ProbeRequest '{}'
I0718 06:35:49.964473 18265 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.966799 32269 test_csi_plugin.cpp:895] GetPluginCapabilitiesRequest '{}'
I0718 06:35:49.967489 18278 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1'
I0718 06:35:49.968814 18277 http.cpp:1115] HTTP POST for /slave(1217)/api/v1 from 172.17.0.2:52624
I0718 06:35:49.969342 18277 http.cpp:2715] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:49.970137 32269 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0718 06:35:49.970537 32270 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0718 06:35:49.971812 18264 v1_volume_manager.cpp:648] NODE_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0718 06:35:49.972340 18264 v1_volume_manager.cpp:648] CONTROLLER_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0718 06:35:49.974244 32269 test_csi_plugin.cpp:1105] ControllerGetCapabilitiesRequest '{}'
I0718 06:35:49.978019 32271 test_csi_plugin.cpp:1241] NodeGetCapabilitiesRequest '{}'
I0718 06:35:49.980964 32269 test_csi_plugin.cpp:1255] NodeGetInfoRequest '{}'
I0718 06:35:49.982805 18274 provider.cpp:659] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0718 06:35:49.982946 18267 status_update_manager_process.hpp:379] Pausing operation status update manager
I0718 06:35:49.983366 18265 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:49.986076 18275 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:49.986701 18259 provider.cpp:459] Connected to resource provider manager
I0718 06:35:49.987385 18261 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:49.989063 18277 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:49.990777 18257 http.cpp:1115] HTTP POST for /slave(1217)/api/v1/resource_provider from 172.17.0.2:52628
I0718 06:35:49.991423 18269 manager.cpp:807] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}
I0718 06:35:50.011234 18278 hierarchical.cpp:1508] Performed allocation for 1 agents in 162283ns
I0718 06:35:50.041683 18268 slave.cpp:8406] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"ab871185-944c-426f-96fa-c6831d8cca77"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}'
I0718 06:35:50.043459 18262 provider.cpp:481] Received SUBSCRIBED event
I0718 06:35:50.043503 18262 provider.cpp:1255] Subscribed with ID ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:50.044394 18257 status_update_manager_process.hpp:314] Recovering operation status update manager
I0718 06:35:50.062119 18265 hierarchical.cpp:1508] Performed allocation for 1 agents in 138827ns
I0718 06:35:50.094015 32271 test_csi_plugin.cpp:1050] ListVolumesRequest '{}'
I0718 06:35:50.096356 18259 provider.cpp:2145] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.096578 18259 provider.cpp:745] Resource provider ab871185-944c-426f-96fa-c6831d8cca77 is in READY state
I0718 06:35:50.096638 18270 status_update_manager_process.hpp:385] Resuming operation status update manager
I0718 06:35:50.096748 18261 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.097267 18273 provider.cpp:1181] Updating profiles { test } for resource provider ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:50.097743 18257 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.099234 18271 http.cpp:1115] HTTP POST for /slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.099692 18259 manager.cpp:1039] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:50.099930 18261 slave.cpp:8406] Handling resource provider message 'UPDATE_STATE: ab871185-944c-426f-96fa-c6831d8cca77 {}'
I0718 06:35:50.100023 18261 slave.cpp:8526] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0718 06:35:50.100754 32269 test_csi_plugin.cpp:1078] GetCapacityRequest '{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0718 06:35:50.101701 18264 hierarchical.cpp:753] Grew agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 by {} (total), { } (used)
I0718 06:35:50.102058 18264 hierarchical.cpp:710] Agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 (2dfcf722f334) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
W0718 06:35:50.102881 18256 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:42893
I0718 06:35:50.104557 18256 sched.cpp:239] Version: 1.9.0
I0718 06:35:50.105274 18275 provider.cpp:933] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to the total resources
I0718 06:35:50.105537 18270 sched.cpp:343] New master detected at master@172.17.0.2:42893
I0718 06:35:50.105690 18270 sched.cpp:408] Authenticating with master master@172.17.0.2:42893
I0718 06:35:50.105712 18270 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0718 06:35:50.106098 18276 authenticatee.cpp:121] Creating new client SASL connection
I0718 06:35:50.106461 18277 master.cpp:10578] Authenticating scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.106591 18273 hierarchical.cpp:1508] Performed allocation for 1 agents in 191270ns
I0718 06:35:50.106680 18263 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2068)@172.17.0.2:42893
I0718 06:35:50.107017 18258 authenticator.cpp:98] Creating new server SASL connection
I0718 06:35:50.107264 18267 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0718 06:35:50.107295 18267 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0718 06:35:50.107434 18272 authenticator.cpp:204] Received SASL authentication start
I0718 06:35:50.107501 18272 authenticator.cpp:326] Authentication requires more steps
I0718 06:35:50.107630 18260 authenticatee.cpp:259] Received SASL authentication step
I0718 06:35:50.107770 18274 authenticator.cpp:232] Received SASL authentication step
I0718 06:35:50.107806 18274 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2dfcf722f334' server FQDN: '2dfcf722f334' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0718 06:35:50.107825 18274 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0718 06:35:50.107872 18274 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0718 06:35:50.107897 18274 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2dfcf722f334' server FQDN: '2dfcf722f334' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0718 06:35:50.107911 18274 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0718 06:35:50.107919 18274 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0718 06:35:50.107936 18274 authenticator.cpp:318] Authentication success
I0718 06:35:50.108047 18264 authenticatee.cpp:299] Authentication success
I0718 06:35:50.108144 18257 master.cpp:10610] Successfully authenticated principal 'test-principal' at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.108250 18279 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2068)@172.17.0.2:42893
I0718 06:35:50.108518 18280 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:42893
I0718 06:35:50.108549 18280 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:42893
I0718 06:35:50.108745 18280 sched.cpp:870] Will retry registration in 699.506857ms if necessary
I0718 06:35:50.108958 18271 master.cpp:2908] Received SUBSCRIBE call for framework 'default' at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.109004 18271 master.cpp:2240] Authorizing framework principal 'test-principal' to receive offers for roles '{ storage/default-role }'
I0718 06:35:50.109678 18259 master.cpp:2995] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0718 06:35:50.112325 18259 master.cpp:10808] Adding framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 with roles { } suppressed
I0718 06:35:50.112905 18259 sched.cpp:751] Framework registered with f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.112958 18259 sched.cpp:770] Scheduler::registered took 25522ns
I0718 06:35:50.113319 18270 hierarchical.cpp:368] Added framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.114655 18270 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.189537ms
I0718 06:35:50.115185 18267 master.cpp:10393] Sending offers [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O0 ] to framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.115813 18272 sched.cpp:934] Scheduler::resourceOffers took 124289ns
I0718 06:35:50.116174 18272 master.cpp:6222] Processing DECLINE call for offers: [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O0 ] for framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 with 5 seconds filter
I0718 06:35:50.116768 18272 master.cpp:12685] Removing offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O0
I0718 06:35:50.117504 18266 hierarchical.cpp:1218] Recovered cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.117584 18266 hierarchical.cpp:1264] Framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:50.158517 18275 provider.cpp:2145] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' and 0 operations to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.158982 18257 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.160059 18269 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.200642 18261 http.cpp:1115] HTTP POST for /slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.201333 18262 manager.cpp:1039] Received UPDATE_STATE call with resources '[{"disk":{"source":{"profile":"test","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"ab871185-944c-426f-96fa-c6831d8cca77"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]' and 0 operations from resource provider ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:50.201990 18276 slave.cpp:8406] Handling resource provider message 'UPDATE_STATE: ab871185-944c-426f-96fa-c6831d8cca77 disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0718 06:35:50.202152 18276 slave.cpp:8526] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048
I0718 06:35:50.204303 18258 hierarchical.cpp:710] Agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 (2dfcf722f334) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048
I0718 06:35:50.205917 18258 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.416548ms
I0718 06:35:50.206583 18270 master.cpp:10393] Sending offers [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O1 ] to framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.207168 18267 sched.cpp:934] Scheduler::resourceOffers took 80757ns
I0718 06:35:50.213413 18275 hierarchical.cpp:1508] Performed allocation for 1 agents in 256217ns
I0718 06:35:50.213567 18257 master.cpp:12685] Removing offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O1
I0718 06:35:50.214010 18257 master.cpp:4739] Processing ACCEPT call for offers: [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O1 ] on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334) for framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.214113 18257 master.cpp:4112] Authorizing principal 'test-principal' to create a MOUNT disk from 'disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0718 06:35:50.215229 18269 master.cpp:6014] Processing CREATE_DISK operation with source disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048 from framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:50.215819 18269 master.cpp:12576] Sending operation '' (uuid: fa3040be-761c-48af-8744-eeacd859c2b1) to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:50.216156 18279 hierarchical.cpp:1432] Allocation paused
I0718 06:35:50.216315 18268 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:50.217308 18279 hierarchical.cpp:1218] Recovered ports(allocated: storage/default-role):[31000-32000]; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048, allocated: disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.217403 18279 hierarchical.cpp:1264] Framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:50.217617 18279 hierarchical.cpp:1442] Allocation resumed
I0718 06:35:50.218603 18277 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:50.218650 18277 provider.cpp:1295] Received CREATE_DISK operation '' (uuid: fa3040be-761c-48af-8744-eeacd859c2b1)
I0718 06:35:50.264605 18270 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.264715 18270 hierarchical.cpp:1508] Performed allocation for 1 agents in 721700ns
I0718 06:35:50.267459 18267 v1_volume_manager.cpp:292] Creating volume with name 'fa3040be-761c-48af-8744-eeacd859c2b1'
I0718 06:35:50.269886 32271 test_csi_plugin.cpp:922] CreateVolumeRequest '{"name":"fa3040be-761c-48af-8744-eeacd859c2b1","capacityRange":{"requiredBytes":"2147483648","limitBytes":"2147483648"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0718 06:35:50.316169 18274 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.316279 18274 hierarchical.cpp:1508] Performed allocation for 1 agents in 450001ns
I0718 06:35:50.352061 18264 provider.cpp:1597] Applying conversion from 'disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to 'disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048' for operation (uuid: fa3040be-761c-48af-8744-eeacd859c2b1)
I0718 06:35:50.367465 18269 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.367585 18269 hierarchical.cpp:1508] Performed allocation for 1 agents in 436515ns
I0718 06:35:50.402191 18280 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: c1e2518c-b64f-4d8d-adbd-33f804348ec5) for operation UUID fa3040be-761c-48af-8744-eeacd859c2b1 of framework 'f44b3929-d9b5-487c-bc8a-9166548ec65c-0000' on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.402269 18280 status_update_manager_process.hpp:414] Creating operation status update stream fa3040be-761c-48af-8744-eeacd859c2b1 checkpoint=true
I0718 06:35:50.402807 18280 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: c1e2518c-b64f-4d8d-adbd-33f804348ec5) for operation UUID fa3040be-761c-48af-8744-eeacd859c2b1 of framework 'f44b3929-d9b5-487c-bc8a-9166548ec65c-0000' on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.419173 18271 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.419293 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 444662ns
I0718 06:35:50.469071 18280 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: c1e2518c-b64f-4d8d-adbd-33f804348ec5) for operation UUID fa3040be-761c-48af-8744-eeacd859c2b1 of framework 'f44b3929-d9b5-487c-bc8a-9166548ec65c-0000' on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.469879 18279 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.470650 18276 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for role storage/default-role of framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.470762 18276 hierarchical.cpp:1508] Performed allocation for 1 agents in 430674ns
I0718 06:35:50.470855 18273 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.509068 18266 http.cpp:1115] HTTP POST for /slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.510097 18260 slave.cpp:8406] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: fa3040be-761c-48af-8744-eeacd859c2b1) for framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0718 06:35:50.510287 18260 slave.cpp:8859] Updating the state of operation with no ID (uuid: fa3040be-761c-48af-8744-eeacd859c2b1) for framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:50.510596 18260 slave.cpp:8613] Forwarding status update of operation with no ID (operation_uuid: fa3040be-761c-48af-8744-eeacd859c2b1) for framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.510973 18278 master.cpp:12232] Updating the state of operation '' (uuid: fa3040be-761c-48af-8744-eeacd859c2b1) for framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:50.512049 18269 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:50.512818 18275 hierarchical.cpp:956] Updated allocation of framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048 to disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048
I0718 06:35:50.513881 18276 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:50.513953 18275 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048, allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.514142 18259 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: c1e2518c-b64f-4d8d-adbd-33f804348ec5) for stream fa3040be-761c-48af-8744-eeacd859c2b1
I0718 06:35:50.514245 18259 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: c1e2518c-b64f-4d8d-adbd-33f804348ec5) for operation UUID fa3040be-761c-48af-8744-eeacd859c2b1 of framework 'f44b3929-d9b5-487c-bc8a-9166548ec65c-0000' on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.523241 18270 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.624642ms
I0718 06:35:50.524140 18277 master.cpp:10393] Sending offers [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O2 ] to framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.525131 18272 sched.cpp:934] Scheduler::resourceOffers took 184138ns
I0718 06:35:50.529074 18278 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0718 06:35:50.530931 18263 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:52630
I0718 06:35:50.531266 18263 http.cpp:263] Processing call RESERVE_RESOURCES
I0718 06:35:50.532136 18263 master.cpp:3824] Authorizing principal 'test-principal' to reserve resources 'disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048'
I0718 06:35:50.534296 18275 master.cpp:12685] Removing offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O2
I0718 06:35:50.534413 18270 sched.cpp:960] Rescinded offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O2
I0718 06:35:50.534502 18270 sched.cpp:971] Scheduler::offerRescinded took 25607ns
I0718 06:35:50.535185 18258 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048, allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.535307 18258 hierarchical.cpp:1264] Framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:50.538084 18277 master.cpp:12576] Sending operation '' (uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c) to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:50.538652 18277 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:50.541456 18279 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:50.541501 18279 provider.cpp:1295] Received RESERVE operation '' (uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c)
I0718 06:35:50.594462 18259 status_update_manager_process.hpp:490] Cleaning up operation status update stream fa3040be-761c-48af-8744-eeacd859c2b1
I0718 06:35:50.662050 18261 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 20c2d345-e373-497d-a205-0d157a4444f4) for operation UUID dacd81f2-2272-4c62-9dfb-906d9e6d751c on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.662115 18261 status_update_manager_process.hpp:414] Creating operation status update stream dacd81f2-2272-4c62-9dfb-906d9e6d751c checkpoint=true
I0718 06:35:50.662621 18261 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 20c2d345-e373-497d-a205-0d157a4444f4) for operation UUID dacd81f2-2272-4c62-9dfb-906d9e6d751c on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.737598 18261 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 20c2d345-e373-497d-a205-0d157a4444f4) for operation UUID dacd81f2-2272-4c62-9dfb-906d9e6d751c on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.738670 18273 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.739692 18275 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.743198 18258 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.649531ms
I0718 06:35:50.744285 18266 master.cpp:10393] Sending offers [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O3 ] to framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.745348 18272 sched.cpp:934] Scheduler::resourceOffers took 130355ns
I0718 06:35:50.748872 18260 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0718 06:35:50.750543 18271 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:52632
I0718 06:35:50.750867 18271 http.cpp:263] Processing call CREATE_VOLUMES
I0718 06:35:50.751615 18271 master.cpp:3951] Authorizing principal 'test-principal' to create volumes '[{"disk":{"persistence":{"id":"6a9a0667-d9f8-4259-96f2-5bbca5a04aa9","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"},"volume":{"container_path":"volume","mode":"RW"}},"name":"disk","provider_id":{"value":"ab871185-944c-426f-96fa-c6831d8cca77"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0718 06:35:50.753542 18262 master.cpp:12685] Removing offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O3
I0718 06:35:50.753687 18261 sched.cpp:960] Rescinded offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O3
I0718 06:35:50.753769 18261 sched.cpp:971] Scheduler::offerRescinded took 29139ns
I0718 06:35:50.754274 18279 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048, allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework f44b3929-d9b5-48
7c-bc8a-9166548ec65c-0000
I0718 06:35:50.754384 18279 hierarchical.cpp:1264] Framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:50.756850 18263 master.cpp:12576] Sending operation '' (uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444) to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:50.757478 18275 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:50.760519 18264 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:50.760560 18264 provider.cpp:1295] Received CREATE operation '' (uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444)
I0718 06:35:50.767174 18268 master.cpp:6415] Processing REVIVE call for framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.767566 18271 hierarchical.cpp:1365] Unsuppressed offers for roles { storage/default-role } of framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.767611 18271 hierarchical.cpp:1387] Revived roles { storage/default-role } of framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:50.769394 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.63964ms
I0718 06:35:50.769804 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 196524ns
I0718 06:35:50.770030 18259 master.cpp:10393] Sending offers [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O4 ] to framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:50.770589 18261 sched.cpp:934] Scheduler::resourceOffers took 75638ns
I0718 06:35:50.780107 18270 http.cpp:1115] HTTP POST for /slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.780961 18275 slave.cpp:8406] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0718 06:35:50.781131 18275 slave.cpp:8859] Updating the state of operation with no ID (uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:50.781180 18275 slave.cpp:8613] Forwarding status update of operation with no ID (operation_uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c) for an operator API call
I0718 06:35:50.781606 18275 master.cpp:12232] Updating the state of operation '' (uuid: dacd81f2-2272-4c62-9dfb-906d9e6d751c) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:50.782094 18277 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:50.863780 18261 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for operation UUID ed2820e5-b8f8-4fef-bf2d-cd9862689444 on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.863840 18261 status_update_manager_process.hpp:414] Creating operation status update stream ed2820e5-b8f8-4fef-bf2d-cd9862689444 checkpoint=true
I0718 06:35:50.863894 18264 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:50.864187 18261 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for operation UUID ed2820e5-b8f8-4fef-bf2d-cd9862689444 on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.930743 18261 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for operation UUID ed2820e5-b8f8-4fef-bf2d-cd9862689444 on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.931201 18261 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 20c2d345-e373-497d-a205-0d157a4444f4) for stream dacd81f2-2272-4c62-9dfb-906d9e6d751c
I0718 06:35:50.931270 18261 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 20c2d345-e373-497d-a205-0d157a4444f4) for operation UUID dacd81f2-2272-4c62-9dfb-906d9e6d751c on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:50.931699 18279 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:50.932663 18263 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:50.972216 18260 http.cpp:1115] HTTP POST for /slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:50.973232 18257 slave.cpp:8406] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0718 06:35:50.973431 18257 slave.cpp:8859] Updating the state of operation with no ID (uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:50.973480 18257 slave.cpp:8613] Forwarding status update of operation with no ID (operation_uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444) for an operator API call
I0718 06:35:50.973817 18265 master.cpp:12232] Updating the state of operation '' (uuid: ed2820e5-b8f8-4fef-bf2d-cd9862689444) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:50.974344 18278 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:50.975754 18273 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:51.006047 18261 status_update_manager_process.hpp:490] Cleaning up operation status update stream dacd81f2-2272-4c62-9dfb-906d9e6d751c
I0718 06:35:51.006266 18261 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for stream ed2820e5-b8f8-4fef-bf2d-cd9862689444
I0718 06:35:51.006338 18261 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: c6cd61e3-ac86-468a-ae8a-d5fa66e47f63) for operation UUID ed2820e5-b8f8-4fef-bf2d-cd9862689444 on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.098153 18261 status_update_manager_process.hpp:490] Cleaning up operation status update stream ed2820e5-b8f8-4fef-bf2d-cd9862689444
I0718 06:35:51.161433 18275 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0718 06:35:51.163033 18265 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:52634
I0718 06:35:51.163265 18265 http.cpp:263] Processing call DESTROY_VOLUMES
I0718 06:35:51.164084 18265 master.cpp:3996] Authorizing principal 'test-principal' to destroy volumes '[{"disk":{"persistence":{"id":"6a9a0667-d9f8-4259-96f2-5bbca5a04aa9","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"},"volume":{"container_path":"volume","mode":"RW"}},"name":"disk","provider_id":{"value":"ab871185-944c-426f-96fa-c6831d8cca77"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0718 06:35:51.166194 18274 master.cpp:12685] Removing offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O4
I0718 06:35:51.166357 18264 sched.cpp:960] Rescinded offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O4
I0718 06:35:51.166435 18264 sched.cpp:971] Scheduler::offerRescinded took 23141ns
I0718 06:35:51.167208 18278 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test),6a9a0667-d9f8-4259-96f2-5bbca5a04aa9:volume]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test),6a9a0667-d9f8-4259-96f2-5bbca5a04aa9:volume]:2048, allocat
ed: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:51.167332 18278 hierarchical.cpp:1264] Framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:51.170236 18259 master.cpp:12576] Sending operation '' (uuid: 499f8347-5392-492a-a035-c566bba26aea) to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:51.170778 18276 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:51.173758 18267 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:51.173802 18267 provider.cpp:1295] Received DESTROY operation '' (uuid: 499f8347-5392-492a-a035-c566bba26aea)
I0718 06:35:51.181913 18277 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.179524ms
I0718 06:35:51.182560 18268 master.cpp:10393] Sending offers [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O5 ] to framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.183188 18265 sched.cpp:934] Scheduler::resourceOffers took 72338ns
I0718 06:35:51.275490 18280 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for operation UUID 499f8347-5392-492a-a035-c566bba26aea on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.275544 18280 status_update_manager_process.hpp:414] Creating operation status update stream 499f8347-5392-492a-a035-c566bba26aea checkpoint=true
I0718 06:35:51.275964 18280 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for operation UUID 499f8347-5392-492a-a035-c566bba26aea on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.342371 18280 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for operation UUID 499f8347-5392-492a-a035-c566bba26aea on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.343181 18264 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:51.344146 18262 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:51.347077 18279 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0718 06:35:51.348814 18275 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:52636
I0718 06:35:51.349077 18275 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0718 06:35:51.349648 18275 master.cpp:3888] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"ab871185-944c-426f-96fa-c6831d8cca77"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0718 06:35:51.351526 18272 master.cpp:12685] Removing offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O5
I0718 06:35:51.351651 18268 sched.cpp:960] Rescinded offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O5
I0718 06:35:51.351732 18268 sched.cpp:971] Scheduler::offerRescinded took 21680ns
I0718 06:35:51.352244 18277 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048, allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework f44b3929-d9b5-48
7c-bc8a-9166548ec65c-0000
I0718 06:35:51.352366 18277 hierarchical.cpp:1264] Framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 filtered agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 for 5secs
I0718 06:35:51.354652 18265 master.cpp:12576] Sending operation '' (uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd) to agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:51.355171 18264 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:51.358350 18266 provider.cpp:481] Received APPLY_OPERATION event
I0718 06:35:51.358391 18266 provider.cpp:1295] Received UNRESERVE operation '' (uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd)
I0718 06:35:51.358405 18259 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.704417ms
I0718 06:35:51.359061 18270 master.cpp:10393] Sending offers [ f44b3929-d9b5-487c-bc8a-9166548ec65c-O6 ] to framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.359689 18258 sched.cpp:934] Scheduler::resourceOffers took 76087ns
I0718 06:35:51.384219 18265 http.cpp:1115] HTTP POST for /slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:51.385090 18274 slave.cpp:8406] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 499f8347-5392-492a-a035-c566bba26aea) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0718 06:35:51.385257 18274 slave.cpp:8859] Updating the state of operation with no ID (uuid: 499f8347-5392-492a-a035-c566bba26aea) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:51.385306 18274 slave.cpp:8613] Forwarding status update of operation with no ID (operation_uuid: 499f8347-5392-492a-a035-c566bba26aea) for an operator API call
I0718 06:35:51.385601 18278 master.cpp:12232] Updating the state of operation '' (uuid: 499f8347-5392-492a-a035-c566bba26aea) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:51.386101 18263 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:51.460168 18258 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 1df98887-f366-4fb6-b294-9c299319e7fb) for operation UUID 06e3fec6-c318-4e9f-8df9-0437b262e2fd on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.460234 18258 status_update_manager_process.hpp:414] Creating operation status update stream 06e3fec6-c318-4e9f-8df9-0437b262e2fd checkpoint=true
I0718 06:35:51.460268 18266 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:51.460696 18258 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 1df98887-f366-4fb6-b294-9c299319e7fb) for operation UUID 06e3fec6-c318-4e9f-8df9-0437b262e2fd on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.527329 18258 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 1df98887-f366-4fb6-b294-9c299319e7fb) for operation UUID 06e3fec6-c318-4e9f-8df9-0437b262e2fd on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.528153 18258 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for stream 499f8347-5392-492a-a035-c566bba26aea
I0718 06:35:51.528301 18258 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: a8b8e3d9-4c78-4529-8ef5-5d1f448a25da) for operation UUID 499f8347-5392-492a-a035-c566bba26aea on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.528995 18268 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:51.530483 18277 process.cpp:3671] Handling HTTP event for process 'slave(1217)' with path: '/slave(1217)/api/v1/resource_provider'
I0718 06:35:51.569037 18278 http.cpp:1115] HTTP POST for /slave(1217)/api/v1/resource_provider from 172.17.0.2:52626
I0718 06:35:51.570623 18271 slave.cpp:8406] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0718 06:35:51.570964 18271 slave.cpp:8859] Updating the state of operation with no ID (uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0718 06:35:51.571045 18271 slave.cpp:8613] Forwarding status update of operation with no ID (operation_uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd) for an operator API call
I0718 06:35:51.571611 18279 master.cpp:12232] Updating the state of operation '' (uuid: 06e3fec6-c318-4e9f-8df9-0437b262e2fd) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0718 06:35:51.572477 18273 slave.cpp:4335] Ignoring new checkpointed resources and operations identical to the current version
I0718 06:35:51.574707 18267 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0718 06:35:51.593834 18258 status_update_manager_process.hpp:490] Cleaning up operation status update stream 499f8347-5392-492a-a035-c566bba26aea
I0718 06:35:51.594085 18258 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 1df98887-f366-4fb6-b294-9c299319e7fb) for stream 06e3fec6-c318-4e9f-8df9-0437b262e2fd
I0718 06:35:51.594157 18258 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 1df98887-f366-4fb6-b294-9c299319e7fb) for operation UUID 06e3fec6-c318-4e9f-8df9-0437b262e2fd on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.677593 18258 status_update_manager_process.hpp:490] Cleaning up operation status update stream 06e3fec6-c318-4e9f-8df9-0437b262e2fd
I0718 06:35:51.746021 18280 master.cpp:1410] Framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 disconnected
I0718 06:35:51.746088 18280 master.cpp:3360] Deactivating framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.746747 18278 hierarchical.cpp:475] Deactivated framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:51.747520 18256 slave.cpp:914] Agent terminating
I0718 06:35:51.748178 18280 master.cpp:12685] Removing offer f44b3929-d9b5-487c-bc8a-9166548ec65c-O6
I0718 06:35:51.748332 18280 master.cpp:3337] Disconnecting framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.748487 18280 master.cpp:1425] Giving framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893 0ns to failover
I0718 06:35:51.748567 18256 manager.cpp:163] Terminating resource provider ab871185-944c-426f-96fa-c6831d8cca77
I0718 06:35:51.749410 18265 master.cpp:10185] Framework failover timeout, removing framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
I0718 06:35:51.749460 18265 master.cpp:11184] Removing framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000 (default) at scheduler-5aacbd68-8dc8-4548-b09a-598cd9c43aea@172.17.0.2:42893
E0718 06:35:51.749918 18263 http_connection.hpp:452] End-Of-File received
I0718 06:35:51.749842 18278 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_4PZYrs/2GB-fa3040be-761c-48af-8744-eeacd859c2b1,test)]:2048, allocated: {}) on agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 from framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:51.749959 18265 master.cpp:1295] Agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334) disconnected
I0718 06:35:51.749989 18265 master.cpp:3397] Disconnecting agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:51.750077 18265 master.cpp:3416] Deactivating agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 at slave(1217)@172.17.0.2:42893 (2dfcf722f334)
I0718 06:35:51.750087 18278 hierarchical.cpp:1432] Allocation paused
I0718 06:35:51.750622 18278 hierarchical.cpp:417] Removed framework f44b3929-d9b5-487c-bc8a-9166548ec65c-0000
I0718 06:35:51.750686 18263 http_connection.hpp:217] Re-detecting endpoint
I0718 06:35:51.750726 18278 hierarchical.cpp:1442] Allocation resumed
I0718 06:35:51.750818 18278 hierarchical.cpp:799] Agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0 deactivated
I0718 06:35:51.751314 18263 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0718 06:35:51.751423 18263 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0718 06:35:51.751483 18268 provider.cpp:471] Disconnected from resource provider manager
I0718 06:35:51.751526 18263 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:51.751689 18268 status_update_manager_process.hpp:379] Pausing operation status update manager
I0718 06:35:51.753279 18269 containerizer.cpp:2575] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0718 06:35:51.753365 18269 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING
I0718 06:35:51.753995 18269 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:51.754637 18260 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
I0718 06:35:51.755327 18268 provider.cpp:459] Connected to resource provider manager
I0718 06:35:51.755766 18276 hierarchical.cpp:1508] Performed allocation for 1 agents in 314032ns
I0718 06:35:51.756248 18257 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:42893/slave(1217)/api/v1/resource_provider
E0718 06:35:51.757019 18257 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Cannot process 'SUBSCRIBE' call as the driver is in state SUBSCRIBING
I0718 06:35:51.757030 18281 process.cpp:2781] Returning '404 Not Found' for '/slave(1217)/api/v1/resource_provider'
E0718 06:35:51.758173 18263 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0718 06:35:51.807391 18258 hierarchical.cpp:1508] Performed allocation for 1 agents in 230887ns
I0718 06:35:51.857656 18264 containerizer.cpp:3116] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0718 06:35:51.858829 18271 hierarchical.cpp:1508] Performed allocation for 1 agents in 171471ns
I0718 06:35:51.859256 18261 provisioner.cpp:611] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:51.861692 18267 container_daemon.cpp:189] Invoking post-stop hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:51.861867 18267 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-h4Grme/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0718 06:35:51.862133 18274 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0718 06:35:51.864620 18281 process.cpp:2781] Returning '404 Not Found' for '/slave(1217)/api/v1'
I0718 06:35:51.882784 18256 master.cpp:1135] Master terminating
I0718 06:35:51.883532 18267 hierarchical.cpp:775] Removed all filters for agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
I0718 06:35:51.883556 18267 hierarchical.cpp:650] Removed agent f44b3929-d9b5-487c-bc8a-9166548ec65c-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2413 ms)
[----------] 50 tests from CSIVersion/StorageLocalResourceProviderTest (92617 ms total)
[----------] Global test environment tear-down
[==========] 2285 tests from 216 test cases ran. (1119127 ms total)
[ PASSED ] 2284 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] MasterQuotaTest.RescindOffersEnforcingLimits
1 FAILED TEST
YOU HAVE 31 DISABLED TESTS
I0718 06:35:52.002019 18281 process.cpp:935] Stopped the socket accept loop
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-1.9.0/_build'
make: *** [distcheck] Error 1
+ docker rmi --force mesos-1563425573-3280
Untagged: mesos-1563425573-3280:latest
Deleted: sha256:546562f5cce8e09b5a716dfd8a4361c45610b3958b40436c8c30276b47e3bf44
Deleted: sha256:c20594c891010db7b3917f9020fbacc60ae0df324de0a9dc2f2eeaaeabaf1bf1
Deleted: sha256:487151d833d3fa6117e464dfd573f4ca1047438f7343a3d14bea1f5d4740e84f
Deleted: sha256:05d02b964096d746847751222973b1ed9aea73d3ccafa844a920f65869eb50a7
Deleted: sha256:d7d39dc3e707cfc993c915b36304366570326da70a316e2dc28d89b81b65a632
Deleted: sha256:be7708a84c1aae092b08d31fb88759de1ba86645903d7f891f4905b6cd0dc0f1
Deleted: sha256:7a982db81134ab3aebeb59fae010e3ec56f7389739634a47147168c45ca1503d
Deleted: sha256:dec3ca3b8b2d5a340ad991d66c5b3102d5e027c3ffe7a1488272179ff3833edb
Deleted: sha256:b0b02e16c0fe1ada7bf5ba34eec77b63cca3eb673e81e51a0a4a8c2512b9f097
Deleted: sha256:f3c5a53b817a96f2c4a90fd400b81875aec38ec812da39c4e8495652713906d7
Deleted: sha256:3547e653b58dae97f05fba274be08646b47804cb15fbcdb5b60ba881d8b57467
Deleted: sha256:2f9ea2b35a050f1cf6f6581bf6518a66d66cfc56a1fda049e31c5ebfc3fe849f
Deleted: sha256:5e90bad7101bde57928d70f92203f8d3e92b8d712d68057fc850ffa292f566a2
Deleted: sha256:f92887612961e8f2cc27f380f2cd956d6e950da4d7f5fb63ccd68d239487c015
Deleted: sha256:52ca4b32e99828cdb63444aea326cbef29826bd2b89b2b7aa0597b23dd66504b
Deleted: sha256:b217b90e0a05ad8ca33196f8ce977223f53f035adabd6b73cc969831b3698b14
Deleted: sha256:6611a7eb38464c1bb8aed2cf32fa411196c213297a3eb2fec39d93615918133a
Deleted: sha256:748e143689a7c8de494296de8289a08d2c0aeb69a9d592cdf93e952214362a1d
Deleted: sha256:a32e211a7b4cd59ee04160a667da96d311235a985eee9db196a123a79db13283
Deleted: sha256:8ba4ea030d64025b8940970894ad1a81ed999362bfdb9ff0684392eadf018e07
Deleted: sha256:dac6718f792dca8df075b14a39fe174d2115dc4537adbde57608bb670b22f0e4
Deleted: sha256:c9904f99f34eeaec632bcfedd7f16a6ce18c3f8662c2c13106e5579bfdf29e5c
Deleted: sha256:6a45bb833a4e4d466155d722d4cae807411a1374c7763ca25fecb7ccb24a9171
Deleted: sha256:541fd8b1a323ee6bd8d5020ae00ac68767dfe732ff188027eba3c0bd7abc4aa5
Deleted: sha256:c0daf28be9a0f7f4a873144d7b27025713684199443d0cba4aba971867557b62
Deleted: sha256:43acd7175d4acbced855dad4851ae64003b81dde13ac9d6f5d3abae77e4bdde7
Deleted: sha256:f5dc98c1630cab32bedb5aa2c3996b776286f56ab0398a4c7a96bf6e52fd305a
Deleted: sha256:c47811592c5d78ac7e4b506097da9e07ca85b424954a04fc18b13ac86eb65072
Deleted: sha256:2409426bf17e9e3e84263c24411fb1f401ecb306d2585ec5d473801e17ea7c12
Deleted: sha256:ae65454464eda51b40b34c0cc0e170c158446675aafd725a4a594c8132c9e452
Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/2613/console
- Mesos Reviewbot
On July 18, 2019, 10 a.m., Meng Zhu wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71111/
> -----------------------------------------------------------
>
> (Updated July 18, 2019, 10 a.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-9812
> https://issues.apache.org/jira/browse/MESOS-9812
>
>
> Repository: mesos
>
>
> Description
> -------
>
> Outstanding offers need to be rescinded as needed to ensure
> roles' requested guarantees can be satisfied.
>
> For simplicity, and also due to the race between the master and
> the allocator, we pessimistically assume that what seems like
> "available" resources in the allocator are all gone. We greedily
> rescind offers until we can satisfy the guarantees.
>
> Also added a test.
>
>
> Diffs
> -----
>
> src/master/quota_handler.cpp 2a3ca5640c850ec8a8aca7abed45386b5b5e1125
> src/tests/master_quota_tests.cpp 64a9b31a38af23fb16a4afd04f6d3413c7d1ffe9
>
>
> Diff: https://reviews.apache.org/r/71111/diff/1/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Meng Zhu
>
>