You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@mesos.apache.org by Andrei Sekretenko <as...@apache.org> on 2020/10/12 20:15:24 UTC
Review Request 72956: Added validation that offer constraints are set
only for existing roles.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72956/
-----------------------------------------------------------
Review request for mesos and Benjamin Mahler.
Bugs: MESOS-10176
https://issues.apache.org/jira/browse/MESOS-10176
Repository: mesos
Description
-------
This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that
the framework does not specify offer constraints for roles to which
it is not going to be subscribed.
Diffs
-----
src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188
src/tests/master/update_framework_tests.cpp 3f86573e8dfeea63fe99064f2137c61d901f4fc7
Diff: https://reviews.apache.org/r/72956/diff/1/
Testing
-------
Thanks,
Andrei Sekretenko
Re: Review Request 72956: Added validation that offer constraints are
set only for existing roles.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72956/#review222028
-----------------------------------------------------------
Patch looks great!
Reviews applied: [72955, 72956]
Passed command: export OS='ubuntu:16.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/jenkins/buildbot.sh
- Mesos Reviewbot
On Oct. 12, 2020, 10:15 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72956/
> -----------------------------------------------------------
>
> (Updated Oct. 12, 2020, 10:15 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-10176
> https://issues.apache.org/jira/browse/MESOS-10176
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that
> the framework does not specify offer constraints for roles to which
> it is not going to be subscribed.
>
>
> Diffs
> -----
>
> src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188
> src/tests/master/update_framework_tests.cpp 3f86573e8dfeea63fe99064f2137c61d901f4fc7
>
>
> Diff: https://reviews.apache.org/r/72956/diff/1/
>
>
> Testing
> -------
>
> `make check`
> `src/mesos-tests --gtest_filter='*UpdateFrameworkTest.OfferConstraintsForUnsubscribedRole*' --gtest_break_on_failure --gtest_repeat=1000`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 72956: Added validation that offer constraints are
set only for existing roles.
Posted by Andrei Sekretenko <as...@apache.org>.
> On Oct. 14, 2020, 12:54 a.m., Benjamin Mahler wrote:
> > src/master/master.cpp
> > Line 2635 (original), 2635-2642 (patched)
> > <https://reviews.apache.org/r/72956/diff/1/?file=2240634#file2240634line2635>
> >
> > Ditto here from the last review, shouldn't this go into the validation.hpp existing stateless validation?
Tried to move this into a separate function in `validation.cpp`; not sure if this makes things better or worse.
The thing with the validation of roles in constraints is that I want to be very clear that this is orthogonal to the internal validity of `OfferConstraints`.
Hence, a stateless validation function like `validate(const FrameworkInfo&, const set<string>& suppressedRoles, const OfferConstraints&)` would look very misleading (or, it will have to do the job of the filter regexp construction just the sake of constraints validation; this will also add the regex construction options to the signature).
One more alternative would be to take the whole `createAllocatorFrameworkOptions()` out of `master.cpp`, which will make it unit-testable.
- Andrei
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72956/#review222040
-----------------------------------------------------------
On Oct. 14, 2020, 8:18 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72956/
> -----------------------------------------------------------
>
> (Updated Oct. 14, 2020, 8:18 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-10176
> https://issues.apache.org/jira/browse/MESOS-10176
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that
> the framework does not specify offer constraints for roles to which
> it is not going to be subscribed.
>
>
> Diffs
> -----
>
> src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188
> src/master/validation.hpp 7fe8f087b322f8e77218f4dd9f9f75707afa3208
> src/master/validation.cpp 5b1bcb5207aac0553bf9c1a0d89525c835393ccb
> src/tests/master/update_framework_tests.cpp 3f86573e8dfeea63fe99064f2137c61d901f4fc7
>
>
> Diff: https://reviews.apache.org/r/72956/diff/2/
>
>
> Testing
> -------
>
> `make check`
> `src/mesos-tests --gtest_filter='*UpdateFrameworkTest.OfferConstraintsForUnsubscribedRole*' --gtest_break_on_failure --gtest_repeat=1000`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 72956: Added validation that offer constraints are
set only for existing roles.
Posted by Benjamin Mahler <bm...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72956/#review222040
-----------------------------------------------------------
src/master/master.cpp
Line 2635 (original), 2635-2642 (patched)
<https://reviews.apache.org/r/72956/#comment311110>
Ditto here from the last review, shouldn't this go into the validation.hpp existing stateless validation?
- Benjamin Mahler
On Oct. 12, 2020, 8:15 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72956/
> -----------------------------------------------------------
>
> (Updated Oct. 12, 2020, 8:15 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-10176
> https://issues.apache.org/jira/browse/MESOS-10176
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that
> the framework does not specify offer constraints for roles to which
> it is not going to be subscribed.
>
>
> Diffs
> -----
>
> src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188
> src/tests/master/update_framework_tests.cpp 3f86573e8dfeea63fe99064f2137c61d901f4fc7
>
>
> Diff: https://reviews.apache.org/r/72956/diff/1/
>
>
> Testing
> -------
>
> `make check`
> `src/mesos-tests --gtest_filter='*UpdateFrameworkTest.OfferConstraintsForUnsubscribedRole*' --gtest_break_on_failure --gtest_repeat=1000`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 72956: Added validation that offer constraints are
set only for existing roles.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72956/#review222057
-----------------------------------------------------------
Bad review!
Reviews applied: [72956, 72955, 72964]
Error:
2020-10-14 20:16:21 URL:https://reviews.apache.org/r/72956/diff/raw/ [5923/5923] -> "72956.patch" [1]
error: patch failed: src/master/validation.hpp:134
error: src/master/validation.hpp: patch does not apply
- Mesos Reviewbot
On Oct. 14, 2020, 6:18 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72956/
> -----------------------------------------------------------
>
> (Updated Oct. 14, 2020, 6:18 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-10176
> https://issues.apache.org/jira/browse/MESOS-10176
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that
> the framework does not specify offer constraints for roles to which
> it is not going to be subscribed.
>
>
> Diffs
> -----
>
> src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188
> src/master/validation.hpp 7fe8f087b322f8e77218f4dd9f9f75707afa3208
> src/master/validation.cpp 5b1bcb5207aac0553bf9c1a0d89525c835393ccb
> src/tests/master/update_framework_tests.cpp 3f86573e8dfeea63fe99064f2137c61d901f4fc7
>
>
> Diff: https://reviews.apache.org/r/72956/diff/2/
>
>
> Testing
> -------
>
> `make check`
> `src/mesos-tests --gtest_filter='*UpdateFrameworkTest.OfferConstraintsForUnsubscribedRole*' --gtest_break_on_failure --gtest_repeat=1000`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 72956: Added validation that offer constraints are
set only for existing roles.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72956/#review222133
-----------------------------------------------------------
Bad patch!
Reviews applied: [72964, 72955, 72956]
Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:16.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/jenkins/buildbot.sh 2>&1 | tee build_72956"]
Error:
...<truncated>...
or process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider'
I1027 22:21:59.412524 4164 hierarchical.cpp:1953] Performed allocation for 1 agents in 1.524917ms
I1027 22:21:59.413250 4169 master.cpp:9580] Sending offers [ 67d3d7f7-102e-4a76-bfce-e64091d7e007-O3 ] to framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707
I1027 22:21:59.413980 4181 sched.cpp:937] Scheduler::resourceOffers took 99231ns
I1027 22:21:59.417760 4175 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I1027 22:21:59.419952 4174 http.cpp:1436] HTTP POST for /master/api/v1 from 172.17.0.2:44026
I1027 22:21:59.420287 4174 http.cpp:277] Processing call CREATE_VOLUMES
I1027 22:21:59.421416 4174 master.cpp:3795] Authorizing principal 'test-principal' to perform action CREATE_VOLUME on object {"value":"storage/default-role","resource":{"provider_id":{"value":"a0f4fd23-7a1e-48c6-9058-cf7bf61d4bde"},"name":"disk","type":"SCALAR","scalar":{"value":2048.0},"reservations":[{"type":"DYNAMIC","role":"storage"},{"type":"DYNAMIC","role":"storage/default-role","principal":"test-principal"}],"disk":{"persistence":{"id":"a4d8a0ad-ca5e-4edd-900b-ec712c7ac155","principal":"test-principal"},"volume":{"mode":"RW","container_path":"volume"},"source":{"type":"MOUNT","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"vendor":"org.apache.mesos.csi.test.local","id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891","profile":"test"}}}}
I1027 22:21:59.423686 4171 sched.cpp:963] Rescinded offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O3
I1027 22:21:59.423812 4171 sched.cpp:974] Scheduler::offerRescinded took 31015ns
I1027 22:21:59.424187 4182 hierarchical.cpp:1676] Recovered ports(allocated: storage/default-role):[31000-32000]; 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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test)]:2048; 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),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test)]:2048, offered or allocated: {}) on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 from framework 67d3d
7f7-102e-4a76-bfce-e64091d7e007-0000
I1027 22:21:59.424618 4167 master.cpp:11879] Removing offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O3
I1027 22:21:59.426604 4182 hierarchical.cpp:1725] Framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 filtered agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 for 5secs
I1027 22:21:59.429592 4177 master.cpp:11744] Sending operation '' (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) to agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca)
I1027 22:21:59.430387 4169 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version
I1027 22:21:59.434455 4165 provider.cpp:498] Received APPLY_OPERATION event
I1027 22:21:59.434523 4165 provider.cpp:1352] Received CREATE operation '' (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad)
I1027 22:21:59.435726 4162 master.cpp:5623] Processing REVIVE call for framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707
I1027 22:21:59.436305 4173 hierarchical.cpp:1821] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000
I1027 22:21:59.438428 4173 hierarchical.cpp:1953] Performed allocation for 1 agents in 1.769894ms
I1027 22:21:59.438925 4173 hierarchical.cpp:1953] Performed allocation for 1 agents in 181270ns
I1027 22:21:59.439420 4171 master.cpp:9580] Sending offers [ 67d3d7f7-102e-4a76-bfce-e64091d7e007-O4 ] to framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707
I1027 22:21:59.440446 4167 sched.cpp:937] Scheduler::resourceOffers took 118458ns
I1027 22:21:59.453526 4179 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:44020
I1027 22:21:59.455102 4176 slave.cpp:8733] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 0f6710b6-e104-4b56-8e67-4c39e7579154) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I1027 22:21:59.455387 4176 slave.cpp:9186] Updating the state of operation with no ID (uuid: 0f6710b6-e104-4b56-8e67-4c39e7579154) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I1027 22:21:59.455458 4176 slave.cpp:8940] Forwarding status update of operation with no ID (operation_uuid: 0f6710b6-e104-4b56-8e67-4c39e7579154) for an operator API call
I1027 22:21:59.455878 4169 master.cpp:11396] Updating the state of operation '' (uuid: 0f6710b6-e104-4b56-8e67-4c39e7579154) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I1027 22:21:59.456435 4172 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version
I1027 22:21:59.612226 4165 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I1027 22:21:59.612180 4167 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for operation UUID e650afe9-c7c0-4285-9dd9-969175eca9ad on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:21:59.612315 4167 status_update_manager_process.hpp:414] Creating operation status update stream e650afe9-c7c0-4285-9dd9-969175eca9ad checkpoint=true
I1027 22:21:59.612658 4167 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for operation UUID e650afe9-c7c0-4285-9dd9-969175eca9ad on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:21:59.720906 4167 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for operation UUID e650afe9-c7c0-4285-9dd9-969175eca9ad on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:21:59.721508 4167 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 5f499b26-6d5a-4322-8a07-907d830b599a) for stream 0f6710b6-e104-4b56-8e67-4c39e7579154
I1027 22:21:59.721585 4167 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 5f499b26-6d5a-4322-8a07-907d830b599a) for operation UUID 0f6710b6-e104-4b56-8e67-4c39e7579154 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:21:59.722259 4163 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider
I1027 22:21:59.723935 4181 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider'
I1027 22:21:59.765915 4175 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:44020
I1027 22:21:59.767163 4172 slave.cpp:8733] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I1027 22:21:59.767416 4172 slave.cpp:9186] Updating the state of operation with no ID (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I1027 22:21:59.767472 4172 slave.cpp:8940] Forwarding status update of operation with no ID (operation_uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) for an operator API call
I1027 22:21:59.768021 4166 master.cpp:11396] Updating the state of operation '' (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I1027 22:21:59.768790 4170 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version
I1027 22:21:59.770588 4177 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I1027 22:21:59.805400 4167 status_update_manager_process.hpp:490] Cleaning up operation status update stream 0f6710b6-e104-4b56-8e67-4c39e7579154
I1027 22:21:59.805846 4167 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for stream e650afe9-c7c0-4285-9dd9-969175eca9ad
I1027 22:21:59.805996 4167 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for operation UUID e650afe9-c7c0-4285-9dd9-969175eca9ad on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:21:59.967684 4167 status_update_manager_process.hpp:490] Cleaning up operation status update stream e650afe9-c7c0-4285-9dd9-969175eca9ad
I1027 22:22:00.080204 4169 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I1027 22:22:00.082646 4166 http.cpp:1436] HTTP POST for /master/api/v1 from 172.17.0.2:44038
I1027 22:22:00.082973 4166 http.cpp:277] Processing call DESTROY_VOLUMES
I1027 22:22:00.084259 4166 master.cpp:3795] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"a0f4fd23-7a1e-48c6-9058-cf7bf61d4bde"},"name":"disk","type":"SCALAR","scalar":{"value":2048.0},"reservations":[{"type":"DYNAMIC","role":"storage"},{"type":"DYNAMIC","role":"storage/default-role","principal":"test-principal"}],"disk":{"persistence":{"id":"a4d8a0ad-ca5e-4edd-900b-ec712c7ac155","principal":"test-principal"},"volume":{"mode":"RW","container_path":"volume"},"source":{"type":"MOUNT","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"vendor":"org.apache.mesos.csi.test.local","id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891","profile":"test"}}}}
I1027 22:22:00.086537 4171 sched.cpp:963] Rescinded offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O4
I1027 22:22:00.086757 4171 sched.cpp:974] Scheduler::offerRescinded took 103691ns
I1027 22:22:00.087441 4174 master.cpp:11879] Removing offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O4
I1027 22:22:00.087388 4168 hierarchical.cpp:1676] Recovered ports(allocated: storage/default-role):[31000-32000]; 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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test),a4d8a0ad-ca5e-4edd-900b-ec712c7ac155:volume]:2048; 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),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test),a4d8a0ad-ca5e-4edd-900b-ec712c7ac155:volume]:2048, offered
or allocated: {}) on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 from framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000
I1027 22:22:00.090749 4168 hierarchical.cpp:1725] Framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 filtered agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 for 5secs
I1027 22:22:00.094596 4182 master.cpp:11744] Sending operation '' (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) to agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:00.095216 4182 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version
I1027 22:22:00.098735 4166 provider.cpp:498] Received APPLY_OPERATION event
I1027 22:22:00.098783 4166 provider.cpp:1352] Received DESTROY operation '' (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1)
I1027 22:22:00.100574 4183 hierarchical.cpp:1953] Performed allocation for 1 agents in 2.618455ms
I1027 22:22:00.101281 4173 master.cpp:9580] Sending offers [ 67d3d7f7-102e-4a76-bfce-e64091d7e007-O5 ] to framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707
I1027 22:22:00.102133 4171 sched.cpp:937] Scheduler::resourceOffers took 120885ns
I1027 22:22:00.201828 4174 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for operation UUID cd0bec9a-6e4e-40fb-996c-af10c13bdef1 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:22:00.201977 4174 status_update_manager_process.hpp:414] Creating operation status update stream cd0bec9a-6e4e-40fb-996c-af10c13bdef1 checkpoint=true
I1027 22:22:00.202373 4174 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for operation UUID cd0bec9a-6e4e-40fb-996c-af10c13bdef1 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:22:00.268620 4174 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for operation UUID cd0bec9a-6e4e-40fb-996c-af10c13bdef1 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:22:00.269913 4165 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider
I1027 22:22:00.271453 4167 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider'
I1027 22:22:00.276281 4177 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I1027 22:22:00.278448 4175 http.cpp:1436] HTTP POST for /master/api/v1 from 172.17.0.2:44040
I1027 22:22:00.278779 4175 http.cpp:277] Processing call UNRESERVE_RESOURCES
I1027 22:22:00.280036 4175 master.cpp:3795] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"a0f4fd23-7a1e-48c6-9058-cf7bf61d4bde"},"name":"disk","type":"SCALAR","scalar":{"value":2048.0},"reservations":[{"type":"DYNAMIC","role":"storage"},{"type":"DYNAMIC","role":"storage/default-role","principal":"test-principal"}],"disk":{"source":{"type":"MOUNT","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"vendor":"org.apache.mesos.csi.test.local","id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891","profile":"test"}}}}
I1027 22:22:00.281949 4162 sched.cpp:963] Rescinded offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O5
I1027 22:22:00.282109 4162 sched.cpp:974] Scheduler::offerRescinded took 50546ns
I1027 22:22:00.282766 4183 hierarchical.cpp:1676] Recovered ports(allocated: storage/default-role):[31000-32000]; 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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test)]:2048; 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),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test)]:2048, offered or allocated: {}) on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 from framework 67d3d
7f7-102e-4a76-bfce-e64091d7e007-0000
I1027 22:22:00.282940 4176 master.cpp:11879] Removing offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O5
I1027 22:22:00.284926 4183 hierarchical.cpp:1725] Framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 filtered agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 for 5secs
I1027 22:22:00.287570 4166 master.cpp:11744] Sending operation '' (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) to agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:00.288395 4165 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version
I1027 22:22:00.292243 4177 provider.cpp:498] Received APPLY_OPERATION event
I1027 22:22:00.292317 4177 provider.cpp:1352] Received UNRESERVE operation '' (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe)
I1027 22:22:00.297627 4175 hierarchical.cpp:1953] Performed allocation for 1 agents in 2.42387ms
I1027 22:22:00.298494 4170 master.cpp:9580] Sending offers [ 67d3d7f7-102e-4a76-bfce-e64091d7e007-O6 ] to framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707
I1027 22:22:00.299423 4184 sched.cpp:937] Scheduler::resourceOffers took 159178ns
I1027 22:22:00.313318 4166 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:44020
I1027 22:22:00.314513 4168 slave.cpp:8733] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I1027 22:22:00.314716 4168 slave.cpp:9186] Updating the state of operation with no ID (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I1027 22:22:00.314769 4168 slave.cpp:8940] Forwarding status update of operation with no ID (operation_uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) for an operator API call
I1027 22:22:00.315179 4163 master.cpp:11396] Updating the state of operation '' (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I1027 22:22:00.315788 4165 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version
I1027 22:22:00.462169 4184 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for operation UUID 1da16584-d1e3-4386-a9a1-27e6c572cebe on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:22:00.462246 4184 status_update_manager_process.hpp:414] Creating operation status update stream 1da16584-d1e3-4386-a9a1-27e6c572cebe checkpoint=true
I1027 22:22:00.462481 4177 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I1027 22:22:00.462597 4184 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for operation UUID 1da16584-d1e3-4386-a9a1-27e6c572cebe on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:22:00.554447 4184 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for operation UUID 1da16584-d1e3-4386-a9a1-27e6c572cebe on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:22:00.554857 4184 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for stream cd0bec9a-6e4e-40fb-996c-af10c13bdef1
I1027 22:22:00.554939 4184 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for operation UUID cd0bec9a-6e4e-40fb-996c-af10c13bdef1 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:22:00.555320 4176 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider
I1027 22:22:00.556428 4183 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider'
I1027 22:22:00.601179 4165 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:44020
I1027 22:22:00.602291 4179 slave.cpp:8733] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I1027 22:22:00.602684 4179 slave.cpp:9186] Updating the state of operation with no ID (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I1027 22:22:00.602757 4179 slave.cpp:8940] Forwarding status update of operation with no ID (operation_uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) for an operator API call
I1027 22:22:00.603193 4178 master.cpp:11396] Updating the state of operation '' (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I1027 22:22:00.603778 4185 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version
I1027 22:22:00.605388 4171 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I1027 22:22:00.638206 4184 status_update_manager_process.hpp:490] Cleaning up operation status update stream cd0bec9a-6e4e-40fb-996c-af10c13bdef1
I1027 22:22:00.638445 4184 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for stream 1da16584-d1e3-4386-a9a1-27e6c572cebe
I1027 22:22:00.638523 4184 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for operation UUID 1da16584-d1e3-4386-a9a1-27e6c572cebe on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:22:00.747154 4184 status_update_manager_process.hpp:490] Cleaning up operation status update stream 1da16584-d1e3-4386-a9a1-27e6c572cebe
I1027 22:22:00.865804 4181 master.cpp:1416] Framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707 disconnected
I1027 22:22:00.865854 4181 master.cpp:3428] Deactivating framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707
I1027 22:22:00.866282 4163 hierarchical.cpp:902] Deactivated framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000
I1027 22:22:00.866811 4163 hierarchical.cpp:1676] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test)]:2048; 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)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test)]:2048, offered or allocated: {}) on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 from framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000
I1027 22:22:00.866925 4181 master.cpp:11879] Removing offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O6
I1027 22:22:00.867043 4181 master.cpp:3412] Disconnecting framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707
I1027 22:22:00.867173 4178 slave.cpp:1002] Agent terminating
I1027 22:22:00.867252 4181 master.cpp:1431] Giving framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707 0ns to failover
I1027 22:22:00.868203 4178 manager.cpp:127] Terminating resource provider a0f4fd23-7a1e-48c6-9058-cf7bf61d4bde
I1027 22:22:00.868628 4174 master.cpp:1301] Agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca) disconnected
I1027 22:22:00.868665 4174 master.cpp:3463] Disconnecting agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:00.868753 4174 master.cpp:3482] Deactivating agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:00.868990 4174 master.cpp:9364] Framework failover timeout, removing framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707
I1027 22:22:00.869035 4174 master.cpp:10375] Removing framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at scheduler-73e40063-b39d-41dd-a601-7b4e64c41a44@172.17.0.2:38707
E1027 22:22:00.869415 4179 http_connection.hpp:449] End-Of-File received
I1027 22:22:00.869663 4163 hierarchical.cpp:1256] Agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 deactivated
I1027 22:22:00.869719 4163 hierarchical.cpp:1877] Allocation paused
I1027 22:22:00.869957 4179 http_connection.hpp:217] Re-detecting endpoint
I1027 22:22:00.870350 4163 hierarchical.cpp:846] Removed framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000
I1027 22:22:00.870421 4163 hierarchical.cpp:1887] Allocation resumed
I1027 22:22:00.870460 4179 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I1027 22:22:00.870544 4179 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I1027 22:22:00.870642 4179 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider
I1027 22:22:00.870723 4183 provider.cpp:488] Disconnected from resource provider manager
I1027 22:22:00.870883 4171 status_update_manager_process.hpp:379] Pausing operation status update manager
I1027 22:22:00.872409 4185 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I1027 22:22:00.872480 4185 containerizer.cpp:3414] 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 after 3.658390144secs
I1027 22:22:00.872956 4185 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:00.874639 4169 hierarchical.cpp:1953] Performed allocation for 1 agents in 206849ns
I1027 22:22:00.874852 4175 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider
I1027 22:22:00.875638 4173 provider.cpp:476] Connected to resource provider manager
I1027 22:22:00.876456 4177 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider
I1027 22:22:00.877408 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1248)/api/v1/resource_provider'
E1027 22:22:00.878964 4180 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I1027 22:22:00.926450 4184 hierarchical.cpp:1953] Performed allocation for 1 agents in 308058ns
I1027 22:22:00.976565 4170 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I1027 22:22:00.978138 4169 hierarchical.cpp:1953] Performed allocation for 1 agents in 240284ns
I1027 22:22:00.978746 4183 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:00.981992 4172 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'
I1027 22:22:00.982364 4174 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-FiGDBq/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:00.982722 4164 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:00.986685 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1248)/api/v1'
I1027 22:22:00.999568 4161 master.cpp:1149] Master terminating
I1027 22:22:01.000471 4177 hierarchical.cpp:1232] Removed all filters for agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
I1027 22:22:01.000528 4177 hierarchical.cpp:1108] Removed agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (3547 ms)
[ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v0
I1027 22:22:01.018968 4161 cluster.cpp:195] Creating default 'local' authorizer
I1027 22:22:01.024662 4163 master.cpp:448] Master 2e0ec788-b347-4e29-8371-3a9f359e84ac (01d434b599ca) started on 172.17.0.2:38707
I1027 22:22:01.024700 4163 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --allocator_agent_recovery_factor="0.8" --allocator_recovery_timeout="10mins" --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/zb8n9j/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_
unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.12.0/_inst/share/mesos/webui" --work_dir="/tmp/zb8n9j/master" --zk_session_timeout="10secs"
I1027 22:22:01.025372 4163 master.cpp:500] Master only allowing authenticated frameworks to register
I1027 22:22:01.025395 4163 master.cpp:506] Master only allowing authenticated agents to register
I1027 22:22:01.025416 4163 master.cpp:512] Master only allowing authenticated HTTP frameworks to register
I1027 22:22:01.025436 4163 credentials.hpp:37] Loading credentials for authentication from '/tmp/zb8n9j/credentials'
I1027 22:22:01.026286 4163 master.cpp:556] Using default 'crammd5' authenticator
I1027 22:22:01.026599 4163 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I1027 22:22:01.026855 4163 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I1027 22:22:01.027052 4163 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I1027 22:22:01.027235 4163 master.cpp:637] Authorization enabled
I1027 22:22:01.027681 4178 whitelist_watcher.cpp:77] No whitelist given
I1027 22:22:01.027819 4167 hierarchical.cpp:656] Initialized hierarchical allocator process
I1027 22:22:01.031508 4173 master.cpp:2174] Elected as the leading master!
I1027 22:22:01.031553 4173 master.cpp:1670] Recovering from registrar
I1027 22:22:01.031788 4185 registrar.cpp:339] Recovering registrar
I1027 22:22:01.032675 4185 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I1027 22:22:01.032852 4185 registrar.cpp:487] Applied 1 operations in 53191ns; attempting to update the registry
I1027 22:22:01.033653 4185 registrar.cpp:544] Successfully updated the registry in 0ns
I1027 22:22:01.033829 4185 registrar.cpp:416] Successfully recovered registrar
I1027 22:22:01.034605 4174 hierarchical.cpp:695] Skipping recovery of hierarchical allocator: nothing to recover
I1027 22:22:01.034639 4162 master.cpp:1823] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
W1027 22:22:01.041569 4161 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:38707
I1027 22:22:01.042424 4161 resolver.cpp:69] Creating default secret resolver
I1027 22:22:01.043359 4161 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W1027 22:22:01.044153 4161 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W1027 22:22:01.044186 4161 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W1027 22:22:01.044206 4161 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I1027 22:22:01.044245 4161 provisioner.cpp:294] Using default backend 'copy'
I1027 22:22:01.047405 4161 cluster.cpp:620] Creating default 'local' authorizer
I1027 22:22:01.050335 4169 slave.cpp:281] Mesos agent started on (1249)@172.17.0.2:38707
I1027 22:22:01.050369 4169 slave.cpp:282] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/zb8n9j/JMNS9U/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/zb8n9j/JMNS9U/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/zb8n9j/JMNS9U/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/zb8n9j/JMNS9U/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/zb8n9j/JMNS9U/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/zb8n9j/JMNS9U/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posi
x" --launcher_dir="/tmp/SRC/build/mesos-1.12.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/zb8n9j/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_Update_v0_BianTL" --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_StorageLoca
lResourceProviderTest_Update_v0_hm8RCC" --zk_session_timeout="10secs"
I1027 22:22:01.050940 4169 credentials.hpp:73] Loading credential for authentication from '/tmp/zb8n9j/JMNS9U/credential'
I1027 22:22:01.051164 4169 slave.cpp:314] Agent using credential for: test-principal
I1027 22:22:01.051213 4169 credentials.hpp:37] Loading credentials for authentication from '/tmp/zb8n9j/JMNS9U/http_credentials'
I1027 22:22:01.051476 4169 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I1027 22:22:01.052033 4169 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I1027 22:22:01.053933 4177 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I1027 22:22:01.053894 4169 slave.cpp:629] 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"}]
I1027 22:22:01.054149 4169 slave.cpp:637] Agent attributes: [ ]
I1027 22:22:01.054172 4169 slave.cpp:646] Agent hostname: 01d434b599ca
I1027 22:22:01.054443 4179 task_status_update_manager.cpp:181] Pausing sending task status updates
I1027 22:22:01.054508 4184 status_update_manager_process.hpp:379] Pausing operation status update manager
I1027 22:22:01.054690 4176 hierarchical.cpp:1953] Performed allocation for 0 agents in 82125ns
I1027 22:22:01.056529 4172 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/meta'
I1027 22:22:01.056843 4164 slave.cpp:7742] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/meta', beginning agent recovery
I1027 22:22:01.057611 4165 task_status_update_manager.cpp:207] Recovering task status update manager
I1027 22:22:01.058221 4185 containerizer.cpp:830] Recovering Mesos containers
I1027 22:22:01.058723 4185 containerizer.cpp:1170] Recovering isolators
I1027 22:22:01.060046 4177 containerizer.cpp:1209] Recovering provisioner
I1027 22:22:01.061256 4176 provisioner.cpp:518] Provisioner recovery complete
I1027 22:22:01.062294 4174 composing.cpp:343] Finished recovering all containerizers
I1027 22:22:01.062711 4175 slave.cpp:8224] Recovering executors
I1027 22:22:01.062886 4175 slave.cpp:8377] Finished recovery
I1027 22:22:01.063971 4167 task_status_update_manager.cpp:181] Pausing sending task status updates
I1027 22:22:01.064052 4170 status_update_manager_process.hpp:379] Pausing operation status update manager
I1027 22:22:01.064064 4178 slave.cpp:1473] New master detected at master@172.17.0.2:38707
I1027 22:22:01.064255 4178 slave.cpp:1538] Detecting new master
I1027 22:22:01.065577 4181 slave.cpp:1565] Authenticating with master master@172.17.0.2:38707
I1027 22:22:01.065709 4181 slave.cpp:1574] Using default CRAM-MD5 authenticatee
I1027 22:22:01.066166 4177 authenticatee.cpp:121] Creating new client SASL connection
I1027 22:22:01.066572 4179 master.cpp:9771] Authenticating slave(1249)@172.17.0.2:38707
I1027 22:22:01.066857 4184 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2113)@172.17.0.2:38707
I1027 22:22:01.067315 4173 authenticator.cpp:98] Creating new server SASL connection
I1027 22:22:01.067672 4176 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1027 22:22:01.067737 4176 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1027 22:22:01.067934 4176 authenticator.cpp:204] Received SASL authentication start
I1027 22:22:01.068038 4176 authenticator.cpp:326] Authentication requires more steps
I1027 22:22:01.068235 4164 authenticatee.cpp:259] Received SASL authentication step
I1027 22:22:01.068429 4165 authenticator.cpp:232] Received SASL authentication step
I1027 22:22:01.068487 4165 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '01d434b599ca' server FQDN: '01d434b599ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1027 22:22:01.068531 4165 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1027 22:22:01.068620 4165 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1027 22:22:01.068671 4165 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '01d434b599ca' server FQDN: '01d434b599ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1027 22:22:01.068709 4165 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1027 22:22:01.068742 4165 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1027 22:22:01.068791 4165 authenticator.cpp:318] Authentication success
I1027 22:22:01.068945 4172 authenticatee.cpp:299] Authentication success
I1027 22:22:01.069141 4166 master.cpp:9803] Successfully authenticated principal 'test-principal' at slave(1249)@172.17.0.2:38707
I1027 22:22:01.069217 4171 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2113)@172.17.0.2:38707
I1027 22:22:01.069698 4182 slave.cpp:1665] Successfully authenticated with master master@172.17.0.2:38707
I1027 22:22:01.070506 4182 slave.cpp:2131] Will retry registration in 5.880334ms if necessary
I1027 22:22:01.070739 4162 master.cpp:6264] Received register agent message from slave(1249)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:01.071344 4162 master.cpp:3795] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I1027 22:22:01.072221 4185 master.cpp:6331] Authorized registration of agent at slave(1249)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:01.072376 4185 master.cpp:6443] Registering agent at slave(1249)@172.17.0.2:38707 (01d434b599ca) with id 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0
I1027 22:22:01.073371 4181 registrar.cpp:487] Applied 1 operations in 371983ns; attempting to update the registry
I1027 22:22:01.074404 4181 registrar.cpp:544] Successfully updated the registry in 928768ns
I1027 22:22:01.074668 4173 master.cpp:6491] Admitted agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:01.075825 4173 master.cpp:6536] Registered agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I1027 22:22:01.075963 4176 slave.cpp:1698] Registered with master master@172.17.0.2:38707; given agent ID 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0
I1027 22:22:01.076045 4164 hierarchical.cpp:1059] Added agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 (01d434b599ca) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
I1027 22:22:01.076154 4166 task_status_update_manager.cpp:188] Resuming sending task status updates
I1027 22:22:01.076472 4164 hierarchical.cpp:1953] Performed allocation for 1 agents in 179682ns
I1027 22:22:01.076660 4176 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/meta/slaves/2e0ec788-b347-4e29-8371-3a9f359e84ac-S0/slave.info'
I1027 22:22:01.076781 4165 status_update_manager_process.hpp:385] Resuming operation status update manager
I1027 22:22:01.078475 4176 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"APCn5LmaRuOhn44j4f1BBg=="},"slave_id":{"value":"2e0ec788-b347-4e29-8371-3a9f359e84ac-S0"},"update_oversubscribed_resources":false}
I1027 22:22:01.079442 4182 master.cpp:7679] Ignoring update on agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca) as it reports no changes
I1027 22:22:01.085672 4184 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1'
I1027 22:22:01.087497 4164 http.cpp:1436] HTTP POST for /slave(1249)/api/v1 from 172.17.0.2:44054
I1027 22:22:01.088093 4164 http.cpp:2828] Processing GET_CONTAINERS call
I1027 22:22:01.095993 4169 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:01.099715 4174 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1'
I1027 22:22:01.101327 4176 http.cpp:1436] HTTP POST for /slave(1249)/api/v1 from 172.17.0.2:44056
I1027 22:22:01.102375 4176 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:01.103921 4172 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:01.105260 4163 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:01.106206 4182 hierarchical.cpp:1953] Performed allocation for 1 agents in 220712ns
I1027 22:22:01.106266 4163 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 438272ns
I1027 22:22:01.107491 4163 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_BianTL/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I1027 22:22:01.107594 4163 containerizer.cpp:3414] 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 after 1.32992ms
I1027 22:22:01.112208 4169 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_3k6nmt","--available_capacity=0B","--volumes=","--forward=unix:///tmp/zb8n9j/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/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-iZj3Cw/endpoint.sock"},{"name":"MESOS_AGENT_ID","type":"VALUE","value":"2e0ec788-b347-4e29-8371-3a9f359e84ac-S0"}]},"task_environment":{},"working
_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="111" --pipe_write="112" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_BianTL/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I1027 22:22:01.128119 4169 launcher.cpp:145] Forked child with pid '18792' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:01.129097 4169 containerizer.cpp:3414] 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 after 21.516032ms
I1027 22:22:01.130980 4176 containerizer.cpp:3414] 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 after 1.76384ms
I1027 22:22:01.131527 4183 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_Update_v0_hm8RCC/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:01.133123 4172 containerizer.cpp:3414] 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 after 2.192896ms
I1027 22:22:01.136818 4171 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'
I1027 22:22:01.137077 4178 service_manager.cpp:795] Connecting to endpoint 'unix:///tmp/mesos-csi-iZj3Cw/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:01.158336 4174 hierarchical.cpp:1953] Performed allocation for 1 agents in 348297ns
I1027 22:22:01.209789 4180 hierarchical.cpp:1953] Performed allocation for 1 agents in 166699ns
I1027 22:22:01.261633 4167 hierarchical.cpp:1953] Performed allocation for 1 agents in 176268ns
I1027 22:22:01.312912 4168 hierarchical.cpp:1953] Performed allocation for 1 agents in 158790ns
I1027 22:22:01.364362 4164 hierarchical.cpp:1953] Performed allocation for 1 agents in 194514ns
I1027 22:22:01.416148 4182 hierarchical.cpp:1953] Performed allocation for 1 agents in 240635ns
I1027 22:22:01.467301 4179 hierarchical.cpp:1953] Performed allocation for 1 agents in 230869ns
I1027 22:22:01.519119 4173 hierarchical.cpp:1953] Performed allocation for 1 agents in 268694ns
I1027 22:22:01.570282 4176 hierarchical.cpp:1953] Performed allocation for 1 agents in 204993ns
I1027 22:22:01.585103 4162 service_manager.cpp:622] Probing endpoint 'unix:///tmp/mesos-csi-iZj3Cw/endpoint.sock' with CSI v1
I1027 22:22:01.588333 4185 service_manager.cpp:609] Probing endpoint 'unix:///tmp/mesos-csi-iZj3Cw/endpoint.sock' with CSI v0
I1027 22:22:01.589629 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Identity/Probe call
I1027 22:22:01.592864 4171 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:01.596361 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Identity/GetPluginCapabilities call
I1027 22:22:01.597700 4166 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1'
I1027 22:22:01.599530 4162 http.cpp:1436] HTTP POST for /slave(1249)/api/v1 from 172.17.0.2:44058
I1027 22:22:01.600229 4162 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:01.601894 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Identity/GetPluginInfo call
I1027 22:22:01.602250 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Identity/GetPluginInfo call
I1027 22:22:01.604629 4181 v0_volume_manager.cpp:656] NODE_SERVICE loaded: {}
I1027 22:22:01.605506 4181 v0_volume_manager.cpp:656] CONTROLLER_SERVICE loaded: {}
I1027 22:22:01.608222 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/ControllerGetCapabilities call
I1027 22:22:01.613160 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Node/NodeGetCapabilities call
I1027 22:22:01.617990 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Node/NodeGetId call
I1027 22:22:01.621397 4168 provider.cpp:677] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I1027 22:22:01.621649 4184 status_update_manager_process.hpp:379] Pausing operation status update manager
I1027 22:22:01.622139 4163 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider
I1027 22:22:01.622280 4179 hierarchical.cpp:1953] Performed allocation for 1 agents in 260614ns
I1027 22:22:01.627043 4170 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider
I1027 22:22:01.628113 4172 provider.cpp:476] Connected to resource provider manager
I1027 22:22:01.629168 4182 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider
I1027 22:22:01.630913 4169 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider'
I1027 22:22:01.633514 4179 http.cpp:1436] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:44062
I1027 22:22:01.634582 4178 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_3k6nmt","--available_capacity=0B","--volumes=","--forward=unix:///tmp/zb8n9j/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}
I1027 22:22:01.673678 4176 hierarchical.cpp:1953] Performed allocation for 1 agents in 198885ns
I1027 22:22:01.692338 4183 slave.cpp:8733] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"5d0f7f0a-5571-436c-ad32-00c6b25cef81"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_3k6nmt","--available_capacity=0B","--volumes=","--forward=unix:///tmp/zb8n9j/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}'
I1027 22:22:01.694782 4171 provider.cpp:498] Received SUBSCRIBED event
I1027 22:22:01.694847 4171 provider.cpp:1310] Subscribed with ID 5d0f7f0a-5571-436c-ad32-00c6b25cef81
I1027 22:22:01.696148 4179 status_update_manager_process.hpp:314] Recovering operation status update manager
I1027 22:22:01.725701 4163 hierarchical.cpp:1953] Performed allocation for 1 agents in 196029ns
I1027 22:22:01.777526 4173 hierarchical.cpp:1953] Performed allocation for 1 agents in 179426ns
I1027 22:22:01.825809 4178 provider.cpp:791] Reconciling storage pools and volumes
I1027 22:22:01.828955 4175 hierarchical.cpp:1953] Performed allocation for 1 agents in 236966ns
I1027 22:22:01.829205 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/ListVolumes call
I1027 22:22:01.833452 4168 provider.cpp:2218] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0
I1027 22:22:01.833904 4179 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider
I1027 22:22:01.833992 4168 provider.cpp:749] Resource provider 5d0f7f0a-5571-436c-ad32-00c6b25cef81 is in READY state
I1027 22:22:01.834097 4163 status_update_manager_process.hpp:385] Resuming operation status update manager
I1027 22:22:01.835078 4166 provider.cpp:1236] Updating profiles { test } for resource provider 5d0f7f0a-5571-436c-ad32-00c6b25cef81
I1027 22:22:01.835590 4176 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider'
I1027 22:22:01.837074 4182 provider.cpp:791] Reconciling storage pools and volumes
I1027 22:22:01.838527 4171 http.cpp:1436] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:44060
I1027 22:22:01.839448 4179 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 5d0f7f0a-5571-436c-ad32-00c6b25cef81
I1027 22:22:01.839846 4164 slave.cpp:8733] Handling resource provider message 'UPDATE_STATE: 5d0f7f0a-5571-436c-ad32-00c6b25cef81 {}'
I1027 22:22:01.839951 4164 slave.cpp:8853] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I1027 22:22:01.840185 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/ListVolumes call
I1027 22:22:01.840570 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/GetCapacity call
I1027 22:22:01.841958 4167 hierarchical.cpp:1210] Grew agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 by {} (total), { } (used)
I1027 22:22:01.842475 4167 hierarchical.cpp:1167] Agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 (01d434b599ca) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I1027 22:22:01.848054 4164 hierarchical.cpp:1953] Performed allocation for 1 agents in 174315ns
I1027 22:22:01.848747 4176 provider.cpp:791] Reconciling storage pools and volumes
I1027 22:22:01.851475 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/ListVolumes call
I1027 22:22:01.851958 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/GetCapacity call
I1027 22:22:01.862438 4165 slave.cpp:1002] Agent terminating
I1027 22:22:01.863360 4165 manager.cpp:127] Terminating resource provider 5d0f7f0a-5571-436c-ad32-00c6b25cef81
I1027 22:22:01.864092 4185 master.cpp:1301] Agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca) disconnected
I1027 22:22:01.864130 4185 master.cpp:3463] Disconnecting agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:01.864209 4185 master.cpp:3482] Deactivating agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:01.864398 4163 hierarchical.cpp:1256] Agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 deactivated
E1027 22:22:01.864652 4173 http_connection.hpp:449] End-Of-File received
I1027 22:22:01.865160 4173 http_connection.hpp:217] Re-detecting endpoint
I1027 22:22:01.865659 4173 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I1027 22:22:01.865710 4173 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I1027 22:22:01.865777 4167 provider.cpp:488] Disconnected from resource provider manager
I1027 22:22:01.865810 4173 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider
I1027 22:22:01.865887 4167 status_update_manager_process.hpp:379] Pausing operation status update manager
I1027 22:22:01.867311 4166 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I1027 22:22:01.867383 4166 containerizer.cpp:3414] 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 after 15.73433728secs
I1027 22:22:01.867969 4166 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:01.869261 4175 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider
I1027 22:22:01.870036 4162 provider.cpp:476] Connected to resource provider manager
I1027 22:22:01.870910 4167 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider
I1027 22:22:01.872042 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1/resource_provider'
E1027 22:22:01.873749 4182 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I1027 22:22:01.893637 4165 hierarchical.cpp:1953] Performed allocation for 1 agents in 138328ns
I1027 22:22:01.944320 4181 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I1027 22:22:01.944399 4178 hierarchical.cpp:1953] Performed allocation for 1 agents in 135464ns
I1027 22:22:01.946596 4183 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:01.950111 4185 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'
I1027 22:22:01.950392 4168 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-iZj3Cw/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:01.950759 4180 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:01.955013 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1'
I1027 22:22:01.968307 4161 master.cpp:1149] Master terminating
I1027 22:22:01.968688 4177 hierarchical.cpp:1232] Removed all filters for agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0
I1027 22:22:01.968716 4177 hierarchical.cpp:1108] Removed agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (965 ms)
[ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v1
I1027 22:22:01.985546 4161 cluster.cpp:195] Creating default 'local' authorizer
I1027 22:22:01.991154 4173 master.cpp:448] Master 7980836c-504b-4b03-80d6-019861211e08 (01d434b599ca) started on 172.17.0.2:38707
I1027 22:22:01.991185 4173 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --allocator_agent_recovery_factor="0.8" --allocator_recovery_timeout="10mins" --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/yNXvzu/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_
unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.12.0/_inst/share/mesos/webui" --work_dir="/tmp/yNXvzu/master" --zk_session_timeout="10secs"
I1027 22:22:01.991639 4173 master.cpp:500] Master only allowing authenticated frameworks to register
I1027 22:22:01.991674 4173 master.cpp:506] Master only allowing authenticated agents to register
I1027 22:22:01.991694 4173 master.cpp:512] Master only allowing authenticated HTTP frameworks to register
I1027 22:22:01.991715 4173 credentials.hpp:37] Loading credentials for authentication from '/tmp/yNXvzu/credentials'
I1027 22:22:01.992008 4173 master.cpp:556] Using default 'crammd5' authenticator
I1027 22:22:01.992236 4173 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I1027 22:22:01.992502 4173 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I1027 22:22:01.992700 4173 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I1027 22:22:01.992904 4173 master.cpp:637] Authorization enabled
I1027 22:22:01.993363 4180 whitelist_watcher.cpp:77] No whitelist given
I1027 22:22:01.993505 4181 hierarchical.cpp:656] Initialized hierarchical allocator process
I1027 22:22:01.997114 4174 master.cpp:2174] Elected as the leading master!
I1027 22:22:01.997156 4174 master.cpp:1670] Recovering from registrar
I1027 22:22:01.997406 4166 registrar.cpp:339] Recovering registrar
I1027 22:22:01.998350 4166 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I1027 22:22:01.998517 4166 registrar.cpp:487] Applied 1 operations in 61322ns; attempting to update the registry
I1027 22:22:01.999295 4166 registrar.cpp:544] Successfully updated the registry in 0ns
I1027 22:22:01.999446 4166 registrar.cpp:416] Successfully recovered registrar
I1027 22:22:01.999967 4162 master.cpp:1823] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
I1027 22:22:02.000012 4179 hierarchical.cpp:695] Skipping recovery of hierarchical allocator: nothing to recover
W1027 22:22:02.006747 4161 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:38707
I1027 22:22:02.007606 4161 resolver.cpp:69] Creating default secret resolver
I1027 22:22:02.008528 4161 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W1027 22:22:02.009246 4161 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W1027 22:22:02.009277 4161 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W1027 22:22:02.009297 4161 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I1027 22:22:02.009335 4161 provisioner.cpp:294] Using default backend 'copy'
I1027 22:22:02.012606 4161 cluster.cpp:620] Creating default 'local' authorizer
I1027 22:22:02.015388 4178 slave.cpp:281] Mesos agent started on (1250)@172.17.0.2:38707
I1027 22:22:02.015417 4178 slave.cpp:282] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/yNXvzu/Y0jDpe/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/yNXvzu/Y0jDpe/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/yNXvzu/Y0jDpe/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/yNXvzu/Y0jDpe/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/yNXvzu/Y0jDpe/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/yNXvzu/Y0jDpe/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posi
x" --launcher_dir="/tmp/SRC/build/mesos-1.12.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/yNXvzu/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_Update_v1_FVuhW2" --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_StorageLoca
lResourceProviderTest_Update_v1_67cWsR" --zk_session_timeout="10secs"
I1027 22:22:02.016022 4178 credentials.hpp:73] Loading credential for authentication from '/tmp/yNXvzu/Y0jDpe/credential'
I1027 22:22:02.016188 4178 slave.cpp:314] Agent using credential for: test-principal
I1027 22:22:02.016214 4178 credentials.hpp:37] Loading credentials for authentication from '/tmp/yNXvzu/Y0jDpe/http_credentials'
I1027 22:22:02.016470 4178 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I1027 22:22:02.016880 4178 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I1027 22:22:02.018610 4173 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I1027 22:22:02.018667 4178 slave.cpp:629] 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"}]
I1027 22:22:02.018916 4178 slave.cpp:637] Agent attributes: [ ]
I1027 22:22:02.018935 4178 slave.cpp:646] Agent hostname: 01d434b599ca
I1027 22:22:02.019130 4174 status_update_manager_process.hpp:379] Pausing operation status update manager
I1027 22:22:02.019167 4170 task_status_update_manager.cpp:181] Pausing sending task status updates
I1027 22:22:02.021096 4177 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/meta'
I1027 22:22:02.021324 4183 slave.cpp:7742] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/meta', beginning agent recovery
I1027 22:22:02.021661 4176 hierarchical.cpp:1953] Performed allocation for 0 agents in 91869ns
I1027 22:22:02.021955 4185 task_status_update_manager.cpp:207] Recovering task status update manager
I1027 22:22:02.022380 4162 containerizer.cpp:830] Recovering Mesos containers
I1027 22:22:02.022800 4162 containerizer.cpp:1170] Recovering isolators
I1027 22:22:02.023695 4174 containerizer.cpp:1209] Recovering provisioner
I1027 22:22:02.024824 4175 provisioner.cpp:518] Provisioner recovery complete
I1027 22:22:02.026113 4185 composing.cpp:343] Finished recovering all containerizers
I1027 22:22:02.026557 4172 slave.cpp:8224] Recovering executors
I1027 22:22:02.026684 4172 slave.cpp:8377] Finished recovery
I1027 22:22:02.027788 4182 task_status_update_manager.cpp:181] Pausing sending task status updates
I1027 22:22:02.027827 4164 status_update_manager_process.hpp:379] Pausing operation status update manager
I1027 22:22:02.027873 4172 slave.cpp:1473] New master detected at master@172.17.0.2:38707
I1027 22:22:02.028046 4172 slave.cpp:1538] Detecting new master
I1027 22:22:02.030474 4165 slave.cpp:1565] Authenticating with master master@172.17.0.2:38707
I1027 22:22:02.030625 4165 slave.cpp:1574] Using default CRAM-MD5 authenticatee
I1027 22:22:02.031085 4162 authenticatee.cpp:121] Creating new client SASL connection
I1027 22:22:02.031492 4174 master.cpp:9771] Authenticating slave(1250)@172.17.0.2:38707
I1027 22:22:02.031723 4173 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2114)@172.17.0.2:38707
I1027 22:22:02.032177 4169 authenticator.cpp:98] Creating new server SASL connection
I1027 22:22:02.032495 4170 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I1027 22:22:02.032541 4170 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I1027 22:22:02.032714 4177 authenticator.cpp:204] Received SASL authentication start
I1027 22:22:02.032822 4177 authenticator.cpp:326] Authentication requires more steps
I1027 22:22:02.033025 4184 authenticatee.cpp:259] Received SASL authentication step
I1027 22:22:02.033241 4167 authenticator.cpp:232] Received SASL authentication step
I1027 22:22:02.033313 4167 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '01d434b599ca' server FQDN: '01d434b599ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1027 22:22:02.033347 4167 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1027 22:22:02.033416 4167 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1027 22:22:02.033455 4167 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '01d434b599ca' server FQDN: '01d434b599ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1027 22:22:02.033486 4167 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1027 22:22:02.033519 4167 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1027 22:22:02.033561 4167 authenticator.cpp:318] Authentication success
I1027 22:22:02.033717 4183 authenticatee.cpp:299] Authentication success
I1027 22:22:02.033879 4176 master.cpp:9803] Successfully authenticated principal 'test-principal' at slave(1250)@172.17.0.2:38707
I1027 22:22:02.033972 4171 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2114)@172.17.0.2:38707
I1027 22:22:02.034361 4178 slave.cpp:1665] Successfully authenticated with master master@172.17.0.2:38707
I1027 22:22:02.034981 4178 slave.cpp:2131] Will retry registration in 13.979823ms if necessary
I1027 22:22:02.035200 4181 master.cpp:6264] Received register agent message from slave(1250)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:02.035804 4181 master.cpp:3795] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I1027 22:22:02.036586 4163 master.cpp:6331] Authorized registration of agent at slave(1250)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:02.036767 4163 master.cpp:6443] Registering agent at slave(1250)@172.17.0.2:38707 (01d434b599ca) with id 7980836c-504b-4b03-80d6-019861211e08-S0
I1027 22:22:02.037776 4165 registrar.cpp:487] Applied 1 operations in 381365ns; attempting to update the registry
I1027 22:22:02.038763 4165 registrar.cpp:544] Successfully updated the registry in 894976ns
I1027 22:22:02.039031 4170 master.cpp:6491] Admitted agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:02.040088 4170 master.cpp:6536] Registered agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I1027 22:22:02.040189 4184 slave.cpp:1698] Registered with master master@172.17.0.2:38707; given agent ID 7980836c-504b-4b03-80d6-019861211e08-S0
I1027 22:22:02.040355 4166 task_status_update_manager.cpp:188] Resuming sending task status updates
I1027 22:22:02.040374 4177 hierarchical.cpp:1059] Added agent 7980836c-504b-4b03-80d6-019861211e08-S0 (01d434b599ca) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
I1027 22:22:02.040910 4184 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/meta/slaves/7980836c-504b-4b03-80d6-019861211e08-S0/slave.info'
I1027 22:22:02.040915 4177 hierarchical.cpp:1953] Performed allocation for 1 agents in 219053ns
I1027 22:22:02.041025 4175 status_update_manager_process.hpp:385] Resuming operation status update manager
I1027 22:22:02.042515 4184 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"sTRibVCRRhecKfpiWEy43A=="},"slave_id":{"value":"7980836c-504b-4b03-80d6-019861211e08-S0"},"update_oversubscribed_resources":false}
I1027 22:22:02.043542 4164 master.cpp:7679] Ignoring update on agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca) as it reports no changes
I1027 22:22:02.049405 4165 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1'
I1027 22:22:02.051185 4175 http.cpp:1436] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:44074
I1027 22:22:02.052012 4175 http.cpp:2828] Processing GET_CONTAINERS call
I1027 22:22:02.060914 4162 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:02.064894 4170 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1'
I1027 22:22:02.066435 4168 http.cpp:1436] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:44076
I1027 22:22:02.067682 4168 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:02.069453 4180 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:02.070626 4179 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:02.071810 4179 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 516096ns
I1027 22:22:02.073230 4179 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_FVuhW2/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I1027 22:22:02.073323 4179 containerizer.cpp:3414] 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 after 1.517824ms
I1027 22:22:02.073562 4181 hierarchical.cpp:1953] Performed allocation for 1 agents in 255936ns
I1027 22:22:02.078480 4162 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_xeWBZF","--available_capacity=0B","--volumes=","--forward=unix:///tmp/yNXvzu/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/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-Z9PGHY/endpoint.sock"},{"name":"MESOS_AGENT_ID","type":"VALUE","value":"7980836c-504b-4b03-80d6-019861211e08-S0"}]},"task_environment":{},"working
_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="111" --pipe_write="112" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_FVuhW2/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I1027 22:22:02.093708 4162 launcher.cpp:145] Forked child with pid '18806' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:02.094727 4162 containerizer.cpp:3414] 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 after 21.398272ms
I1027 22:22:02.096310 4162 containerizer.cpp:3414] 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 after 1.583872ms
I1027 22:22:02.096722 4184 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_Update_v1_67cWsR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:02.097929 4172 containerizer.cpp:3414] 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 after 1.554944ms
I1027 22:22:02.101649 4173 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'
I1027 22:22:02.101938 4163 service_manager.cpp:795] Connecting to endpoint 'unix:///tmp/mesos-csi-Z9PGHY/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:02.125177 4183 hierarchical.cpp:1953] Performed allocation for 1 agents in 266487ns
I1027 22:22:02.176331 4184 hierarchical.cpp:1953] Performed allocation for 1 agents in 218030ns
I1027 22:22:02.227741 4180 hierarchical.cpp:1953] Performed allocation for 1 agents in 286968ns
I1027 22:22:02.278831 4167 hierarchical.cpp:1953] Performed allocation for 1 agents in 200796ns
I1027 22:22:02.330262 4170 hierarchical.cpp:1953] Performed allocation for 1 agents in 155470ns
I1027 22:22:02.381809 4181 hierarchical.cpp:1953] Performed allocation for 1 agents in 156314ns
I1027 22:22:02.433491 4169 hierarchical.cpp:1953] Performed allocation for 1 agents in 143854ns
I1027 22:22:02.484535 4175 hierarchical.cpp:1953] Performed allocation for 1 agents in 214503ns
I1027 22:22:02.535359 4162 hierarchical.cpp:1953] Performed allocation for 1 agents in 154978ns
I1027 22:22:02.558447 4164 service_manager.cpp:622] Probing endpoint 'unix:///tmp/mesos-csi-Z9PGHY/endpoint.sock' with CSI v1
I1027 22:22:02.561594 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Identity/Probe call
I1027 22:22:02.566174 4173 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:02.570391 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Identity/GetPluginCapabilities call
I1027 22:22:02.571681 4175 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1'
I1027 22:22:02.573675 4182 http.cpp:1436] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:44088
I1027 22:22:02.574520 4182 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:02.576895 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Identity/GetPluginInfo call
I1027 22:22:02.577453 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Identity/GetPluginInfo call
I1027 22:22:02.580444 4165 v1_volume_manager.cpp:677] NODE_SERVICE loaded: {}
I1027 22:22:02.581347 4165 v1_volume_manager.cpp:677] CONTROLLER_SERVICE loaded: {}
I1027 22:22:02.584501 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
I1027 22:22:02.587445 4162 hierarchical.cpp:1953] Performed allocation for 1 agents in 225965ns
I1027 22:22:02.589948 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Node/NodeGetCapabilities call
I1027 22:22:02.595288 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Node/NodeGetInfo call
I1027 22:22:02.598826 4173 provider.cpp:677] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I1027 22:22:02.599056 4180 status_update_manager_process.hpp:379] Pausing operation status update manager
I1027 22:22:02.599706 4167 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider
I1027 22:22:02.604614 4175 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider
I1027 22:22:02.605742 4185 provider.cpp:476] Connected to resource provider manager
I1027 22:22:02.606871 4181 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider
I1027 22:22:02.608769 4164 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider'
I1027 22:22:02.611454 4173 http.cpp:1436] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:44092
I1027 22:22:02.612654 4165 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_xeWBZF","--available_capacity=0B","--volumes=","--forward=unix:///tmp/yNXvzu/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}
I1027 22:22:02.638798 4177 hierarchical.cpp:1953] Performed allocation for 1 agents in 247814ns
I1027 22:22:02.659528 4172 slave.cpp:8733] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"71d208e3-4cc5-480b-b45a-37abbb1c4ab3"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_xeWBZF","--available_capacity=0B","--volumes=","--forward=unix:///tmp/yNXvzu/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}'
I1027 22:22:02.661659 4179 provider.cpp:498] Received SUBSCRIBED event
I1027 22:22:02.661722 4179 provider.cpp:1310] Subscribed with ID 71d208e3-4cc5-480b-b45a-37abbb1c4ab3
I1027 22:22:02.662734 4173 status_update_manager_process.hpp:314] Recovering operation status update manager
I1027 22:22:02.689925 4167 hierarchical.cpp:1953] Performed allocation for 1 agents in 154682ns
I1027 22:22:02.741641 4162 hierarchical.cpp:1953] Performed allocation for 1 agents in 178510ns
I1027 22:22:02.767518 4165 provider.cpp:791] Reconciling storage pools and volumes
I1027 22:22:02.771236 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/ListVolumes call
I1027 22:22:02.775377 4180 provider.cpp:2218] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 7980836c-504b-4b03-80d6-019861211e08-S0
I1027 22:22:02.775825 4179 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider
I1027 22:22:02.776005 4180 provider.cpp:749] Resource provider 71d208e3-4cc5-480b-b45a-37abbb1c4ab3 is in READY state
I1027 22:22:02.776073 4173 status_update_manager_process.hpp:385] Resuming operation status update manager
I1027 22:22:02.777132 4162 provider.cpp:1236] Updating profiles { test } for resource provider 71d208e3-4cc5-480b-b45a-37abbb1c4ab3
I1027 22:22:02.777516 4176 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider'
I1027 22:22:02.778800 4171 provider.cpp:791] Reconciling storage pools and volumes
I1027 22:22:02.780418 4174 http.cpp:1436] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:44090
I1027 22:22:02.781188 4173 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 71d208e3-4cc5-480b-b45a-37abbb1c4ab3
I1027 22:22:02.781527 4183 slave.cpp:8733] Handling resource provider message 'UPDATE_STATE: 71d208e3-4cc5-480b-b45a-37abbb1c4ab3 {}'
I1027 22:22:02.781685 4183 slave.cpp:8853] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I1027 22:22:02.782261 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/ListVolumes call
I1027 22:22:02.783010 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/GetCapacity call
I1027 22:22:02.784294 4172 hierarchical.cpp:1210] Grew agent 7980836c-504b-4b03-80d6-019861211e08-S0 by {} (total), { } (used)
I1027 22:22:02.785245 4172 hierarchical.cpp:1167] Agent 7980836c-504b-4b03-80d6-019861211e08-S0 (01d434b599ca) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I1027 22:22:02.792011 4162 hierarchical.cpp:1953] Performed allocation for 1 agents in 305662ns
I1027 22:22:02.792286 4175 provider.cpp:791] Reconciling storage pools and volumes
I1027 22:22:02.795267 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/ListVolumes call
I1027 22:22:02.795876 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/GetCapacity call
I1027 22:22:02.806404 4162 slave.cpp:1002] Agent terminating
I1027 22:22:02.807566 4162 manager.cpp:127] Terminating resource provider 71d208e3-4cc5-480b-b45a-37abbb1c4ab3
I1027 22:22:02.808166 4164 master.cpp:1301] Agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca) disconnected
I1027 22:22:02.808228 4164 master.cpp:3463] Disconnecting agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:02.808346 4164 master.cpp:3482] Deactivating agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca)
I1027 22:22:02.808507 4166 hierarchical.cpp:1256] Agent 7980836c-504b-4b03-80d6-019861211e08-S0 deactivated
E1027 22:22:02.808842 4167 http_connection.hpp:449] End-Of-File received
I1027 22:22:02.809526 4167 http_connection.hpp:217] Re-detecting endpoint
I1027 22:22:02.810217 4167 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I1027 22:22:02.810338 4167 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I1027 22:22:02.810395 4175 provider.cpp:488] Disconnected from resource provider manager
I1027 22:22:02.810467 4167 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider
I1027 22:22:02.810632 4184 status_update_manager_process.hpp:379] Pausing operation status update manager
I1027 22:22:02.812739 4173 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I1027 22:22:02.812830 4173 containerizer.cpp:3414] 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 after 15.714965248secs
I1027 22:22:02.813417 4173 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:02.814663 4181 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider
I1027 22:22:02.815485 4182 provider.cpp:476] Connected to resource provider manager
I1027 22:22:02.816428 4177 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider
I1027 22:22:02.817514 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1/resource_provider'
E1027 22:22:02.819304 4172 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I1027 22:22:02.836248 4180 hierarchical.cpp:1953] Performed allocation for 1 agents in 144413ns
I1027 22:22:02.887215 4179 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I1027 22:22:02.887240 4174 hierarchical.cpp:1953] Performed allocation for 1 agents in 183328ns
I1027 22:22:02.889788 4175 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:02.893399 4164 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'
I1027 22:22:02.893715 4162 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-Z9PGHY/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I1027 22:22:02.894418 4174 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I1027 22:22:02.897889 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1'
I1027 22:22:02.909773 4161 master.cpp:1149] Master terminating
I1027 22:22:02.910137 4176 hierarchical.cpp:1232] Removed all filters for agent 7980836c-504b-4b03-80d6-019861211e08-S0
I1027 22:22:02.910166 4176 hierarchical.cpp:1108] Removed agent 7980836c-504b-4b03-80d6-019861211e08-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (940 ms)
[----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (130890 ms total)
[----------] Global test environment tear-down
[==========] 2340 tests from 224 test cases ran. (1435624 ms total)
[ PASSED ] 2339 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] OversubscriptionTest.FixedResourceEstimator
1 FAILED TEST
YOU HAVE 34 DISABLED TESTS
I1027 22:22:03.027797 4186 process.cpp:935] Stopped the socket accept loop
Makefile:16043: recipe for target 'check-local' failed
make[4]: *** [check-local] Error 1
make[4]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src'
Makefile:15151: recipe for target 'check-am' failed
make[3]: *** [check-am] Error 2
make[3]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src'
Makefile:15155: recipe for target 'check' failed
make[2]: *** [check] Error 2
make[2]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src'
Makefile:785: recipe for target 'check-recursive' failed
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub'
Makefile:991: recipe for target 'distcheck' failed
make: *** [distcheck] Error 1
Error response from daemon: conflict: unable to delete e895c0531b9a (cannot be forced) - image is being used by running container e54d9f77b396
Full log: https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot/1559/console
- Mesos Reviewbot
On Oct. 14, 2020, 6:18 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72956/
> -----------------------------------------------------------
>
> (Updated Oct. 14, 2020, 6:18 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-10176
> https://issues.apache.org/jira/browse/MESOS-10176
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that
> the framework does not specify offer constraints for roles to which
> it is not going to be subscribed.
>
>
> Diffs
> -----
>
> src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188
> src/master/validation.hpp 7fe8f087b322f8e77218f4dd9f9f75707afa3208
> src/master/validation.cpp 5b1bcb5207aac0553bf9c1a0d89525c835393ccb
> src/tests/master/update_framework_tests.cpp 3f86573e8dfeea63fe99064f2137c61d901f4fc7
>
>
> Diff: https://reviews.apache.org/r/72956/diff/3/
>
>
> Testing
> -------
>
> `make check`
> `src/mesos-tests --gtest_filter='*UpdateFrameworkTest.OfferConstraintsForUnsubscribedRole*' --gtest_break_on_failure --gtest_repeat=1000`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 72956: Added validation that offer constraints are
set only for existing roles.
Posted by Andrei Sekretenko <as...@apache.org>.
> On Oct. 15, 2020, 11:22 p.m., Benjamin Mahler wrote:
> > src/master/master.cpp
> > Line 2622 (original), 2622-2624 (patched)
> > <https://reviews.apache.org/r/72956/diff/2/?file=2240748#file2240748line2622>
> >
> > ```
> > Make sure the offer constraints don't use roles other than the
> > framework's roles.
> > ```
> >
> > That seems sufficient for the reader? I'm not sure they need to be explained here that you could construct a "valid" OfferConstraintsFilter with roles outside of the framework's roles
Fully agree that my previous version probably doesn't add much value. On the other hand, the shorter version still has to be kept it in sync with the code of `validateOfferConstraintsRoles()`.
Removed this comment altogether, hopefully the function name is descriptive enough.
> On Oct. 15, 2020, 11:22 p.m., Benjamin Mahler wrote:
> > src/master/validation.hpp
> > Lines 137-139 (patched)
> > <https://reviews.apache.org/r/72956/diff/2/?file=2240749#file2240749line137>
> >
> > Similar to the last review, just want to comment on how these are unit testable. In this case, I'm not sure how we could avoid the integration test though since it's not a sub-case of validation where we can just ensure in the integration test that overall validation is called.
> >
> > Still, might want to just add the simple unit test for this?
I'll probably send a follow-up patch with unit tests, for this, and also for the suppressed roles validation.
> On Oct. 15, 2020, 11:22 p.m., Benjamin Mahler wrote:
> > src/master/validation.cpp
> > Lines 706 (patched)
> > <https://reviews.apache.org/r/72956/diff/2/?file=2240750#file2240750line706>
> >
> > could just use `foreachkey (`
> >
> > ```
> > foreachkey (const string& role, offerConstraints.role_constraints()) {
> >
> > }
> > ```
Unfortunatley, there is no straightforward way to use a protobuf map with `foreachkey()`.
This macro employs `std::get<>`, which is not overloaded for protobuf's `MapPair`.
- Andrei
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72956/#review222061
-----------------------------------------------------------
On Oct. 14, 2020, 8:18 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72956/
> -----------------------------------------------------------
>
> (Updated Oct. 14, 2020, 8:18 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-10176
> https://issues.apache.org/jira/browse/MESOS-10176
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that
> the framework does not specify offer constraints for roles to which
> it is not going to be subscribed.
>
>
> Diffs
> -----
>
> src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188
> src/master/validation.hpp 7fe8f087b322f8e77218f4dd9f9f75707afa3208
> src/master/validation.cpp 5b1bcb5207aac0553bf9c1a0d89525c835393ccb
> src/tests/master/update_framework_tests.cpp 3f86573e8dfeea63fe99064f2137c61d901f4fc7
>
>
> Diff: https://reviews.apache.org/r/72956/diff/3/
>
>
> Testing
> -------
>
> `make check`
> `src/mesos-tests --gtest_filter='*UpdateFrameworkTest.OfferConstraintsForUnsubscribedRole*' --gtest_break_on_failure --gtest_repeat=1000`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 72956: Added validation that offer constraints are
set only for existing roles.
Posted by Benjamin Mahler <bm...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72956/#review222061
-----------------------------------------------------------
Ship it!
src/master/master.cpp
Line 2622 (original), 2622-2624 (patched)
<https://reviews.apache.org/r/72956/#comment311130>
```
Make sure the offer constraints don't use roles other than the
framework's roles.
```
That seems sufficient for the reader? I'm not sure they need to be explained here that you could construct a "valid" OfferConstraintsFilter with roles outside of the framework's roles
src/master/validation.hpp
Lines 137-139 (patched)
<https://reviews.apache.org/r/72956/#comment311129>
Similar to the last review, just want to comment on how these are unit testable. In this case, I'm not sure how we could avoid the integration test though since it's not a sub-case of validation where we can just ensure in the integration test that overall validation is called.
Still, might want to just add the simple unit test for this?
src/master/validation.cpp
Lines 706 (patched)
<https://reviews.apache.org/r/72956/#comment311128>
could just use `foreachkey (`
```
foreachkey (const string& role, offerConstraints.role_constraints()) {
}
```
- Benjamin Mahler
On Oct. 14, 2020, 6:18 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72956/
> -----------------------------------------------------------
>
> (Updated Oct. 14, 2020, 6:18 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-10176
> https://issues.apache.org/jira/browse/MESOS-10176
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that
> the framework does not specify offer constraints for roles to which
> it is not going to be subscribed.
>
>
> Diffs
> -----
>
> src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188
> src/master/validation.hpp 7fe8f087b322f8e77218f4dd9f9f75707afa3208
> src/master/validation.cpp 5b1bcb5207aac0553bf9c1a0d89525c835393ccb
> src/tests/master/update_framework_tests.cpp 3f86573e8dfeea63fe99064f2137c61d901f4fc7
>
>
> Diff: https://reviews.apache.org/r/72956/diff/2/
>
>
> Testing
> -------
>
> `make check`
> `src/mesos-tests --gtest_filter='*UpdateFrameworkTest.OfferConstraintsForUnsubscribedRole*' --gtest_break_on_failure --gtest_repeat=1000`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 72956: Added validation that offer constraints are
set only for existing roles.
Posted by Andrei Sekretenko <as...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72956/
-----------------------------------------------------------
(Updated Oct. 14, 2020, 8:18 p.m.)
Review request for mesos and Benjamin Mahler.
Bugs: MESOS-10176
https://issues.apache.org/jira/browse/MESOS-10176
Repository: mesos
Description
-------
This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that
the framework does not specify offer constraints for roles to which
it is not going to be subscribed.
Diffs (updated)
-----
src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188
src/master/validation.hpp 7fe8f087b322f8e77218f4dd9f9f75707afa3208
src/master/validation.cpp 5b1bcb5207aac0553bf9c1a0d89525c835393ccb
src/tests/master/update_framework_tests.cpp 3f86573e8dfeea63fe99064f2137c61d901f4fc7
Diff: https://reviews.apache.org/r/72956/diff/2/
Changes: https://reviews.apache.org/r/72956/diff/1-2/
Testing
-------
`make check`
`src/mesos-tests --gtest_filter='*UpdateFrameworkTest.OfferConstraintsForUnsubscribedRole*' --gtest_break_on_failure --gtest_repeat=1000`
Thanks,
Andrei Sekretenko