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...@mesosphere.io> on 2019/07/10 13:16:08 UTC
Review Request 71047: Added per-role suppress/revival to Java test
framework.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/
-----------------------------------------------------------
Review request for mesos and Benjamin Mahler.
Bugs: MESOS-9849
https://issues.apache.org/jira/browse/MESOS-9849
Repository: mesos
Description
-------
This patch adds exercising per-role suppress/revival to the Java test
framework to ensure that passing the corresponding arguments through the
Java bindings works.
Diffs
-----
src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
Diff: https://reviews.apache.org/r/71047/diff/1/
Testing
-------
Thanks,
Andrei Sekretenko
Re: Review Request 71047: Added unsuppressing via `updateFramework()`
to Java example framework.
Posted by Benjamin Mahler <bm...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/#review216915
-----------------------------------------------------------
Ship it!
Ship It!
- Benjamin Mahler
On July 26, 2019, 7:34 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71047/
> -----------------------------------------------------------
>
> (Updated July 26, 2019, 7:34 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-9849
> https://issues.apache.org/jira/browse/MESOS-9849
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch ensures that the list of suppressed roles is passed through
> the `updateFramework()` of Java V0 bindings. Now the framework
> subscribes with all roles suppressed and after that issues
> UPDATE_FRAMEWORK call to unsuppress offers.
>
>
> Diffs
> -----
>
> src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
>
>
> Diff: https://reviews.apache.org/r/71047/diff/4/
>
>
> Testing
> -------
>
> `./bin/mesos-tests.sh --gtest_filter="ExamplesTest.JavaFramework" --gtest_break_on_failure --gtest_repeat=5 --verbose`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 71047: Added unsuppressing via `updateFramework()`
to Java example framework.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/#review216897
-----------------------------------------------------------
Patch looks great!
Reviews applied: [71047]
Passed command: export OS='ubuntu:14.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/docker-build.sh
- Mesos Reviewbot
On July 26, 2019, 12:34 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71047/
> -----------------------------------------------------------
>
> (Updated July 26, 2019, 12:34 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-9849
> https://issues.apache.org/jira/browse/MESOS-9849
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch ensures that the list of suppressed roles is passed through
> the `updateFramework()` of Java V0 bindings. Now the framework
> subscribes with all roles suppressed and after that issues
> UPDATE_FRAMEWORK call to unsuppress offers.
>
>
> Diffs
> -----
>
> src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
>
>
> Diff: https://reviews.apache.org/r/71047/diff/4/
>
>
> Testing
> -------
>
> `./bin/mesos-tests.sh --gtest_filter="ExamplesTest.JavaFramework" --gtest_break_on_failure --gtest_repeat=5 --verbose`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 71047: Added unsuppressing via `updateFramework()`
to Java example framework.
Posted by Andrei Sekretenko <as...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/
-----------------------------------------------------------
(Updated July 26, 2019, 7:34 p.m.)
Review request for mesos and Benjamin Mahler.
Changes
-------
Removed excercising REVIVE.
Summary (updated)
-----------------
Added unsuppressing via `updateFramework()` to Java example framework.
Bugs: MESOS-9849
https://issues.apache.org/jira/browse/MESOS-9849
Repository: mesos
Description (updated)
-------
This patch ensures that the list of suppressed roles is passed through
the `updateFramework()` of Java V0 bindings. Now the framework
subscribes with all roles suppressed and after that issues
UPDATE_FRAMEWORK call to unsuppress offers.
Diffs (updated)
-----
src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
Diff: https://reviews.apache.org/r/71047/diff/4/
Changes: https://reviews.apache.org/r/71047/diff/3-4/
Testing
-------
`./bin/mesos-tests.sh --gtest_filter="ExamplesTest.JavaFramework" --gtest_break_on_failure --gtest_repeat=5 --verbose`
Thanks,
Andrei Sekretenko
Re: Review Request 71047: Added unsuppressing via `updateFramework()`
to Java example framework.
Posted by Andrei Sekretenko <as...@mesosphere.io>.
> On July 24, 2019, 3:18 p.m., Benjamin Mahler wrote:
> > The batching seems like a divergence from test_framework.py (and we'd ideally like those to be consistent), or have the java and python test frameworks already diverged? Reading through them quickly now, they seem nearly the same except at some point we added some testing of binary data in status updates to the python test framework (since it was broken and subsequently fixed).
> >
> > Could we keep them in sync? Either with the current approach from your recent test_framework.py patch, or with the batching approach in both. Personally, I think just keeping it simple and having an unsuppression during registration is enough. If we aren't ok with the manual testing for regression purposes, we can always add another test framework for both java/python that's more tailored towards suppression / unsuppression rather than trying to fit it all into the existing test.
Agreed, it's an example framework, after all, and this is becoming a bit too much for one example.
Removed suppressOffers()/revivieOffers() pair.
- Andrei
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/#review216832
-----------------------------------------------------------
On July 26, 2019, 7:34 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71047/
> -----------------------------------------------------------
>
> (Updated July 26, 2019, 7:34 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-9849
> https://issues.apache.org/jira/browse/MESOS-9849
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch ensures that the list of suppressed roles is passed through
> the `updateFramework()` of Java V0 bindings. Now the framework
> subscribes with all roles suppressed and after that issues
> UPDATE_FRAMEWORK call to unsuppress offers.
>
>
> Diffs
> -----
>
> src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
>
>
> Diff: https://reviews.apache.org/r/71047/diff/4/
>
>
> Testing
> -------
>
> `./bin/mesos-tests.sh --gtest_filter="ExamplesTest.JavaFramework" --gtest_break_on_failure --gtest_repeat=5 --verbose`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 71047: Added per-role suppress/revival to Java test
framework.
Posted by Benjamin Mahler <bm...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/#review216832
-----------------------------------------------------------
The batching seems like a divergence from test_framework.py (and we'd ideally like those to be consistent), or have the java and python test frameworks already diverged? Reading through them quickly now, they seem nearly the same except at some point we added some testing of binary data in status updates to the python test framework (since it was broken and subsequently fixed).
Could we keep them in sync? Either with the current approach from your recent test_framework.py patch, or with the batching approach in both. Personally, I think just keeping it simple and having an unsuppression during registration is enough. If we aren't ok with the manual testing for regression purposes, we can always add another test framework for both java/python that's more tailored towards suppression / unsuppression rather than trying to fit it all into the existing test.
- Benjamin Mahler
On July 16, 2019, 1:48 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71047/
> -----------------------------------------------------------
>
> (Updated July 16, 2019, 1:48 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-9849
> https://issues.apache.org/jira/browse/MESOS-9849
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds exercising per-role suppress/revival to the Java test
> framework to ensure that Java bindings pass roles lists into the
> UPDATE_FRAMEWORK and REVIVE calls.
>
>
> Diffs
> -----
>
> src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
>
>
> Diff: https://reviews.apache.org/r/71047/diff/3/
>
>
> Testing
> -------
>
> `./bin/mesos-tests.sh --gtest_filter="ExamplesTest.JavaFramework" --gtest_break_on_failure --gtest_repeat=5 --verbose`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 71047: Added per-role suppress/revival to Java test
framework.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/#review216667
-----------------------------------------------------------
Patch looks great!
Reviews applied: [71047]
Passed command: export OS='ubuntu:14.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/docker-build.sh
- Mesos Reviewbot
On July 16, 2019, 6:48 a.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71047/
> -----------------------------------------------------------
>
> (Updated July 16, 2019, 6:48 a.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-9849
> https://issues.apache.org/jira/browse/MESOS-9849
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds exercising per-role suppress/revival to the Java test
> framework to ensure that Java bindings pass roles lists into the
> UPDATE_FRAMEWORK and REVIVE calls.
>
>
> Diffs
> -----
>
> src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
>
>
> Diff: https://reviews.apache.org/r/71047/diff/3/
>
>
> Testing
> -------
>
> `./bin/mesos-tests.sh --gtest_filter="ExamplesTest.JavaFramework" --gtest_break_on_failure --gtest_repeat=5 --verbose`
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 71047: Added per-role suppress/revival to Java test
framework.
Posted by Andrei Sekretenko <as...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/
-----------------------------------------------------------
(Updated July 16, 2019, 1:48 p.m.)
Review request for mesos and Benjamin Mahler.
Changes
-------
Removed update of FrameworkInfo; made broken reviveOffers() fail the framework.
Bugs: MESOS-9849
https://issues.apache.org/jira/browse/MESOS-9849
Repository: mesos
Description (updated)
-------
This patch adds exercising per-role suppress/revival to the Java test
framework to ensure that Java bindings pass roles lists into the
UPDATE_FRAMEWORK and REVIVE calls.
Diffs (updated)
-----
src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
Diff: https://reviews.apache.org/r/71047/diff/2/
Changes: https://reviews.apache.org/r/71047/diff/1-2/
Testing
-------
Thanks,
Andrei Sekretenko
Re: Review Request 71047: Added per-role suppress/revival to Java test
framework.
Posted by Benjamin Mahler <bm...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/#review216493
-----------------------------------------------------------
Unsuppressing upon registering seems reasonable, but the suppress/revive upon TASK_FINISHED seems strange.
src/examples/java/TestFramework.java
Lines 53 (patched)
<https://reviews.apache.org/r/71047/#comment303722>
Let's just clear the suppressed roles? It looks like there's no actual assertion that the name change took place? Whereas the unsuppression is needed to get offers and launch the tasks.
src/examples/java/TestFramework.java
Lines 150-153 (patched)
<https://reviews.apache.org/r/71047/#comment303723>
This is strange, and is it even going to fail the test if these calls don't take effect properly?
- Benjamin Mahler
On July 10, 2019, 1:16 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71047/
> -----------------------------------------------------------
>
> (Updated July 10, 2019, 1:16 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-9849
> https://issues.apache.org/jira/browse/MESOS-9849
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds exercising per-role suppress/revival to the Java test
> framework to ensure that passing the corresponding arguments through the
> Java bindings works.
>
>
> Diffs
> -----
>
> src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
>
>
> Diff: https://reviews.apache.org/r/71047/diff/1/
>
>
> Testing
> -------
>
>
> Thanks,
>
> Andrei Sekretenko
>
>
Re: Review Request 71047: Added per-role suppress/revival to Java test
framework.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71047/#review216487
-----------------------------------------------------------
Bad patch!
Reviews applied: [71047]
Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:14.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/docker-build.sh 2>&1 | tee build_71047"]
Error:
...<truncated>...
us UUID: c4a37b8a-d6f4-4c32-ae99-3ddf48e8de12) for operation UUID 814d4696-73e9-4929-8797-bbc5bf7eb5be on agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0
I0710 15:54:55.127045 18278 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:44968/slave(1199)/api/v1/resource_provider
I0710 15:54:55.128481 18271 process.cpp:3671] Handling HTTP event for process 'slave(1199)' with path: '/slave(1199)/api/v1/resource_provider'
I0710 15:54:55.132359 18264 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0710 15:54:55.134366 18274 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:45566
I0710 15:54:55.134639 18274 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0710 15:54:55.135423 18274 master.cpp:3785] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_diZEs1/2GB-fb8728fd-97b6-48f0-a119-3c585c3b43dd","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"ac49acbc-1b73-421b-9599-b71c27ac1aef"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0710 15:54:55.138424 18266 master.cpp:12470] Removing offer d00b84e5-8718-46ea-940c-e286f72e8ecc-O5
I0710 15:54:55.138586 18263 sched.cpp:960] Rescinded offer d00b84e5-8718-46ea-940c-e286f72e8ecc-O5
I0710 15:54:55.138669 18263 sched.cpp:971] Scheduler::offerRescinded took 23992ns
I0710 15:54:55.139626 18277 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_diZEs1/2GB-fb8728fd-97b6-48f0-a119-3c585c3b43dd,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_diZEs1/2GB-fb8728fd-97b6-48f0-a119-3c585c3b43dd,test)]:2048, allocated: {}) on agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0 from framework d00b84e5-8718-46
ea-940c-e286f72e8ecc-0000
I0710 15:54:55.139758 18277 hierarchical.cpp:1264] Framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000 filtered agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0 for 5secs
I0710 15:54:55.142410 18269 master.cpp:12361] Sending operation '' (uuid: b7639072-1776-41d5-ba53-0e24f7548b4c) to agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0 at slave(1199)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:55.142972 18278 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:55.146268 18264 provider.cpp:481] Received APPLY_OPERATION event
I0710 15:54:55.146315 18264 provider.cpp:1295] Received UNRESERVE operation '' (uuid: b7639072-1776-41d5-ba53-0e24f7548b4c)
I0710 15:54:55.152446 18280 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.127484ms
I0710 15:54:55.153100 18262 master.cpp:10195] Sending offers [ d00b84e5-8718-46ea-940c-e286f72e8ecc-O6 ] to framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000 (default) at scheduler-a2595cdd-6af2-49fb-bd5f-313deba49d89@172.17.0.2:44968
I0710 15:54:55.153779 18274 sched.cpp:934] Scheduler::resourceOffers took 138us
I0710 15:54:55.166543 18260 http.cpp:1115] HTTP POST for /slave(1199)/api/v1/resource_provider from 172.17.0.2:45554
I0710 15:54:55.167589 18269 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 814d4696-73e9-4929-8797-bbc5bf7eb5be) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 15:54:55.167793 18269 slave.cpp:8670] Updating the state of operation with no ID (uuid: 814d4696-73e9-4929-8797-bbc5bf7eb5be) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 15:54:55.167843 18269 slave.cpp:8424] Forwarding status update of operation with no ID (operation_uuid: 814d4696-73e9-4929-8797-bbc5bf7eb5be) for an operator API call
I0710 15:54:55.168205 18273 master.cpp:12017] Updating the state of operation '' (uuid: 814d4696-73e9-4929-8797-bbc5bf7eb5be) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 15:54:55.168776 18278 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:55.226965 18274 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 9acea5e1-2ec1-49f1-aaca-6f317e021df4) for operation UUID b7639072-1776-41d5-ba53-0e24f7548b4c on agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0
I0710 15:54:55.227031 18274 status_update_manager_process.hpp:414] Creating operation status update stream b7639072-1776-41d5-ba53-0e24f7548b4c checkpoint=true
I0710 15:54:55.227058 18264 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 15:54:55.227363 18274 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 9acea5e1-2ec1-49f1-aaca-6f317e021df4) for operation UUID b7639072-1776-41d5-ba53-0e24f7548b4c on agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0
I0710 15:54:55.277416 18274 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 9acea5e1-2ec1-49f1-aaca-6f317e021df4) for operation UUID b7639072-1776-41d5-ba53-0e24f7548b4c on agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0
I0710 15:54:55.277727 18274 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: c4a37b8a-d6f4-4c32-ae99-3ddf48e8de12) for stream 814d4696-73e9-4929-8797-bbc5bf7eb5be
I0710 15:54:55.277806 18274 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: c4a37b8a-d6f4-4c32-ae99-3ddf48e8de12) for operation UUID 814d4696-73e9-4929-8797-bbc5bf7eb5be on agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0
I0710 15:54:55.278232 18268 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:44968/slave(1199)/api/v1/resource_provider
I0710 15:54:55.279184 18277 process.cpp:3671] Handling HTTP event for process 'slave(1199)' with path: '/slave(1199)/api/v1/resource_provider'
I0710 15:54:55.318950 18278 http.cpp:1115] HTTP POST for /slave(1199)/api/v1/resource_provider from 172.17.0.2:45554
I0710 15:54:55.319809 18272 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: b7639072-1776-41d5-ba53-0e24f7548b4c) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 15:54:55.319999 18272 slave.cpp:8670] Updating the state of operation with no ID (uuid: b7639072-1776-41d5-ba53-0e24f7548b4c) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 15:54:55.320070 18272 slave.cpp:8424] Forwarding status update of operation with no ID (operation_uuid: b7639072-1776-41d5-ba53-0e24f7548b4c) for an operator API call
I0710 15:54:55.320430 18275 master.cpp:12017] Updating the state of operation '' (uuid: b7639072-1776-41d5-ba53-0e24f7548b4c) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 15:54:55.320976 18267 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:55.322346 18263 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 15:54:55.327563 18274 status_update_manager_process.hpp:490] Cleaning up operation status update stream 814d4696-73e9-4929-8797-bbc5bf7eb5be
I0710 15:54:55.327778 18274 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 9acea5e1-2ec1-49f1-aaca-6f317e021df4) for stream b7639072-1776-41d5-ba53-0e24f7548b4c
I0710 15:54:55.327850 18274 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 9acea5e1-2ec1-49f1-aaca-6f317e021df4) for operation UUID b7639072-1776-41d5-ba53-0e24f7548b4c on agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0
I0710 15:54:55.411499 18274 status_update_manager_process.hpp:490] Cleaning up operation status update stream b7639072-1776-41d5-ba53-0e24f7548b4c
I0710 15:54:55.471657 18276 master.cpp:1410] Framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000 (default) at scheduler-a2595cdd-6af2-49fb-bd5f-313deba49d89@172.17.0.2:44968 disconnected
I0710 15:54:55.471731 18276 master.cpp:3342] Deactivating framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000 (default) at scheduler-a2595cdd-6af2-49fb-bd5f-313deba49d89@172.17.0.2:44968
I0710 15:54:55.472196 18272 hierarchical.cpp:475] Deactivated framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000
I0710 15:54:55.472796 18259 slave.cpp:912] Agent terminating
I0710 15:54:55.473129 18276 master.cpp:12470] Removing offer d00b84e5-8718-46ea-940c-e286f72e8ecc-O6
I0710 15:54:55.473227 18276 master.cpp:3319] Disconnecting framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000 (default) at scheduler-a2595cdd-6af2-49fb-bd5f-313deba49d89@172.17.0.2:44968
I0710 15:54:55.473342 18276 master.cpp:1425] Giving framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000 (default) at scheduler-a2595cdd-6af2-49fb-bd5f-313deba49d89@172.17.0.2:44968 0ns to failover
I0710 15:54:55.473845 18259 manager.cpp:163] Terminating resource provider ac49acbc-1b73-421b-9599-b71c27ac1aef
I0710 15:54:55.474092 18272 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_diZEs1/2GB-fb8728fd-97b6-48f0-a119-3c585c3b43dd,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_diZEs1/2GB-fb8728fd-97b6-48f0-a119-3c585c3b43dd,test)]:2048, allocated: {}) on agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0 from framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000
I0710 15:54:55.474391 18260 master.cpp:1295] Agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0 at slave(1199)@172.17.0.2:44968 (b727e219f54d) disconnected
I0710 15:54:55.474423 18260 master.cpp:3379] Disconnecting agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0 at slave(1199)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:55.474512 18260 master.cpp:3398] Deactivating agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0 at slave(1199)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:55.474665 18271 hierarchical.cpp:799] Agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0 deactivated
I0710 15:54:55.474961 18273 master.cpp:9987] Framework failover timeout, removing framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000 (default) at scheduler-a2595cdd-6af2-49fb-bd5f-313deba49d89@172.17.0.2:44968
I0710 15:54:55.474997 18273 master.cpp:10979] Removing framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000 (default) at scheduler-a2595cdd-6af2-49fb-bd5f-313deba49d89@172.17.0.2:44968
I0710 15:54:55.475389 18281 hierarchical.cpp:1432] Allocation paused
E0710 15:54:55.475473 18261 http_connection.hpp:452] End-Of-File received
I0710 15:54:55.475863 18281 hierarchical.cpp:417] Removed framework d00b84e5-8718-46ea-940c-e286f72e8ecc-0000
I0710 15:54:55.475996 18261 http_connection.hpp:217] Re-detecting endpoint
I0710 15:54:55.476367 18281 hierarchical.cpp:1442] Allocation resumed
I0710 15:54:55.476470 18261 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0710 15:54:55.476534 18261 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0710 15:54:55.476613 18261 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:44968/slave(1199)/api/v1/resource_provider
I0710 15:54:55.476698 18264 provider.cpp:471] Disconnected from resource provider manager
I0710 15:54:55.477080 18266 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 15:54:55.478046 18260 containerizer.cpp:2575] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0710 15:54:55.478081 18260 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING
I0710 15:54:55.478484 18260 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 15:54:55.479586 18283 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:44968/slave(1199)/api/v1/resource_provider
I0710 15:54:55.480159 18265 provider.cpp:459] Connected to resource provider manager
I0710 15:54:55.480656 18281 hierarchical.cpp:1508] Performed allocation for 1 agents in 148974ns
I0710 15:54:55.480806 18264 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:44968/slave(1199)/api/v1/resource_provider
E0710 15:54:55.481459 18264 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Cannot process 'SUBSCRIBE' call as the driver is in state SUBSCRIBING
I0710 15:54:55.481587 18284 process.cpp:2781] Returning '404 Not Found' for '/slave(1199)/api/v1/resource_provider'
E0710 15:54:55.482741 18261 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0710 15:54:55.531530 18269 hierarchical.cpp:1508] Performed allocation for 1 agents in 130205ns
I0710 15:54:55.582430 18263 containerizer.cpp:3116] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0710 15:54:55.582932 18267 hierarchical.cpp:1508] Performed allocation for 1 agents in 111204ns
I0710 15:54:55.583720 18280 provisioner.cpp:609] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 15:54:55.585850 18270 container_daemon.cpp:189] Invoking post-stop hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:55.586033 18269 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-MkIz2X/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 15:54:55.586253 18271 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:55.588464 18284 process.cpp:2781] Returning '404 Not Found' for '/slave(1199)/api/v1'
I0710 15:54:55.599258 18259 master.cpp:1135] Master terminating
I0710 15:54:55.599900 18283 hierarchical.cpp:775] Removed all filters for agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0
I0710 15:54:55.599928 18283 hierarchical.cpp:650] Removed agent d00b84e5-8718-46ea-940c-e286f72e8ecc-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v0 (2409 ms)
[ RUN ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1
I0710 15:54:55.613960 18259 cluster.cpp:176] Creating default 'local' authorizer
I0710 15:54:55.618620 18273 master.cpp:440] Master 753f1040-d566-4097-a9e4-d6acaedc978b (b727e219f54d) started on 172.17.0.2:44968
I0710 15:54:55.618649 18273 master.cpp:443] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/JG9vsm/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca
table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/mesos/mesos-1.9.0/_inst/share/mesos/webui" --work_dir="/tmp/JG9vsm/master" --zk_session_timeout="10secs"
I0710 15:54:55.619024 18273 master.cpp:492] Master only allowing authenticated frameworks to register
I0710 15:54:55.619041 18273 master.cpp:498] Master only allowing authenticated agents to register
I0710 15:54:55.619048 18273 master.cpp:504] Master only allowing authenticated HTTP frameworks to register
I0710 15:54:55.619057 18273 credentials.hpp:37] Loading credentials for authentication from '/tmp/JG9vsm/credentials'
I0710 15:54:55.619328 18273 master.cpp:548] Using default 'crammd5' authenticator
I0710 15:54:55.619529 18273 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0710 15:54:55.619756 18273 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0710 15:54:55.619948 18273 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0710 15:54:55.620131 18273 master.cpp:629] Authorization enabled
I0710 15:54:55.620477 18264 hierarchical.cpp:241] Initialized hierarchical allocator process
I0710 15:54:55.620507 18267 whitelist_watcher.cpp:77] No whitelist given
I0710 15:54:55.623255 18283 master.cpp:2150] Elected as the leading master!
I0710 15:54:55.623289 18283 master.cpp:1664] Recovering from registrar
I0710 15:54:55.623486 18263 registrar.cpp:339] Recovering registrar
I0710 15:54:55.624450 18263 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0710 15:54:55.624621 18263 registrar.cpp:487] Applied 1 operations in 40468ns; attempting to update the registry
I0710 15:54:55.625360 18263 registrar.cpp:544] Successfully updated the registry in 0ns
I0710 15:54:55.625519 18263 registrar.cpp:416] Successfully recovered registrar
I0710 15:54:55.625969 18269 master.cpp:1799] Recovered 0 agents from the registry (143B); allowing 10mins for agents to reregister
I0710 15:54:55.626037 18262 hierarchical.cpp:280] Skipping recovery of hierarchical allocator: nothing to recover
W0710 15:54:55.631738 18259 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:44968
I0710 15:54:55.632992 18259 containerizer.cpp:314] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0710 15:54:55.633550 18259 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0710 15:54:55.633708 18259 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0710 15:54:55.633749 18259 provisioner.cpp:298] Using default backend 'copy'
I0710 15:54:55.636193 18259 cluster.cpp:510] Creating default 'local' authorizer
I0710 15:54:55.638526 18282 slave.cpp:265] Mesos agent started on (1200)@172.17.0.2:44968
I0710 15:54:55.638551 18282 slave.cpp:266] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/JG9vsm/rFfW6O/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/JG9vsm/rFfW6O/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/JG9vsm/rFfW6O/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/JG9vsm/rFfW6O/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/JG9vsm/rFfW6O/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/JG9vsm/rFfW6O/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.9.0/_build/src" --logbufsecs="0" --
logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/JG9vsm/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_swqbrs" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsW
ithResourceProviderResources_v1_5iurL5" --zk_session_timeout="10secs"
I0710 15:54:55.638978 18282 credentials.hpp:86] Loading credential for authentication from '/tmp/JG9vsm/rFfW6O/credential'
I0710 15:54:55.639140 18282 slave.cpp:298] Agent using credential for: test-principal
I0710 15:54:55.639166 18282 credentials.hpp:37] Loading credentials for authentication from '/tmp/JG9vsm/rFfW6O/http_credentials'
I0710 15:54:55.639358 18282 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0710 15:54:55.639739 18282 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0710 15:54:55.641414 18282 slave.cpp:613] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0710 15:54:55.641626 18282 slave.cpp:621] Agent attributes: [ ]
I0710 15:54:55.641643 18282 slave.cpp:630] Agent hostname: b727e219f54d
I0710 15:54:55.641815 18280 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 15:54:55.641865 18260 task_status_update_manager.cpp:181] Pausing sending task status updates
I0710 15:54:55.642868 18278 process.cpp:3671] Handling HTTP event for process 'test-disk-profile-server' with path: '/test-disk-profile-server/profiles'
I0710 15:54:55.643599 18270 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_5iurL5/meta'
I0710 15:54:55.643993 18274 slave.cpp:7246] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_5iurL5/meta', beginning agent recovery
I0710 15:54:55.644598 18263 task_status_update_manager.cpp:207] Recovering task status update manager
I0710 15:54:55.645124 18276 containerizer.cpp:796] Recovering Mesos containers
I0710 15:54:55.645493 18276 containerizer.cpp:1122] Recovering isolators
I0710 15:54:55.646478 18270 containerizer.cpp:1161] Recovering provisioner
I0710 15:54:55.647233 18272 provisioner.cpp:498] Provisioner recovery complete
I0710 15:54:55.647325 18282 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0710 15:54:55.648098 18271 composing.cpp:339] Finished recovering all containerizers
I0710 15:54:55.648437 18264 slave.cpp:7708] Recovering executors
I0710 15:54:55.648560 18264 slave.cpp:7861] Finished recovery
I0710 15:54:55.649502 18280 task_status_update_manager.cpp:181] Pausing sending task status updates
I0710 15:54:55.649528 18273 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 15:54:55.649550 18276 slave.cpp:1258] New master detected at master@172.17.0.2:44968
I0710 15:54:55.649716 18276 slave.cpp:1323] Detecting new master
I0710 15:54:55.651036 18261 slave.cpp:1350] Authenticating with master master@172.17.0.2:44968
I0710 15:54:55.651165 18261 slave.cpp:1359] Using default CRAM-MD5 authenticatee
I0710 15:54:55.651537 18260 authenticatee.cpp:121] Creating new client SASL connection
I0710 15:54:55.651901 18270 master.cpp:10380] Authenticating slave(1200)@172.17.0.2:44968
I0710 15:54:55.652092 18275 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2046)@172.17.0.2:44968
I0710 15:54:55.652393 18282 authenticator.cpp:98] Creating new server SASL connection
I0710 15:54:55.652652 18274 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0710 15:54:55.652688 18274 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0710 15:54:55.652829 18269 authenticator.cpp:204] Received SASL authentication start
I0710 15:54:55.652899 18269 authenticator.cpp:326] Authentication requires more steps
I0710 15:54:55.653074 18272 authenticatee.cpp:259] Received SASL authentication step
I0710 15:54:55.653265 18268 authenticator.cpp:232] Received SASL authentication step
I0710 15:54:55.653313 18268 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b727e219f54d' server FQDN: 'b727e219f54d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0710 15:54:55.653337 18268 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0710 15:54:55.653381 18268 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0710 15:54:55.653405 18268 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b727e219f54d' server FQDN: 'b727e219f54d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0710 15:54:55.653425 18268 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0710 15:54:55.653445 18268 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0710 15:54:55.653479 18268 authenticator.cpp:318] Authentication success
I0710 15:54:55.653586 18263 authenticatee.cpp:299] Authentication success
I0710 15:54:55.653736 18265 master.cpp:10412] Successfully authenticated principal 'test-principal' at slave(1200)@172.17.0.2:44968
I0710 15:54:55.653945 18262 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2046)@172.17.0.2:44968
I0710 15:54:55.654084 18279 slave.cpp:1450] Successfully authenticated with master master@172.17.0.2:44968
I0710 15:54:55.654592 18279 slave.cpp:1900] Will retry registration in 2.8361ms if necessary
I0710 15:54:55.654789 18278 master.cpp:6900] Received register agent message from slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:55.655156 18278 master.cpp:4099] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
I0710 15:54:55.655851 18276 master.cpp:6967] Authorized registration of agent at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:55.655946 18276 master.cpp:7082] Registering agent at slave(1200)@172.17.0.2:44968 (b727e219f54d) with id 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:55.656599 18277 registrar.cpp:487] Applied 1 operations in 201842ns; attempting to update the registry
I0710 15:54:55.657369 18277 registrar.cpp:544] Successfully updated the registry in 0ns
I0710 15:54:55.657579 18282 master.cpp:7130] Admitted agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:55.658396 18282 master.cpp:7175] Registered agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0710 15:54:55.658519 18269 slave.cpp:1483] Registered with master master@172.17.0.2:44968; given agent ID 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:55.658514 18272 hierarchical.cpp:617] Added agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 (b727e219f54d) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0710 15:54:55.658884 18272 hierarchical.cpp:1508] Performed allocation for 1 agents in 160597ns
I0710 15:54:55.658952 18272 task_status_update_manager.cpp:188] Resuming sending task status updates
I0710 15:54:55.659119 18269 slave.cpp:1518] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_5iurL5/meta/slaves/753f1040-d566-4097-a9e4-d6acaedc978b-S0/slave.info'
I0710 15:54:55.659164 18271 status_update_manager_process.hpp:385] Resuming operation status update manager
I0710 15:54:55.660451 18269 slave.cpp:1570] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"mDC/bQFcTX2oywmT2ZtoPw=="},"slave_id":{"value":"753f1040-d566-4097-a9e4-d6acaedc978b-S0"},"update_oversubscribed_resources":false}
I0710 15:54:55.661307 18269 master.cpp:8261] Ignoring update on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d) as it reports no changes
I0710 15:54:55.665872 18274 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1'
I0710 15:54:55.667028 18263 http.cpp:1115] HTTP POST for /slave(1200)/api/v1 from 172.17.0.2:45576
I0710 15:54:55.667575 18263 http.cpp:2120] Processing GET_CONTAINERS call
I0710 15:54:55.672721 18270 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:55.674996 18274 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1'
I0710 15:54:55.675886 18263 http.cpp:1115] HTTP POST for /slave(1200)/api/v1 from 172.17.0.2:45578
I0710 15:54:55.676764 18263 http.cpp:2486] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:55.677613 18280 http.cpp:2590] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_5iurL5/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:55.678215 18278 containerizer.cpp:1357] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 15:54:55.679428 18278 containerizer.cpp:1529] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_swqbrs/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0710 15:54:55.679471 18278 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING
I0710 15:54:55.682049 18273 containerizer.cpp:2055] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_5iurL5/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-3gRj7h/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperat
ionsWithResourceProviderResources_v1_5iurL5/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="89" --pipe_write="90" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_swqbrs/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0710 15:54:55.690933 18273 launcher.cpp:145] Forked child with pid '32067' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:55.691730 18273 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING
I0710 15:54:55.693229 18273 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING
I0710 15:54:55.693655 18274 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_5iurL5/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 15:54:55.694941 18271 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING
I0710 15:54:55.697862 18280 container_daemon.cpp:140] Invoking post-start hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:55.698213 18262 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-3gRj7h/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 15:54:55.867539 18270 hierarchical.cpp:1508] Performed allocation for 1 agents in 193315ns
I0710 15:54:55.918305 18281 hierarchical.cpp:1508] Performed allocation for 1 agents in 117258ns
I0710 15:54:55.969478 18264 hierarchical.cpp:1508] Performed allocation for 1 agents in 111088ns
I0710 15:54:56.020999 18261 hierarchical.cpp:1508] Performed allocation for 1 agents in 110577ns
I0710 15:54:56.072353 18265 hierarchical.cpp:1508] Performed allocation for 1 agents in 111536ns
I0710 15:54:56.123891 18269 hierarchical.cpp:1508] Performed allocation for 1 agents in 131825ns
I0710 15:54:56.175595 18278 hierarchical.cpp:1508] Performed allocation for 1 agents in 109317ns
I0710 15:54:56.181941 18262 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-3gRj7h/endpoint.sock' with CSI v1
I0710 15:54:56.204383 32071 test_csi_plugin.cpp:909] ProbeRequest '{}'
I0710 15:54:56.206501 18275 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:56.209017 32072 test_csi_plugin.cpp:895] GetPluginCapabilitiesRequest '{}'
I0710 15:54:56.209856 18263 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1'
I0710 15:54:56.210942 18267 http.cpp:1115] HTTP POST for /slave(1200)/api/v1 from 172.17.0.2:45580
I0710 15:54:56.211526 18267 http.cpp:2704] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:56.212560 32071 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0710 15:54:56.212852 32072 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0710 15:54:56.214045 18272 v1_volume_manager.cpp:648] NODE_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0710 15:54:56.214884 18272 v1_volume_manager.cpp:648] CONTROLLER_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0710 15:54:56.216624 32071 test_csi_plugin.cpp:1105] ControllerGetCapabilitiesRequest '{}'
I0710 15:54:56.219972 32071 test_csi_plugin.cpp:1241] NodeGetCapabilitiesRequest '{}'
I0710 15:54:56.222718 32071 test_csi_plugin.cpp:1255] NodeGetInfoRequest '{}'
I0710 15:54:56.224335 18277 provider.cpp:659] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0710 15:54:56.224483 18282 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 15:54:56.224797 18265 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:56.226588 18272 hierarchical.cpp:1508] Performed allocation for 1 agents in 163393ns
I0710 15:54:56.227718 18279 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:56.228242 18268 provider.cpp:459] Connected to resource provider manager
I0710 15:54:56.228804 18261 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:56.229763 18260 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1/resource_provider'
I0710 15:54:56.231209 18273 http.cpp:1115] HTTP POST for /slave(1200)/api/v1/resource_provider from 172.17.0.2:45584
I0710 15:54:56.231808 18265 manager.cpp:807] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}
I0710 15:54:56.277299 18278 hierarchical.cpp:1508] Performed allocation for 1 agents in 121610ns
I0710 15:54:56.283226 18262 slave.cpp:8217] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"deeb488f-4019-4431-a661-c79bd4d23ca7"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}'
I0710 15:54:56.284560 18282 provider.cpp:481] Received SUBSCRIBED event
I0710 15:54:56.284598 18282 provider.cpp:1255] Subscribed with ID deeb488f-4019-4431-a661-c79bd4d23ca7
I0710 15:54:56.285327 18273 status_update_manager_process.hpp:314] Recovering operation status update manager
I0710 15:54:56.328588 18281 hierarchical.cpp:1508] Performed allocation for 1 agents in 115025ns
I0710 15:54:56.335414 32073 test_csi_plugin.cpp:1050] ListVolumesRequest '{}'
I0710 15:54:56.337400 18261 provider.cpp:2145] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:56.337610 18261 provider.cpp:745] Resource provider deeb488f-4019-4431-a661-c79bd4d23ca7 is in READY state
I0710 15:54:56.337630 18271 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:56.337687 18268 status_update_manager_process.hpp:385] Resuming operation status update manager
I0710 15:54:56.338284 18275 provider.cpp:1181] Updating profiles { test } for resource provider deeb488f-4019-4431-a661-c79bd4d23ca7
I0710 15:54:56.338624 18273 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1/resource_provider'
I0710 15:54:56.340474 18262 http.cpp:1115] HTTP POST for /slave(1200)/api/v1/resource_provider from 172.17.0.2:45582
I0710 15:54:56.340871 18271 manager.cpp:1039] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider deeb488f-4019-4431-a661-c79bd4d23ca7
I0710 15:54:56.341056 18260 slave.cpp:8217] Handling resource provider message 'UPDATE_STATE: deeb488f-4019-4431-a661-c79bd4d23ca7 {}'
I0710 15:54:56.341187 18260 slave.cpp:8337] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0710 15:54:56.341464 32073 test_csi_plugin.cpp:1078] GetCapacityRequest '{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0710 15:54:56.342818 18281 hierarchical.cpp:753] Grew agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 by {} (total), { } (used)
I0710 15:54:56.343158 18281 hierarchical.cpp:710] Agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 (b727e219f54d) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
W0710 15:54:56.343935 18259 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:44968
I0710 15:54:56.345468 18259 sched.cpp:239] Version: 1.9.0
I0710 15:54:56.345628 18263 provider.cpp:933] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to the total resources
I0710 15:54:56.346227 18262 sched.cpp:343] New master detected at master@172.17.0.2:44968
I0710 15:54:56.346357 18262 sched.cpp:408] Authenticating with master master@172.17.0.2:44968
I0710 15:54:56.346382 18262 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0710 15:54:56.346729 18268 authenticatee.cpp:121] Creating new client SASL connection
I0710 15:54:56.347062 18275 master.cpp:10380] Authenticating scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:56.347255 18282 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2047)@172.17.0.2:44968
I0710 15:54:56.347353 18270 hierarchical.cpp:1508] Performed allocation for 1 agents in 169243ns
I0710 15:54:56.347594 18269 authenticator.cpp:98] Creating new server SASL connection
I0710 15:54:56.347849 18272 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0710 15:54:56.347882 18272 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0710 15:54:56.348028 18277 authenticator.cpp:204] Received SASL authentication start
I0710 15:54:56.348119 18277 authenticator.cpp:326] Authentication requires more steps
I0710 15:54:56.348266 18260 authenticatee.cpp:259] Received SASL authentication step
I0710 15:54:56.348433 18276 authenticator.cpp:232] Received SASL authentication step
I0710 15:54:56.348484 18276 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b727e219f54d' server FQDN: 'b727e219f54d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0710 15:54:56.348510 18276 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0710 15:54:56.348554 18276 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0710 15:54:56.348578 18276 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b727e219f54d' server FQDN: 'b727e219f54d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0710 15:54:56.348600 18276 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0710 15:54:56.348623 18276 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0710 15:54:56.348660 18276 authenticator.cpp:318] Authentication success
I0710 15:54:56.348771 18281 authenticatee.cpp:299] Authentication success
I0710 15:54:56.348960 18265 master.cpp:10412] Successfully authenticated principal 'test-principal' at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:56.349006 18273 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2047)@172.17.0.2:44968
I0710 15:54:56.349265 18280 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:44968
I0710 15:54:56.349294 18280 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:44968
I0710 15:54:56.349449 18280 sched.cpp:870] Will retry registration in 247.739203ms if necessary
I0710 15:54:56.349658 18279 master.cpp:2890] Received SUBSCRIBE call for framework 'default' at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:56.349696 18279 master.cpp:2222] Authorizing framework principal 'test-principal' to receive offers for roles '{ storage/default-role }'
I0710 15:54:56.350291 18271 master.cpp:2977] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0710 15:54:56.352841 18271 master.cpp:10610] Adding framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968 with roles { } suppressed
I0710 15:54:56.353399 18267 sched.cpp:751] Framework registered with 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.353456 18267 sched.cpp:770] Scheduler::registered took 26909ns
I0710 15:54:56.353760 18261 hierarchical.cpp:368] Added framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.354961 18261 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.051387ms
I0710 15:54:56.355427 18282 master.cpp:10195] Sending offers [ 753f1040-d566-4097-a9e4-d6acaedc978b-O0 ] to framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:56.356053 18269 sched.cpp:934] Scheduler::resourceOffers took 139449ns
I0710 15:54:56.356410 18272 master.cpp:6119] Processing DECLINE call for offers: [ 753f1040-d566-4097-a9e4-d6acaedc978b-O0 ] for framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968 with 5 seconds filter
I0710 15:54:56.356963 18272 master.cpp:12470] Removing offer 753f1040-d566-4097-a9e4-d6acaedc978b-O0
I0710 15:54:56.357631 18277 hierarchical.cpp:1218] Recovered cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 from framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.357702 18277 hierarchical.cpp:1264] Framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 filtered agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for 5secs
I0710 15:54:56.391975 18263 provider.cpp:2145] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' and 0 operations to agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:56.392410 18260 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:56.393395 18265 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1/resource_provider'
I0710 15:54:56.430858 18279 http.cpp:1115] HTTP POST for /slave(1200)/api/v1/resource_provider from 172.17.0.2:45582
I0710 15:54:56.431509 18266 manager.cpp:1039] Received UPDATE_STATE call with resources '[{"disk":{"source":{"profile":"test","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"deeb488f-4019-4431-a661-c79bd4d23ca7"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]' and 0 operations from resource provider deeb488f-4019-4431-a661-c79bd4d23ca7
I0710 15:54:56.432013 18268 slave.cpp:8217] Handling resource provider message 'UPDATE_STATE: deeb488f-4019-4431-a661-c79bd4d23ca7 disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0710 15:54:56.432157 18268 slave.cpp:8337] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048
I0710 15:54:56.434396 18270 hierarchical.cpp:710] Agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 (b727e219f54d) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048
I0710 15:54:56.435760 18270 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.160176ms
I0710 15:54:56.436408 18261 master.cpp:10195] Sending offers [ 753f1040-d566-4097-a9e4-d6acaedc978b-O1 ] to framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:56.437052 18282 sched.cpp:934] Scheduler::resourceOffers took 83409ns
I0710 15:54:56.445785 18277 master.cpp:12470] Removing offer 753f1040-d566-4097-a9e4-d6acaedc978b-O1
I0710 15:54:56.446151 18277 master.cpp:4636] Processing ACCEPT call for offers: [ 753f1040-d566-4097-a9e4-d6acaedc978b-O1 ] on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d) for framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:56.446249 18263 hierarchical.cpp:1508] Performed allocation for 1 agents in 222457ns
I0710 15:54:56.446251 18277 master.cpp:4009] Authorizing principal 'test-principal' to create a MOUNT disk from 'disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0710 15:54:56.447263 18281 master.cpp:5911] Processing CREATE_DISK operation with source disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048 from framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968 to agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:56.447801 18281 master.cpp:12361] Sending operation '' (uuid: 8b642e27-76f5-40f5-9edf-e9d3c92ae523) to agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:56.448112 18273 hierarchical.cpp:1432] Allocation paused
I0710 15:54:56.448308 18283 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:56.449285 18273 hierarchical.cpp:1218] Recovered ports(allocated: storage/default-role):[31000-32000]; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048, allocated: disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048) on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 from framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.449383 18273 hierarchical.cpp:1264] Framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 filtered agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for 5secs
I0710 15:54:56.449623 18273 hierarchical.cpp:1442] Allocation resumed
I0710 15:54:56.450430 18270 provider.cpp:481] Received APPLY_OPERATION event
I0710 15:54:56.450471 18270 provider.cpp:1295] Received CREATE_DISK operation '' (uuid: 8b642e27-76f5-40f5-9edf-e9d3c92ae523)
I0710 15:54:56.497834 18282 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for role storage/default-role of framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.498006 18282 hierarchical.cpp:1508] Performed allocation for 1 agents in 681977ns
I0710 15:54:56.501154 18272 v1_volume_manager.cpp:292] Creating volume with name '8b642e27-76f5-40f5-9edf-e9d3c92ae523'
I0710 15:54:56.503922 32073 test_csi_plugin.cpp:922] CreateVolumeRequest '{"name":"8b642e27-76f5-40f5-9edf-e9d3c92ae523","capacityRange":{"requiredBytes":"2147483648","limitBytes":"2147483648"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0710 15:54:56.550108 18264 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for role storage/default-role of framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.550281 18264 hierarchical.cpp:1508] Performed allocation for 1 agents in 752453ns
I0710 15:54:56.577615 18281 provider.cpp:1597] Applying conversion from 'disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to 'disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048' for operation (uuid: 8b642e27-76f5-40f5-9edf-e9d3c92ae523)
I0710 15:54:56.601264 18283 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for role storage/default-role of framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.601374 18283 hierarchical.cpp:1508] Performed allocation for 1 agents in 452183ns
I0710 15:54:56.627866 18280 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: a0199860-02b4-415d-bef8-4e02df705c09) for operation UUID 8b642e27-76f5-40f5-9edf-e9d3c92ae523 of framework '753f1040-d566-4097-a9e4-d6acaedc978b-0000' on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:56.627938 18280 status_update_manager_process.hpp:414] Creating operation status update stream 8b642e27-76f5-40f5-9edf-e9d3c92ae523 checkpoint=true
I0710 15:54:56.628327 18280 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: a0199860-02b4-415d-bef8-4e02df705c09) for operation UUID 8b642e27-76f5-40f5-9edf-e9d3c92ae523 of framework '753f1040-d566-4097-a9e4-d6acaedc978b-0000' on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:56.652911 18266 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for role storage/default-role of framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.653020 18266 hierarchical.cpp:1508] Performed allocation for 1 agents in 429410ns
I0710 15:54:56.694715 18280 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: a0199860-02b4-415d-bef8-4e02df705c09) for operation UUID 8b642e27-76f5-40f5-9edf-e9d3c92ae523 of framework '753f1040-d566-4097-a9e4-d6acaedc978b-0000' on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:56.695574 18268 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:56.696682 18267 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1/resource_provider'
I0710 15:54:56.704761 18262 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for role storage/default-role of framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.704869 18262 hierarchical.cpp:1508] Performed allocation for 1 agents in 432398ns
I0710 15:54:56.734700 18272 http.cpp:1115] HTTP POST for /slave(1200)/api/v1/resource_provider from 172.17.0.2:45582
I0710 15:54:56.735674 18263 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 8b642e27-76f5-40f5-9edf-e9d3c92ae523) for framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 15:54:56.735865 18263 slave.cpp:8670] Updating the state of operation with no ID (uuid: 8b642e27-76f5-40f5-9edf-e9d3c92ae523) for framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 15:54:56.736209 18263 slave.cpp:8424] Forwarding status update of operation with no ID (operation_uuid: 8b642e27-76f5-40f5-9edf-e9d3c92ae523) for framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.736599 18265 master.cpp:12017] Updating the state of operation '' (uuid: 8b642e27-76f5-40f5-9edf-e9d3c92ae523) for framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 15:54:56.737746 18283 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:56.738534 18277 hierarchical.cpp:956] Updated allocation of framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 from disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048 to disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048
I0710 15:54:56.739184 18267 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 15:54:56.739280 18277 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048, allocated: {}) on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 from framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.739346 18271 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: a0199860-02b4-415d-bef8-4e02df705c09) for stream 8b642e27-76f5-40f5-9edf-e9d3c92ae523
I0710 15:54:56.739434 18271 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: a0199860-02b4-415d-bef8-4e02df705c09) for operation UUID 8b642e27-76f5-40f5-9edf-e9d3c92ae523 of framework '753f1040-d566-4097-a9e4-d6acaedc978b-0000' on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:56.757321 18270 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.121894ms
I0710 15:54:56.757999 18269 master.cpp:10195] Sending offers [ 753f1040-d566-4097-a9e4-d6acaedc978b-O2 ] to framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:56.758687 18260 sched.cpp:934] Scheduler::resourceOffers took 115580ns
I0710 15:54:56.761967 18283 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0710 15:54:56.763612 18273 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:45586
I0710 15:54:56.763862 18273 http.cpp:263] Processing call RESERVE_RESOURCES
I0710 15:54:56.764611 18273 master.cpp:3721] Authorizing principal 'test-principal' to reserve resources 'disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048'
I0710 15:54:56.766291 18277 master.cpp:12470] Removing offer 753f1040-d566-4097-a9e4-d6acaedc978b-O2
I0710 15:54:56.766412 18269 sched.cpp:960] Rescinded offer 753f1040-d566-4097-a9e4-d6acaedc978b-O2
I0710 15:54:56.766491 18269 sched.cpp:971] Scheduler::offerRescinded took 25853ns
I0710 15:54:56.767001 18270 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048, allocated: {}) on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 from framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:56.767104 18270 hierarchical.cpp:1264] Framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 filtered agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for 5secs
I0710 15:54:56.769506 18260 master.cpp:12361] Sending operation '' (uuid: 0169981f-e4ed-4fa2-b733-967d4d9e7db0) to agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:56.770114 18276 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:56.772716 18275 provider.cpp:481] Received APPLY_OPERATION event
I0710 15:54:56.772758 18275 provider.cpp:1295] Received RESERVE operation '' (uuid: 0169981f-e4ed-4fa2-b733-967d4d9e7db0)
I0710 15:54:56.811566 18271 status_update_manager_process.hpp:490] Cleaning up operation status update stream 8b642e27-76f5-40f5-9edf-e9d3c92ae523
I0710 15:54:56.896086 18273 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 8a2fb5f4-5159-4aaf-a5c5-d375bc343ebb) for operation UUID 0169981f-e4ed-4fa2-b733-967d4d9e7db0 on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:56.896157 18273 status_update_manager_process.hpp:414] Creating operation status update stream 0169981f-e4ed-4fa2-b733-967d4d9e7db0 checkpoint=true
I0710 15:54:56.896525 18273 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 8a2fb5f4-5159-4aaf-a5c5-d375bc343ebb) for operation UUID 0169981f-e4ed-4fa2-b733-967d4d9e7db0 on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:56.988219 18273 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 8a2fb5f4-5159-4aaf-a5c5-d375bc343ebb) for operation UUID 0169981f-e4ed-4fa2-b733-967d4d9e7db0 on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.006044 18262 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:57.006985 18269 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1/resource_provider'
I0710 15:54:57.010107 18277 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.218049ms
I0710 15:54:57.010723 18270 master.cpp:10195] Sending offers [ 753f1040-d566-4097-a9e4-d6acaedc978b-O3 ] to framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:57.011360 18278 sched.cpp:934] Scheduler::resourceOffers took 77043ns
I0710 15:54:57.014148 18265 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0710 15:54:57.015740 18279 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:45588
I0710 15:54:57.015970 18279 http.cpp:263] Processing call CREATE_VOLUMES
I0710 15:54:57.016724 18279 master.cpp:3848] Authorizing principal 'test-principal' to create volumes '[{"disk":{"persistence":{"id":"000188eb-71e0-428b-b72e-9ee19c1202b8","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"},"volume":{"container_path":"volume","mode":"RW"}},"name":"disk","provider_id":{"value":"deeb488f-4019-4431-a661-c79bd4d23ca7"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0710 15:54:57.018628 18268 master.cpp:12470] Removing offer 753f1040-d566-4097-a9e4-d6acaedc978b-O3
I0710 15:54:57.018718 18273 sched.cpp:960] Rescinded offer 753f1040-d566-4097-a9e4-d6acaedc978b-O3
I0710 15:54:57.018797 18273 sched.cpp:971] Scheduler::offerRescinded took 28291ns
I0710 15:54:57.019430 18271 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048, allocated: {}) on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 from framework 753f1040-d566-40
97-a9e4-d6acaedc978b-0000
I0710 15:54:57.019541 18271 hierarchical.cpp:1264] Framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 filtered agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for 5secs
I0710 15:54:57.022033 18275 master.cpp:12361] Sending operation '' (uuid: f3510499-e458-4125-83d2-4dc2a94808b0) to agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:57.022624 18269 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:57.022697 18270 master.cpp:6233] Processing REVIVE call for framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:57.023098 18272 hierarchical.cpp:1365] Unsuppressed offers for roles { storage/default-role } of framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:57.023125 18272 hierarchical.cpp:1387] Revived roles { storage/default-role } of framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:57.024349 18272 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.075017ms
I0710 15:54:57.024742 18272 hierarchical.cpp:1508] Performed allocation for 1 agents in 197544ns
I0710 15:54:57.025082 18264 master.cpp:10195] Sending offers [ 753f1040-d566-4097-a9e4-d6acaedc978b-O4 ] to framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:57.025452 18266 provider.cpp:481] Received APPLY_OPERATION event
I0710 15:54:57.025493 18266 provider.cpp:1295] Received CREATE operation '' (uuid: f3510499-e458-4125-83d2-4dc2a94808b0)
I0710 15:54:57.025795 18264 sched.cpp:934] Scheduler::resourceOffers took 75900ns
I0710 15:54:57.046442 18277 http.cpp:1115] HTTP POST for /slave(1200)/api/v1/resource_provider from 172.17.0.2:45582
I0710 15:54:57.047394 18278 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 0169981f-e4ed-4fa2-b733-967d4d9e7db0) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 15:54:57.047575 18278 slave.cpp:8670] Updating the state of operation with no ID (uuid: 0169981f-e4ed-4fa2-b733-967d4d9e7db0) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 15:54:57.047644 18278 slave.cpp:8424] Forwarding status update of operation with no ID (operation_uuid: 0169981f-e4ed-4fa2-b733-967d4d9e7db0) for an operator API call
I0710 15:54:57.047984 18269 master.cpp:12017] Updating the state of operation '' (uuid: 0169981f-e4ed-4fa2-b733-967d4d9e7db0) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 15:54:57.048632 18278 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:57.125560 18264 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: abee6e5a-6f4e-4f86-9db2-37c2d33f83ac) for operation UUID f3510499-e458-4125-83d2-4dc2a94808b0 on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.125622 18264 status_update_manager_process.hpp:414] Creating operation status update stream f3510499-e458-4125-83d2-4dc2a94808b0 checkpoint=true
I0710 15:54:57.125658 18266 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 15:54:57.125950 18264 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: abee6e5a-6f4e-4f86-9db2-37c2d33f83ac) for operation UUID f3510499-e458-4125-83d2-4dc2a94808b0 on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.190158 18264 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: abee6e5a-6f4e-4f86-9db2-37c2d33f83ac) for operation UUID f3510499-e458-4125-83d2-4dc2a94808b0 on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.190547 18264 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 8a2fb5f4-5159-4aaf-a5c5-d375bc343ebb) for stream 0169981f-e4ed-4fa2-b733-967d4d9e7db0
I0710 15:54:57.190623 18264 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 8a2fb5f4-5159-4aaf-a5c5-d375bc343ebb) for operation UUID 0169981f-e4ed-4fa2-b733-967d4d9e7db0 on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.191071 18268 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:57.191905 18267 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1/resource_provider'
I0710 15:54:57.230448 18265 http.cpp:1115] HTTP POST for /slave(1200)/api/v1/resource_provider from 172.17.0.2:45582
I0710 15:54:57.231448 18276 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: f3510499-e458-4125-83d2-4dc2a94808b0) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 15:54:57.231632 18276 slave.cpp:8670] Updating the state of operation with no ID (uuid: f3510499-e458-4125-83d2-4dc2a94808b0) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 15:54:57.231695 18276 slave.cpp:8424] Forwarding status update of operation with no ID (operation_uuid: f3510499-e458-4125-83d2-4dc2a94808b0) for an operator API call
I0710 15:54:57.232288 18283 master.cpp:12017] Updating the state of operation '' (uuid: f3510499-e458-4125-83d2-4dc2a94808b0) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 15:54:57.232827 18272 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:57.234230 18271 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 15:54:57.257006 18264 status_update_manager_process.hpp:490] Cleaning up operation status update stream 0169981f-e4ed-4fa2-b733-967d4d9e7db0
I0710 15:54:57.257302 18264 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: abee6e5a-6f4e-4f86-9db2-37c2d33f83ac) for stream f3510499-e458-4125-83d2-4dc2a94808b0
I0710 15:54:57.257397 18264 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: abee6e5a-6f4e-4f86-9db2-37c2d33f83ac) for operation UUID f3510499-e458-4125-83d2-4dc2a94808b0 on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.349151 18264 status_update_manager_process.hpp:490] Cleaning up operation status update stream f3510499-e458-4125-83d2-4dc2a94808b0
I0710 15:54:57.420277 18269 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0710 15:54:57.421603 18278 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:45590
I0710 15:54:57.421844 18278 http.cpp:263] Processing call DESTROY_VOLUMES
I0710 15:54:57.422623 18278 master.cpp:3893] Authorizing principal 'test-principal' to destroy volumes '[{"disk":{"persistence":{"id":"000188eb-71e0-428b-b72e-9ee19c1202b8","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"},"volume":{"container_path":"volume","mode":"RW"}},"name":"disk","provider_id":{"value":"deeb488f-4019-4431-a661-c79bd4d23ca7"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0710 15:54:57.424644 18280 master.cpp:12470] Removing offer 753f1040-d566-4097-a9e4-d6acaedc978b-O4
I0710 15:54:57.424762 18261 sched.cpp:960] Rescinded offer 753f1040-d566-4097-a9e4-d6acaedc978b-O4
I0710 15:54:57.424844 18261 sched.cpp:971] Scheduler::offerRescinded took 24375ns
I0710 15:54:57.425653 18279 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test),000188eb-71e0-428b-b72e-9ee19c1202b8:volume]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test),000188eb-71e0-428b-b72e-9ee19c1202b8:volume]:2048, allocat
ed: {}) on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 from framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:57.425772 18279 hierarchical.cpp:1264] Framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 filtered agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for 5secs
I0710 15:54:57.428937 18268 master.cpp:12361] Sending operation '' (uuid: bd2414f3-e2c4-405a-8a91-114de961e5da) to agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:57.429464 18264 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:57.432340 18265 provider.cpp:481] Received APPLY_OPERATION event
I0710 15:54:57.432381 18265 provider.cpp:1295] Received DESTROY operation '' (uuid: bd2414f3-e2c4-405a-8a91-114de961e5da)
I0710 15:54:57.440639 18283 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.141914ms
I0710 15:54:57.441336 18272 master.cpp:10195] Sending offers [ 753f1040-d566-4097-a9e4-d6acaedc978b-O5 ] to framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:57.442044 18278 sched.cpp:934] Scheduler::resourceOffers took 91110ns
I0710 15:54:57.518096 18281 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: f5c681b3-0e18-4caf-8742-3227b0299965) for operation UUID bd2414f3-e2c4-405a-8a91-114de961e5da on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.518158 18281 status_update_manager_process.hpp:414] Creating operation status update stream bd2414f3-e2c4-405a-8a91-114de961e5da checkpoint=true
I0710 15:54:57.518479 18281 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: f5c681b3-0e18-4caf-8742-3227b0299965) for operation UUID bd2414f3-e2c4-405a-8a91-114de961e5da on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.584961 18281 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: f5c681b3-0e18-4caf-8742-3227b0299965) for operation UUID bd2414f3-e2c4-405a-8a91-114de961e5da on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.585769 18261 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:57.586678 18266 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1/resource_provider'
I0710 15:54:57.589800 18271 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0710 15:54:57.591208 18276 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:45592
I0710 15:54:57.591426 18276 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0710 15:54:57.592108 18276 master.cpp:3785] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"deeb488f-4019-4431-a661-c79bd4d23ca7"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0710 15:54:57.593919 18274 master.cpp:12470] Removing offer 753f1040-d566-4097-a9e4-d6acaedc978b-O5
I0710 15:54:57.594043 18272 sched.cpp:960] Rescinded offer 753f1040-d566-4097-a9e4-d6acaedc978b-O5
I0710 15:54:57.594125 18272 sched.cpp:971] Scheduler::offerRescinded took 26321ns
I0710 15:54:57.594595 18283 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048, allocated: {}) on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 from framework 753f1040-d566-40
97-a9e4-d6acaedc978b-0000
I0710 15:54:57.594703 18283 hierarchical.cpp:1264] Framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 filtered agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 for 5secs
I0710 15:54:57.596918 18278 master.cpp:12361] Sending operation '' (uuid: b5ac6b07-e99c-4719-8302-3c3376b8edaa) to agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:57.597600 18273 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:57.600018 18267 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.094721ms
I0710 15:54:57.600392 18263 provider.cpp:481] Received APPLY_OPERATION event
I0710 15:54:57.600430 18263 provider.cpp:1295] Received UNRESERVE operation '' (uuid: b5ac6b07-e99c-4719-8302-3c3376b8edaa)
I0710 15:54:57.600751 18270 master.cpp:10195] Sending offers [ 753f1040-d566-4097-a9e4-d6acaedc978b-O6 ] to framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:57.601338 18269 sched.cpp:934] Scheduler::resourceOffers took 70245ns
I0710 15:54:57.626344 18261 http.cpp:1115] HTTP POST for /slave(1200)/api/v1/resource_provider from 172.17.0.2:45582
I0710 15:54:57.627351 18279 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: bd2414f3-e2c4-405a-8a91-114de961e5da) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 15:54:57.627542 18279 slave.cpp:8670] Updating the state of operation with no ID (uuid: bd2414f3-e2c4-405a-8a91-114de961e5da) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 15:54:57.627595 18279 slave.cpp:8424] Forwarding status update of operation with no ID (operation_uuid: bd2414f3-e2c4-405a-8a91-114de961e5da) for an operator API call
I0710 15:54:57.627940 18273 master.cpp:12017] Updating the state of operation '' (uuid: bd2414f3-e2c4-405a-8a91-114de961e5da) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 15:54:57.628506 18262 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:57.703088 18269 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: b3ed4442-bcf6-49bf-9f9d-ff3f464befe4) for operation UUID b5ac6b07-e99c-4719-8302-3c3376b8edaa on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.703150 18269 status_update_manager_process.hpp:414] Creating operation status update stream b5ac6b07-e99c-4719-8302-3c3376b8edaa checkpoint=true
I0710 15:54:57.703176 18263 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 15:54:57.703485 18269 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: b3ed4442-bcf6-49bf-9f9d-ff3f464befe4) for operation UUID b5ac6b07-e99c-4719-8302-3c3376b8edaa on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.753279 18269 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: b3ed4442-bcf6-49bf-9f9d-ff3f464befe4) for operation UUID b5ac6b07-e99c-4719-8302-3c3376b8edaa on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.753623 18269 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: f5c681b3-0e18-4caf-8742-3227b0299965) for stream bd2414f3-e2c4-405a-8a91-114de961e5da
I0710 15:54:57.753707 18269 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: f5c681b3-0e18-4caf-8742-3227b0299965) for operation UUID bd2414f3-e2c4-405a-8a91-114de961e5da on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.754077 18260 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:57.754922 18265 process.cpp:3671] Handling HTTP event for process 'slave(1200)' with path: '/slave(1200)/api/v1/resource_provider'
I0710 15:54:57.794430 18266 http.cpp:1115] HTTP POST for /slave(1200)/api/v1/resource_provider from 172.17.0.2:45582
I0710 15:54:57.795214 18262 slave.cpp:8217] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: b5ac6b07-e99c-4719-8302-3c3376b8edaa) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0710 15:54:57.795406 18262 slave.cpp:8670] Updating the state of operation with no ID (uuid: b5ac6b07-e99c-4719-8302-3c3376b8edaa) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0710 15:54:57.795460 18262 slave.cpp:8424] Forwarding status update of operation with no ID (operation_uuid: b5ac6b07-e99c-4719-8302-3c3376b8edaa) for an operator API call
I0710 15:54:57.795794 18268 master.cpp:12017] Updating the state of operation '' (uuid: b5ac6b07-e99c-4719-8302-3c3376b8edaa) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0710 15:54:57.796332 18264 slave.cpp:4198] Ignoring new checkpointed resources and operations identical to the current version
I0710 15:54:57.797659 18274 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0710 15:54:57.820168 18269 status_update_manager_process.hpp:490] Cleaning up operation status update stream bd2414f3-e2c4-405a-8a91-114de961e5da
I0710 15:54:57.820400 18269 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: b3ed4442-bcf6-49bf-9f9d-ff3f464befe4) for stream b5ac6b07-e99c-4719-8302-3c3376b8edaa
I0710 15:54:57.820490 18269 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: b3ed4442-bcf6-49bf-9f9d-ff3f464befe4) for operation UUID b5ac6b07-e99c-4719-8302-3c3376b8edaa on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:57.895653 18269 status_update_manager_process.hpp:490] Cleaning up operation status update stream b5ac6b07-e99c-4719-8302-3c3376b8edaa
I0710 15:54:57.955536 18281 master.cpp:1410] Framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968 disconnected
I0710 15:54:57.955579 18281 master.cpp:3342] Deactivating framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:57.955891 18266 hierarchical.cpp:475] Deactivated framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:57.956406 18264 slave.cpp:912] Agent terminating
I0710 15:54:57.956544 18281 master.cpp:12470] Removing offer 753f1040-d566-4097-a9e4-d6acaedc978b-O6
I0710 15:54:57.956634 18281 master.cpp:3319] Disconnecting framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:57.956693 18281 master.cpp:1425] Giving framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968 0ns to failover
I0710 15:54:57.957386 18264 manager.cpp:163] Terminating resource provider deeb488f-4019-4431-a661-c79bd4d23ca7
I0710 15:54:57.957423 18266 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ysEI5I/2GB-8b642e27-76f5-40f5-9edf-e9d3c92ae523,test)]:2048, allocated: {}) on agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 from framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:57.957800 18279 master.cpp:9987] Framework failover timeout, removing framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:57.957850 18279 master.cpp:10979] Removing framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000 (default) at scheduler-3297b2b4-fb4c-4962-8697-a587bdec7972@172.17.0.2:44968
I0710 15:54:57.958344 18275 hierarchical.cpp:1432] Allocation paused
E0710 15:54:57.958384 18271 http_connection.hpp:452] End-Of-File received
I0710 15:54:57.958407 18279 master.cpp:1295] Agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d) disconnected
I0710 15:54:57.958442 18279 master.cpp:3379] Disconnecting agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:57.958540 18279 master.cpp:3398] Deactivating agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 at slave(1200)@172.17.0.2:44968 (b727e219f54d)
I0710 15:54:57.958884 18275 hierarchical.cpp:417] Removed framework 753f1040-d566-4097-a9e4-d6acaedc978b-0000
I0710 15:54:57.958914 18271 http_connection.hpp:217] Re-detecting endpoint
I0710 15:54:57.958948 18275 hierarchical.cpp:1442] Allocation resumed
I0710 15:54:57.959019 18275 hierarchical.cpp:799] Agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0 deactivated
I0710 15:54:57.959326 18271 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0710 15:54:57.959399 18271 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0710 15:54:57.959434 18260 provider.cpp:471] Disconnected from resource provider manager
I0710 15:54:57.959463 18271 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:57.959538 18260 status_update_manager_process.hpp:379] Pausing operation status update manager
I0710 15:54:57.962882 18278 containerizer.cpp:2575] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0710 15:54:57.962920 18278 containerizer.cpp:3277] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING
I0710 15:54:57.963286 18278 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 15:54:57.967454 18280 hierarchical.cpp:1508] Performed allocation for 1 agents in 203369ns
I0710 15:54:57.968794 18268 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:57.969382 18274 provider.cpp:459] Connected to resource provider manager
I0710 15:54:57.969918 18271 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:44968/slave(1200)/api/v1/resource_provider
I0710 15:54:57.971184 18284 process.cpp:2781] Returning '404 Not Found' for '/slave(1200)/api/v1/resource_provider'
E0710 15:54:57.972980 18273 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0710 15:54:58.020848 18262 hierarchical.cpp:1508] Performed allocation for 1 agents in 109371ns
I0710 15:54:58.070951 18280 containerizer.cpp:3116] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0710 15:54:58.071569 18272 hierarchical.cpp:1508] Performed allocation for 1 agents in 110797ns
I0710 15:54:58.072373 18276 provisioner.cpp:609] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 15:54:58.074474 18269 container_daemon.cpp:189] Invoking post-stop hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:58.074630 18262 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-3gRj7h/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0710 15:54:58.074837 18264 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0710 15:54:58.077095 18284 process.cpp:2781] Returning '404 Not Found' for '/slave(1200)/api/v1'
I0710 15:54:58.089488 18264 master.cpp:1135] Master terminating
I0710 15:54:58.090018 18281 hierarchical.cpp:775] Removed all filters for agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
I0710 15:54:58.090042 18281 hierarchical.cpp:650] Removed agent 753f1040-d566-4097-a9e4-d6acaedc978b-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2487 ms)
[----------] 50 tests from CSIVersion/StorageLocalResourceProviderTest (94575 ms total)
[----------] Global test environment tear-down
[==========] 2265 tests from 216 test cases ran. (1037996 ms total)
[ PASSED ] 2264 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] CSIVersion/StorageLocalResourceProviderTest.RetryOperationStatusUpdateAfterRecovery/v1, where GetParam() = "v1"
1 FAILED TEST
YOU HAVE 31 DISABLED TESTS
I0710 15:54:58.192019 18284 process.cpp:935] Stopped the socket accept loop
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-1.9.0/_build'
make: *** [distcheck] Error 1
+ docker rmi --force mesos-1562768556-3754
Untagged: mesos-1562768556-3754:latest
Deleted: sha256:20ef9658792a32ab825e75fd71767d8d84ce0368323a1cd5ed39c48445bb1cb2
Deleted: sha256:bf2e8aabf94da706b12c50f228ffbe1954d7f277a17b018b08429f3cc7851b4a
Deleted: sha256:c1c85f6fd63b76d9fa0c2e084533f539ef866101631940c6859f7a78f4779935
Deleted: sha256:bde1b4a5c541f11a66120d46521bd37b6b958066cf295ba5e7a0a00e1b03b994
Deleted: sha256:e1405b08760cc10b860ff6d5aced3559bb8f9d164b7a16a9e1a29380f636787c
Deleted: sha256:2230eee1143d930573ad24f178179d35797822f9eeb23b007d24cd45b2aae85c
Deleted: sha256:f6276d535b1610a82c67f4edbccdf813533637adf321100fe96374cd04383442
Deleted: sha256:ed539eda2d0c1424a648b73bb6fd86d285e1377c1bca5cb8b05423d61fd0ce73
Deleted: sha256:1f1c18c25c27fc1fac7419cd67989f373b910becc317be77d34b27aaf92e27a6
Deleted: sha256:ea986e521c773ccd803c5bbaec13e2040f87ac481ef7010885723bd0f361fe3d
Deleted: sha256:7612c0c153960f73385a331e2a2de4cc8b0fe345fb64b11a2e3a41731c88430b
Deleted: sha256:2ce83bf3f2e4d89907e4f7942650a30eceb988359e8961d18a12c657bb4d9932
Deleted: sha256:3040855a3b5b6be43bb9b848e5712e80673d3dd3a64b6da4cae7e75b57495cd0
Deleted: sha256:68d4933bd07589319151ea44347f81946028589e8c5df6570c5d5b96374c052f
Deleted: sha256:9f0efb9e437d280a3149b2339a9c513bde8e69d6b1fe97b2f61c4f405c423d0f
Deleted: sha256:d0e4dfe8a25a6aaa8faa716151ff8e654eeac7be2632a65fa236721aabe5ea54
Deleted: sha256:ce93157cd83916aced43fb39cb7d3e1f336133f017362614e3d5ebd0565155bf
Deleted: sha256:23f112f51cc799124863f62285525c68398b6fd687be18509cb13e1570b59e61
Deleted: sha256:7cccffdbc28f8703b198c1fbb764513c0eedc2b123c8ed7ee6966e5b13f959c0
Deleted: sha256:5e7034e99a4153565397fef5584a66ac525c40bfbe96c19500ab0785ba71db48
Deleted: sha256:f7a6a36953fd860b6f4dcb5671fdad846444229aae83faf80fd105d1b6310dcd
Deleted: sha256:23f5c854d6499090181d254a63b72b7b6cf509e1f529859c7d4d254289e2ea38
Deleted: sha256:be948a2179a340181379df62c5830f32c173a4baf47d67a781d4f2e7d972df5c
Deleted: sha256:de1b8e069fd4b9c9275920620b89c96194ba0e88096506450418c3fff973c629
Deleted: sha256:8da433c8be680445723751039d23af26c13649fdba7cdf7e8cfbab0ab8ae8874
Deleted: sha256:4cb1695f789d9b9965d08d6c7b7ef47a4cd3a92d387c6c0f3a6fc9a75ded20bb
Deleted: sha256:956af603748e757356e0fa4ddd0ef045ec7c88083b8d7755ae23a940beaf7af0
Deleted: sha256:2c1449f8864ccf114fe300f7378387ec6f2246baedb9d0a658d91a169d08bfc4
Deleted: sha256:c46df4f3f424d55d15c656c5ee11bd8ad82e38c8da269f1c00bd195a8e8e6dfb
Deleted: sha256:51cc61df50eb09a351206d7fcebaf121173313a7ebfca49d47afa69fe693e3cc
Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/2477/console
- Mesos Reviewbot
On July 10, 2019, 1:16 p.m., Andrei Sekretenko wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71047/
> -----------------------------------------------------------
>
> (Updated July 10, 2019, 1:16 p.m.)
>
>
> Review request for mesos and Benjamin Mahler.
>
>
> Bugs: MESOS-9849
> https://issues.apache.org/jira/browse/MESOS-9849
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This patch adds exercising per-role suppress/revival to the Java test
> framework to ensure that passing the corresponding arguments through the
> Java bindings works.
>
>
> Diffs
> -----
>
> src/examples/java/TestFramework.java c8b0ceacd1305f7ff67f2ef490e14513d2757f5a
>
>
> Diff: https://reviews.apache.org/r/71047/diff/1/
>
>
> Testing
> -------
>
>
> Thanks,
>
> Andrei Sekretenko
>
>