You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@mesos.apache.org by Benjamin Mahler <bm...@apache.org> on 2020/01/28 19:19:07 UTC
Review Request 72056: Improved performance of v1 agent operator API
GetMetrics call.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72056/
-----------------------------------------------------------
Review request for mesos, Andrei Sekretenko and Greg Mann.
Bugs: MESOS-10026
https://issues.apache.org/jira/browse/MESOS-10026
Repository: mesos
Description
-------
This follow the same approach used for the master's GetMetrics call:
https://github.com/apache/mesos/commit/469f2ebaf65b1642d1eb4a1df81a
https://github.com/apache/mesos/commit/3dda3622f5ed01e8c132dc5ca594
That is, serializing directly to protobuf or json from the in-memory
v0 state.
Diffs
-----
src/slave/http.cpp 04ad0d816618a1880913857a6f0ff38c4643c488
Diff: https://reviews.apache.org/r/72056/diff/1/
Testing
-------
make check
Thanks,
Benjamin Mahler
Re: Review Request 72056: Improved performance of v1 agent operator
API GET_METRICS call.
Posted by Andrei Sekretenko <as...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72056/#review219650
-----------------------------------------------------------
src/slave/http.cpp
Lines 1079 (patched)
<https://reviews.apache.org/r/72056/#comment307852>
Hmm... do I understand correctly that code for master's GET_METRICS differs only in the type of the `Response` protobuf?
Did you consider templatizing metrics serialization on `Response` and reusing it for both calls?
- Andrei Sekretenko
On Jan. 30, 2020, 9:31 p.m., Benjamin Mahler wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72056/
> -----------------------------------------------------------
>
> (Updated Jan. 30, 2020, 9:31 p.m.)
>
>
> Review request for mesos, Andrei Sekretenko and Greg Mann.
>
>
> Bugs: MESOS-10026
> https://issues.apache.org/jira/browse/MESOS-10026
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This follow the same approach used for the master's GET_METRICS call:
>
> https://github.com/apache/mesos/commit/469f2ebaf65b1642d1eb4a1df81a
> https://github.com/apache/mesos/commit/3dda3622f5ed01e8c132dc5ca594
>
> That is, serializing directly to protobuf or json from the in-memory
> v0 state.
>
>
> Diffs
> -----
>
> src/slave/http.cpp 04ad0d816618a1880913857a6f0ff38c4643c488
>
>
> Diff: https://reviews.apache.org/r/72056/diff/2/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Benjamin Mahler
>
>
Re: Review Request 72056: Improved performance of v1 agent operator
API GET_METRICS call.
Posted by Benjamin Mahler <bm...@apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72056/
-----------------------------------------------------------
(Updated Jan. 30, 2020, 9:31 p.m.)
Review request for mesos, Andrei Sekretenko and Greg Mann.
Changes
-------
- Removed unnecessary mesos:: qualification.
Summary (updated)
-----------------
Improved performance of v1 agent operator API GET_METRICS call.
Bugs: MESOS-10026
https://issues.apache.org/jira/browse/MESOS-10026
Repository: mesos
Description (updated)
-------
This follow the same approach used for the master's GET_METRICS call:
https://github.com/apache/mesos/commit/469f2ebaf65b1642d1eb4a1df81a
https://github.com/apache/mesos/commit/3dda3622f5ed01e8c132dc5ca594
That is, serializing directly to protobuf or json from the in-memory
v0 state.
Diffs (updated)
-----
src/slave/http.cpp 04ad0d816618a1880913857a6f0ff38c4643c488
Diff: https://reviews.apache.org/r/72056/diff/2/
Changes: https://reviews.apache.org/r/72056/diff/1-2/
Testing
-------
make check
Thanks,
Benjamin Mahler
Re: Review Request 72056: Improved performance of v1 agent operator
API GetMetrics call.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72056/#review219408
-----------------------------------------------------------
Bad patch!
Reviews applied: [72056]
Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:16.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/jenkins/buildbot.sh 2>&1 | tee build_72056"]
Error:
...<truncated>...
"},"source":{"type":"MOUNT","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"vendor":"org.apache.mesos.csi.test.local","id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc","profile":"test"}}}}
I0129 00:31:25.008051 3160 sched.cpp:960] Rescinded offer f6dfea47-3650-4278-98b1-f3713d38a2ff-O3
I0129 00:31:25.008142 3160 sched.cpp:971] Scheduler::offerRescinded took 30809ns
I0129 00:31:25.008590 3165 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc,test)]:2048, offered or allocated: {}) on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 from framework f6dfe
a47-3650-4278-98b1-f3713d38a2ff-0000
I0129 00:31:25.008703 3157 master.cpp:12273] Removing offer f6dfea47-3650-4278-98b1-f3713d38a2ff-O3
I0129 00:31:25.010107 3165 hierarchical.cpp:1625] Framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 filtered agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 for 5secs
I0129 00:31:25.012970 3156 master.cpp:12138] Sending operation '' (uuid: b040b5ba-5282-4e19-a808-f61f2ffe2767) to agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 at slave(1249)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:25.013752 3164 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version
I0129 00:31:25.017030 3154 provider.cpp:498] Received APPLY_OPERATION event
I0129 00:31:25.017089 3154 provider.cpp:1351] Received CREATE operation '' (uuid: b040b5ba-5282-4e19-a808-f61f2ffe2767)
I0129 00:31:25.021564 3163 master.cpp:5958] Processing REVIVE call for framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419
I0129 00:31:25.022112 3163 hierarchical.cpp:1721] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000
I0129 00:31:25.023716 3163 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.400064ms
I0129 00:31:25.024180 3163 hierarchical.cpp:1853] Performed allocation for 1 agents in 199083ns
I0129 00:31:25.024420 3151 master.cpp:9974] Sending offers [ f6dfea47-3650-4278-98b1-f3713d38a2ff-O4 ] to framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419
I0129 00:31:25.025055 3158 sched.cpp:934] Scheduler::resourceOffers took 84009ns
I0129 00:31:25.036053 3152 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.3:32982
I0129 00:31:25.037024 3159 slave.cpp:8559] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 74326f60-548b-4f0e-a4cc-d86a78f41905) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0129 00:31:25.037204 3159 slave.cpp:9012] Updating the state of operation with no ID (uuid: 74326f60-548b-4f0e-a4cc-d86a78f41905) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0129 00:31:25.037252 3159 slave.cpp:8766] Forwarding status update of operation with no ID (operation_uuid: 74326f60-548b-4f0e-a4cc-d86a78f41905) for an operator API call
I0129 00:31:25.037611 3165 master.cpp:11790] Updating the state of operation '' (uuid: 74326f60-548b-4f0e-a4cc-d86a78f41905) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0129 00:31:25.038223 3155 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version
I0129 00:31:25.227874 3159 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 93279184-9d47-4ba7-afd2-aa77f7328dfd) for operation UUID b040b5ba-5282-4e19-a808-f61f2ffe2767 on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:25.227962 3159 status_update_manager_process.hpp:414] Creating operation status update stream b040b5ba-5282-4e19-a808-f61f2ffe2767 checkpoint=true
I0129 00:31:25.227984 3154 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0129 00:31:25.228227 3159 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 93279184-9d47-4ba7-afd2-aa77f7328dfd) for operation UUID b040b5ba-5282-4e19-a808-f61f2ffe2767 on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:25.322897 3159 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 93279184-9d47-4ba7-afd2-aa77f7328dfd) for operation UUID b040b5ba-5282-4e19-a808-f61f2ffe2767 on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:25.323273 3159 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: f3b7d01e-70ff-4cce-b081-1eaf15d6e166) for stream 74326f60-548b-4f0e-a4cc-d86a78f41905
I0129 00:31:25.323345 3159 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: f3b7d01e-70ff-4cce-b081-1eaf15d6e166) for operation UUID 74326f60-548b-4f0e-a4cc-d86a78f41905 on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:25.323951 3165 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.3:46419/slave(1249)/api/v1/resource_provider
I0129 00:31:25.325150 3158 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider'
I0129 00:31:25.369022 3166 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.3:32982
I0129 00:31:25.370829 3162 slave.cpp:8559] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: b040b5ba-5282-4e19-a808-f61f2ffe2767) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0129 00:31:25.371166 3162 slave.cpp:9012] Updating the state of operation with no ID (uuid: b040b5ba-5282-4e19-a808-f61f2ffe2767) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0129 00:31:25.371225 3162 slave.cpp:8766] Forwarding status update of operation with no ID (operation_uuid: b040b5ba-5282-4e19-a808-f61f2ffe2767) for an operator API call
I0129 00:31:25.371654 3154 master.cpp:11790] Updating the state of operation '' (uuid: b040b5ba-5282-4e19-a808-f61f2ffe2767) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0129 00:31:25.372238 3165 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version
I0129 00:31:25.374233 3160 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0129 00:31:25.401679 3159 status_update_manager_process.hpp:490] Cleaning up operation status update stream 74326f60-548b-4f0e-a4cc-d86a78f41905
I0129 00:31:25.401934 3159 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 93279184-9d47-4ba7-afd2-aa77f7328dfd) for stream b040b5ba-5282-4e19-a808-f61f2ffe2767
I0129 00:31:25.402034 3159 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 93279184-9d47-4ba7-afd2-aa77f7328dfd) for operation UUID b040b5ba-5282-4e19-a808-f61f2ffe2767 on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:25.546910 3159 status_update_manager_process.hpp:490] Cleaning up operation status update stream b040b5ba-5282-4e19-a808-f61f2ffe2767
I0129 00:31:25.649494 3165 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0129 00:31:25.651568 3161 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.3:33192
I0129 00:31:25.651958 3161 http.cpp:277] Processing call DESTROY_VOLUMES
I0129 00:31:25.653120 3161 master.cpp:3712] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"6ede652f-c732-4f42-aad5-d7e9b0dc8d53"},"name":"disk","type":"SCALAR","scalar":{"value":2048.0},"reservations":[{"type":"DYNAMIC","role":"storage"},{"type":"DYNAMIC","role":"storage/default-role","principal":"test-principal"}],"disk":{"persistence":{"id":"fc9674ca-1df3-4030-9eb6-f88ecead2646","principal":"test-principal"},"volume":{"mode":"RW","container_path":"volume"},"source":{"type":"MOUNT","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"vendor":"org.apache.mesos.csi.test.local","id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc","profile":"test"}}}}
I0129 00:31:25.655334 3152 sched.cpp:960] Rescinded offer f6dfea47-3650-4278-98b1-f3713d38a2ff-O4
I0129 00:31:25.655431 3152 sched.cpp:971] Scheduler::offerRescinded took 27572ns
I0129 00:31:25.656126 3160 master.cpp:12273] Removing offer f6dfea47-3650-4278-98b1-f3713d38a2ff-O4
I0129 00:31:25.656085 3155 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc,test),fc9674ca-1df3-4030-9eb6-f88ecead2646:volume]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc,test),fc9674ca-1df3-4030-9eb6-f88ecead2646:volume]:2048, offered
or allocated: {}) on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 from framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000
I0129 00:31:25.658223 3155 hierarchical.cpp:1625] Framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 filtered agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 for 5secs
I0129 00:31:25.661419 3158 master.cpp:12138] Sending operation '' (uuid: 1542de35-0f71-4969-b555-284b9a11e480) to agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 at slave(1249)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:25.661965 3156 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version
I0129 00:31:25.665379 3163 provider.cpp:498] Received APPLY_OPERATION event
I0129 00:31:25.665431 3163 provider.cpp:1351] Received DESTROY operation '' (uuid: 1542de35-0f71-4969-b555-284b9a11e480)
I0129 00:31:25.669777 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.164039ms
I0129 00:31:25.670529 3158 master.cpp:9974] Sending offers [ f6dfea47-3650-4278-98b1-f3713d38a2ff-O5 ] to framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419
I0129 00:31:25.671186 3165 sched.cpp:934] Scheduler::resourceOffers took 80116ns
I0129 00:31:25.813843 3151 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 4328a7d8-3862-459b-93a6-13e4df6f6924) for operation UUID 1542de35-0f71-4969-b555-284b9a11e480 on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:25.813957 3151 status_update_manager_process.hpp:414] Creating operation status update stream 1542de35-0f71-4969-b555-284b9a11e480 checkpoint=true
I0129 00:31:25.814327 3151 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 4328a7d8-3862-459b-93a6-13e4df6f6924) for operation UUID 1542de35-0f71-4969-b555-284b9a11e480 on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:25.885911 3151 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 4328a7d8-3862-459b-93a6-13e4df6f6924) for operation UUID 1542de35-0f71-4969-b555-284b9a11e480 on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:25.887162 3164 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.3:46419/slave(1249)/api/v1/resource_provider
I0129 00:31:25.888839 3161 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider'
I0129 00:31:25.893127 3159 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0129 00:31:25.895043 3163 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.3:33202
I0129 00:31:25.895432 3163 http.cpp:277] Processing call UNRESERVE_RESOURCES
I0129 00:31:25.896369 3163 master.cpp:3712] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"6ede652f-c732-4f42-aad5-d7e9b0dc8d53"},"name":"disk","type":"SCALAR","scalar":{"value":2048.0},"reservations":[{"type":"DYNAMIC","role":"storage"},{"type":"DYNAMIC","role":"storage/default-role","principal":"test-principal"}],"disk":{"source":{"type":"MOUNT","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"vendor":"org.apache.mesos.csi.test.local","id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc","profile":"test"}}}}
I0129 00:31:25.898185 3161 sched.cpp:960] Rescinded offer f6dfea47-3650-4278-98b1-f3713d38a2ff-O5
I0129 00:31:25.898293 3161 sched.cpp:971] Scheduler::offerRescinded took 31623ns
I0129 00:31:25.898880 3152 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc,test)]:2048, offered or allocated: {}) on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 from framework f6dfe
a47-3650-4278-98b1-f3713d38a2ff-0000
I0129 00:31:25.899106 3162 master.cpp:12273] Removing offer f6dfea47-3650-4278-98b1-f3713d38a2ff-O5
I0129 00:31:25.900720 3152 hierarchical.cpp:1625] Framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 filtered agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 for 5secs
I0129 00:31:25.903679 3153 master.cpp:12138] Sending operation '' (uuid: daf80f8a-17cf-4abf-82fd-5ea9b084f4ac) to agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 at slave(1249)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:25.904402 3153 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version
I0129 00:31:25.907567 3154 provider.cpp:498] Received APPLY_OPERATION event
I0129 00:31:25.907630 3154 provider.cpp:1351] Received UNRESERVE operation '' (uuid: daf80f8a-17cf-4abf-82fd-5ea9b084f4ac)
I0129 00:31:25.913898 3165 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.451195ms
I0129 00:31:25.914739 3158 master.cpp:9974] Sending offers [ f6dfea47-3650-4278-98b1-f3713d38a2ff-O6 ] to framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419
I0129 00:31:25.915490 3155 sched.cpp:934] Scheduler::resourceOffers took 94536ns
I0129 00:31:25.932633 3163 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.3:32982
I0129 00:31:25.933759 3161 slave.cpp:8559] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 1542de35-0f71-4969-b555-284b9a11e480) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0129 00:31:25.934018 3161 slave.cpp:9012] Updating the state of operation with no ID (uuid: 1542de35-0f71-4969-b555-284b9a11e480) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0129 00:31:25.934083 3161 slave.cpp:8766] Forwarding status update of operation with no ID (operation_uuid: 1542de35-0f71-4969-b555-284b9a11e480) for an operator API call
I0129 00:31:25.934687 3156 master.cpp:11790] Updating the state of operation '' (uuid: 1542de35-0f71-4969-b555-284b9a11e480) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0129 00:31:25.935452 3160 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version
I0129 00:31:26.085176 3161 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 6fd3b90e-a1bc-48b5-96fc-1ab0cea24f69) for operation UUID daf80f8a-17cf-4abf-82fd-5ea9b084f4ac on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:26.085286 3161 status_update_manager_process.hpp:414] Creating operation status update stream daf80f8a-17cf-4abf-82fd-5ea9b084f4ac checkpoint=true
I0129 00:31:26.085414 3154 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0129 00:31:26.085714 3161 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 6fd3b90e-a1bc-48b5-96fc-1ab0cea24f69) for operation UUID daf80f8a-17cf-4abf-82fd-5ea9b084f4ac on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:26.149340 3161 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 6fd3b90e-a1bc-48b5-96fc-1ab0cea24f69) for operation UUID daf80f8a-17cf-4abf-82fd-5ea9b084f4ac on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:26.149799 3161 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 4328a7d8-3862-459b-93a6-13e4df6f6924) for stream 1542de35-0f71-4969-b555-284b9a11e480
I0129 00:31:26.149868 3161 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 4328a7d8-3862-459b-93a6-13e4df6f6924) for operation UUID 1542de35-0f71-4969-b555-284b9a11e480 on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:26.150264 3162 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.3:46419/slave(1249)/api/v1/resource_provider
I0129 00:31:26.151674 3158 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider'
I0129 00:31:26.196456 3153 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.3:32982
I0129 00:31:26.197626 3151 slave.cpp:8559] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: daf80f8a-17cf-4abf-82fd-5ea9b084f4ac) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0129 00:31:26.197857 3151 slave.cpp:9012] Updating the state of operation with no ID (uuid: daf80f8a-17cf-4abf-82fd-5ea9b084f4ac) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0129 00:31:26.197911 3151 slave.cpp:8766] Forwarding status update of operation with no ID (operation_uuid: daf80f8a-17cf-4abf-82fd-5ea9b084f4ac) for an operator API call
I0129 00:31:26.198307 3154 master.cpp:11790] Updating the state of operation '' (uuid: daf80f8a-17cf-4abf-82fd-5ea9b084f4ac) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0129 00:31:26.198941 3162 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version
I0129 00:31:26.200596 3163 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0129 00:31:26.233551 3161 status_update_manager_process.hpp:490] Cleaning up operation status update stream 1542de35-0f71-4969-b555-284b9a11e480
I0129 00:31:26.233840 3161 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 6fd3b90e-a1bc-48b5-96fc-1ab0cea24f69) for stream daf80f8a-17cf-4abf-82fd-5ea9b084f4ac
I0129 00:31:26.233948 3161 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 6fd3b90e-a1bc-48b5-96fc-1ab0cea24f69) for operation UUID daf80f8a-17cf-4abf-82fd-5ea9b084f4ac on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:26.317654 3161 status_update_manager_process.hpp:490] Cleaning up operation status update stream daf80f8a-17cf-4abf-82fd-5ea9b084f4ac
I0129 00:31:26.440923 3165 master.cpp:1414] Framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419 disconnected
I0129 00:31:26.440977 3165 master.cpp:3333] Deactivating framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419
I0129 00:31:26.441370 3158 hierarchical.cpp:813] Deactivated framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000
I0129 00:31:26.441879 3159 slave.cpp:989] Agent terminating
I0129 00:31:26.442044 3165 master.cpp:12273] Removing offer f6dfea47-3650-4278-98b1-f3713d38a2ff-O6
I0129 00:31:26.441953 3158 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_weD2MV/2GB-58a42de1-e3eb-4c51-98cc-6f9a0cf92efc,test)]:2048, offered or allocated: {}) on agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 from framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000
I0129 00:31:26.442162 3165 master.cpp:3310] Disconnecting framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419
I0129 00:31:26.442240 3165 master.cpp:1429] Giving framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419 0ns to failover
I0129 00:31:26.442775 3159 manager.cpp:127] Terminating resource provider 6ede652f-c732-4f42-aad5-d7e9b0dc8d53
I0129 00:31:26.443202 3164 master.cpp:1299] Agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 at slave(1249)@172.17.0.3:46419 (1a3d67eabb35) disconnected
I0129 00:31:26.443240 3164 master.cpp:3368] Disconnecting agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 at slave(1249)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:26.443331 3164 master.cpp:3387] Deactivating agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 at slave(1249)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:26.443532 3164 master.cpp:9760] Framework failover timeout, removing framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419
I0129 00:31:26.443570 3164 master.cpp:10762] Removing framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000 (default) at scheduler-8b05a517-7d36-4438-a8ef-59bb9eb3fe67@172.17.0.3:46419
E0129 00:31:26.443698 3160 http_connection.hpp:449] End-Of-File received
I0129 00:31:26.443789 3158 hierarchical.cpp:1156] Agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0 deactivated
I0129 00:31:26.444021 3166 hierarchical.cpp:1777] Allocation paused
I0129 00:31:26.444243 3160 http_connection.hpp:217] Re-detecting endpoint
I0129 00:31:26.444614 3166 hierarchical.cpp:757] Removed framework f6dfea47-3650-4278-98b1-f3713d38a2ff-0000
I0129 00:31:26.444674 3160 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0129 00:31:26.444689 3166 hierarchical.cpp:1787] Allocation resumed
I0129 00:31:26.444725 3160 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0129 00:31:26.444789 3162 provider.cpp:488] Disconnected from resource provider manager
I0129 00:31:26.444821 3160 http_connection.hpp:227] New endpoint detected at http://172.17.0.3:46419/slave(1249)/api/v1/resource_provider
I0129 00:31:26.444995 3156 status_update_manager_process.hpp:379] Pausing operation status update manager
I0129 00:31:26.446163 3153 containerizer.cpp:2619] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0129 00:31:26.446210 3153 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 3.966571904secs
I0129 00:31:26.446595 3153 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:26.447376 3162 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.3:46419/slave(1249)/api/v1/resource_provider
I0129 00:31:26.448009 3163 provider.cpp:476] Connected to resource provider manager
I0129 00:31:26.448388 3155 hierarchical.cpp:1853] Performed allocation for 1 agents in 184259ns
I0129 00:31:26.448642 3165 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.3:46419/slave(1249)/api/v1/resource_provider
I0129 00:31:26.449359 3167 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1/resource_provider'
E0129 00:31:26.450754 3156 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0129 00:31:26.500020 3162 hierarchical.cpp:1853] Performed allocation for 1 agents in 246636ns
I0129 00:31:26.550271 3151 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0129 00:31:26.551939 3165 hierarchical.cpp:1853] Performed allocation for 1 agents in 196259ns
I0129 00:31:26.552322 3151 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:26.555398 3152 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'
I0129 00:31:26.555630 3152 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-O3RVsC/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:26.555841 3165 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:26.559051 3167 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1'
I0129 00:31:26.572190 3150 master.cpp:1140] Master terminating
I0129 00:31:26.573210 3161 hierarchical.cpp:1132] Removed all filters for agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
I0129 00:31:26.573243 3161 hierarchical.cpp:1008] Removed agent f6dfea47-3650-4278-98b1-f3713d38a2ff-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (3853 ms)
[ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v0
I0129 00:31:26.617286 3150 cluster.cpp:180] Creating default 'local' authorizer
I0129 00:31:26.622674 3157 master.cpp:443] Master 9164103e-e341-424b-b6d8-81630cb0a623 (1a3d67eabb35) started on 172.17.0.3:46419
I0129 00:31:26.622721 3157 master.cpp:446] 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/6X7iHQ/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="/tmp/SRC/build/mesos-1.10.0/_inst/share/mesos/webui" --work_dir="/tmp/6X7iHQ/master" --zk_session_timeout="10secs"
I0129 00:31:26.623257 3157 master.cpp:495] Master only allowing authenticated frameworks to register
I0129 00:31:26.623286 3157 master.cpp:501] Master only allowing authenticated agents to register
I0129 00:31:26.623313 3157 master.cpp:507] Master only allowing authenticated HTTP frameworks to register
I0129 00:31:26.623338 3157 credentials.hpp:37] Loading credentials for authentication from '/tmp/6X7iHQ/credentials'
I0129 00:31:26.623875 3157 master.cpp:551] Using default 'crammd5' authenticator
I0129 00:31:26.624081 3157 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0129 00:31:26.624312 3157 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0129 00:31:26.624493 3157 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0129 00:31:26.624663 3157 master.cpp:632] Authorization enabled
I0129 00:31:26.625062 3159 hierarchical.cpp:567] Initialized hierarchical allocator process
I0129 00:31:26.625080 3166 whitelist_watcher.cpp:77] No whitelist given
I0129 00:31:26.628299 3161 master.cpp:2172] Elected as the leading master!
I0129 00:31:26.628340 3161 master.cpp:1668] Recovering from registrar
I0129 00:31:26.628625 3152 registrar.cpp:339] Recovering registrar
I0129 00:31:26.629551 3152 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0129 00:31:26.629698 3152 registrar.cpp:487] Applied 1 operations in 48811ns; attempting to update the registry
I0129 00:31:26.630481 3152 registrar.cpp:544] Successfully updated the registry in 0ns
I0129 00:31:26.630635 3152 registrar.cpp:416] Successfully recovered registrar
I0129 00:31:26.631223 3164 master.cpp:1821] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
I0129 00:31:26.631255 3159 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover
W0129 00:31:26.637284 3150 process.cpp:2877] Attempted to spawn already running process files@172.17.0.3:46419
I0129 00:31:26.638769 3150 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0129 00:31:26.648255 3150 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0129 00:31:26.648288 3150 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0129 00:31:26.648306 3150 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0129 00:31:26.648340 3150 provisioner.cpp:294] Using default backend 'copy'
I0129 00:31:26.651506 3150 cluster.cpp:527] Creating default 'local' authorizer
I0129 00:31:26.654321 3162 slave.cpp:270] Mesos agent started on (1250)@172.17.0.3:46419
I0129 00:31:26.654359 3162 slave.cpp:271] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/6X7iHQ/oGVsIa/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/6X7iHQ/oGVsIa/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/6X7iHQ/oGVsIa/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/6X7iHQ/oGVsIa/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/6X7iHQ/oGVsIa/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/6X7iHQ/oGVsIa/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posi
x" --launcher_dir="/tmp/SRC/build/mesos-1.10.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/6X7iHQ/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_6ZF9al" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLoca
lResourceProviderTest_Update_v0_Ie4QDv" --zk_session_timeout="10secs"
I0129 00:31:26.655052 3162 credentials.hpp:86] Loading credential for authentication from '/tmp/6X7iHQ/oGVsIa/credential'
I0129 00:31:26.655243 3162 slave.cpp:303] Agent using credential for: test-principal
I0129 00:31:26.655288 3162 credentials.hpp:37] Loading credentials for authentication from '/tmp/6X7iHQ/oGVsIa/http_credentials'
I0129 00:31:26.655562 3162 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0129 00:31:26.656008 3162 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0129 00:31:26.656729 3157 hierarchical.cpp:1853] Performed allocation for 0 agents in 106142ns
I0129 00:31:26.657896 3163 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0129 00:31:26.657855 3162 slave.cpp:618] 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"}]
I0129 00:31:26.658198 3162 slave.cpp:626] Agent attributes: [ ]
I0129 00:31:26.658221 3162 slave.cpp:635] Agent hostname: 1a3d67eabb35
I0129 00:31:26.658493 3158 task_status_update_manager.cpp:181] Pausing sending task status updates
I0129 00:31:26.658582 3154 status_update_manager_process.hpp:379] Pausing operation status update manager
I0129 00:31:26.660459 3165 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Ie4QDv/meta'
I0129 00:31:26.660737 3153 slave.cpp:7568] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Ie4QDv/meta', beginning agent recovery
I0129 00:31:26.661386 3152 task_status_update_manager.cpp:207] Recovering task status update manager
I0129 00:31:26.661904 3160 containerizer.cpp:820] Recovering Mesos containers
I0129 00:31:26.662274 3160 containerizer.cpp:1160] Recovering isolators
I0129 00:31:26.663357 3166 containerizer.cpp:1199] Recovering provisioner
I0129 00:31:26.664165 3159 provisioner.cpp:518] Provisioner recovery complete
I0129 00:31:26.665103 3155 composing.cpp:339] Finished recovering all containerizers
I0129 00:31:26.665452 3156 slave.cpp:8050] Recovering executors
I0129 00:31:26.665586 3156 slave.cpp:8203] Finished recovery
I0129 00:31:26.666688 3166 slave.cpp:1416] New master detected at master@172.17.0.3:46419
I0129 00:31:26.666705 3165 task_status_update_manager.cpp:181] Pausing sending task status updates
I0129 00:31:26.666733 3157 status_update_manager_process.hpp:379] Pausing operation status update manager
I0129 00:31:26.666918 3166 slave.cpp:1481] Detecting new master
I0129 00:31:26.674455 3164 slave.cpp:1508] Authenticating with master master@172.17.0.3:46419
I0129 00:31:26.674585 3164 slave.cpp:1517] Using default CRAM-MD5 authenticatee
I0129 00:31:26.674965 3161 authenticatee.cpp:121] Creating new client SASL connection
I0129 00:31:26.675284 3162 master.cpp:10159] Authenticating slave(1250)@172.17.0.3:46419
I0129 00:31:26.675480 3154 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2109)@172.17.0.3:46419
I0129 00:31:26.675889 3163 authenticator.cpp:98] Creating new server SASL connection
I0129 00:31:26.676144 3155 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0129 00:31:26.676179 3155 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0129 00:31:26.676318 3160 authenticator.cpp:204] Received SASL authentication start
I0129 00:31:26.676394 3160 authenticator.cpp:326] Authentication requires more steps
I0129 00:31:26.676494 3160 authenticatee.cpp:259] Received SASL authentication step
I0129 00:31:26.676641 3152 authenticator.cpp:232] Received SASL authentication step
I0129 00:31:26.676682 3152 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '1a3d67eabb35' server FQDN: '1a3d67eabb35' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0129 00:31:26.676697 3152 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0129 00:31:26.676748 3152 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0129 00:31:26.676803 3152 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '1a3d67eabb35' server FQDN: '1a3d67eabb35' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0129 00:31:26.676831 3152 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0129 00:31:26.676857 3152 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0129 00:31:26.676892 3152 authenticator.cpp:318] Authentication success
I0129 00:31:26.677098 3153 authenticatee.cpp:299] Authentication success
I0129 00:31:26.677188 3158 master.cpp:10191] Successfully authenticated principal 'test-principal' at slave(1250)@172.17.0.3:46419
I0129 00:31:26.677213 3165 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2109)@172.17.0.3:46419
I0129 00:31:26.677723 3157 slave.cpp:1608] Successfully authenticated with master master@172.17.0.3:46419
I0129 00:31:26.678263 3157 slave.cpp:2058] Will retry registration in 14.042508ms if necessary
I0129 00:31:26.678524 3161 master.cpp:6629] Received register agent message from slave(1250)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:26.678858 3161 master.cpp:3712] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0129 00:31:26.679661 3155 master.cpp:6696] Authorized registration of agent at slave(1250)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:26.679766 3155 master.cpp:6808] Registering agent at slave(1250)@172.17.0.3:46419 (1a3d67eabb35) with id 9164103e-e341-424b-b6d8-81630cb0a623-S0
I0129 00:31:26.680385 3160 registrar.cpp:487] Applied 1 operations in 201110ns; attempting to update the registry
I0129 00:31:26.681113 3151 registrar.cpp:544] Successfully updated the registry in 630272ns
I0129 00:31:26.681419 3164 master.cpp:6856] Admitted agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 at slave(1250)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:26.682320 3164 master.cpp:6901] Registered agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 at slave(1250)@172.17.0.3:46419 (1a3d67eabb35) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0129 00:31:26.682482 3157 slave.cpp:1641] Registered with master master@172.17.0.3:46419; given agent ID 9164103e-e341-424b-b6d8-81630cb0a623-S0
I0129 00:31:26.682615 3153 hierarchical.cpp:959] Added agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 (1a3d67eabb35) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
I0129 00:31:26.682670 3161 task_status_update_manager.cpp:188] Resuming sending task status updates
I0129 00:31:26.683012 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 165746ns
I0129 00:31:26.708436 3163 hierarchical.cpp:1853] Performed allocation for 1 agents in 107554ns
I0129 00:31:26.721105 3157 slave.cpp:1676] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Ie4QDv/meta/slaves/9164103e-e341-424b-b6d8-81630cb0a623-S0/slave.info'
I0129 00:31:26.721307 3162 status_update_manager_process.hpp:385] Resuming operation status update manager
I0129 00:31:26.722273 3157 slave.cpp:1728] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"/Lw+4JjBTISRqQbMYJQdSg=="},"slave_id":{"value":"9164103e-e341-424b-b6d8-81630cb0a623-S0"},"update_oversubscribed_resources":false}
I0129 00:31:26.723289 3166 master.cpp:8039] Ignoring update on agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 at slave(1250)@172.17.0.3:46419 (1a3d67eabb35) as it reports no changes
I0129 00:31:26.727766 3152 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1'
I0129 00:31:26.729269 3166 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.3:33214
I0129 00:31:26.729763 3166 http.cpp:2296] Processing GET_CONTAINERS call
I0129 00:31:26.759443 3161 hierarchical.cpp:1853] Performed allocation for 1 agents in 184604ns
I0129 00:31:26.762063 3153 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:26.765027 3164 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1'
I0129 00:31:26.766232 3157 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.3:33216
I0129 00:31:26.767037 3157 http.cpp:2756] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:26.768137 3154 http.cpp:2860] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Ie4QDv/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:26.791399 3159 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:26.792179 3159 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 305920ns
I0129 00:31:26.793162 3159 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_6ZF9al/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0129 00:31:26.793231 3159 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.054208ms
I0129 00:31:26.796731 3163 containerizer.cpp:2099] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_oDzz6F","--available_capacity=0B","--volumes=","--forward=unix:///tmp/6X7iHQ/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Ie4QDv/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-p3p9Pv/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Ie4QDv/containers/o
rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="109" --pipe_write="110" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_6ZF9al/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0129 00:31:26.807646 3163 launcher.cpp:145] Forked child with pid '14672' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:26.808784 3163 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 15.5328ms
I0129 00:31:26.810973 3163 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 2.177024ms
I0129 00:31:26.811453 3155 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Ie4QDv/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:26.812080 3160 hierarchical.cpp:1853] Performed allocation for 1 agents in 275059ns
I0129 00:31:26.812795 3164 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 1.840128ms
I0129 00:31:26.815891 3161 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'
I0129 00:31:26.816030 3161 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-p3p9Pv/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:26.863654 3164 hierarchical.cpp:1853] Performed allocation for 1 agents in 181285ns
I0129 00:31:26.915076 3166 hierarchical.cpp:1853] Performed allocation for 1 agents in 185599ns
I0129 00:31:26.966099 3160 hierarchical.cpp:1853] Performed allocation for 1 agents in 175012ns
I0129 00:31:27.017369 3159 hierarchical.cpp:1853] Performed allocation for 1 agents in 191758ns
I0129 00:31:27.068631 3155 hierarchical.cpp:1853] Performed allocation for 1 agents in 239534ns
I0129 00:31:27.120347 3152 hierarchical.cpp:1853] Performed allocation for 1 agents in 216696ns
I0129 00:31:27.148115 3166 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-p3p9Pv/endpoint.sock' with CSI v1
I0129 00:31:27.169950 3163 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-p3p9Pv/endpoint.sock' with CSI v0
I0129 00:31:27.171133 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/Probe call
I0129 00:31:27.171878 3160 hierarchical.cpp:1853] Performed allocation for 1 agents in 218691ns
I0129 00:31:27.173740 3156 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:27.176776 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginCapabilities call
I0129 00:31:27.177572 3162 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1'
I0129 00:31:27.178867 3151 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.3:33276
I0129 00:31:27.179545 3151 http.cpp:2974] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:27.181217 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call
I0129 00:31:27.181526 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call
I0129 00:31:27.183007 3163 v0_volume_manager.cpp:628] NODE_SERVICE loaded: {}
I0129 00:31:27.184176 3152 v0_volume_manager.cpp:628] CONTROLLER_SERVICE loaded: {}
I0129 00:31:27.186273 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ControllerGetCapabilities call
I0129 00:31:27.189991 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetCapabilities call
I0129 00:31:27.192901 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetId call
I0129 00:31:27.195078 3156 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0129 00:31:27.195276 3158 status_update_manager_process.hpp:379] Pausing operation status update manager
I0129 00:31:27.195677 3161 http_connection.hpp:227] New endpoint detected at http://172.17.0.3:46419/slave(1250)/api/v1/resource_provider
I0129 00:31:27.198688 3154 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.3:46419/slave(1250)/api/v1/resource_provider
I0129 00:31:27.199461 3151 provider.cpp:476] Connected to resource provider manager
I0129 00:31:27.200073 3153 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.3:46419/slave(1250)/api/v1/resource_provider
I0129 00:31:27.201288 3161 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider'
I0129 00:31:27.203142 3163 http.cpp:1405] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.3:33284
I0129 00:31:27.203960 3160 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_oDzz6F","--available_capacity=0B","--volumes=","--forward=unix:///tmp/6X7iHQ/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}
I0129 00:31:27.223059 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 190810ns
I0129 00:31:27.242820 3161 slave.cpp:8559] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"d4f6324b-ca34-42b5-958d-bb02a95f2930"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_oDzz6F","--available_capacity=0B","--volumes=","--forward=unix:///tmp/6X7iHQ/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}'
I0129 00:31:27.244585 3164 provider.cpp:498] Received SUBSCRIBED event
I0129 00:31:27.244638 3164 provider.cpp:1309] Subscribed with ID d4f6324b-ca34-42b5-958d-bb02a95f2930
I0129 00:31:27.273924 3151 status_update_manager_process.hpp:314] Recovering operation status update manager
I0129 00:31:27.274317 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 199401ns
I0129 00:31:27.325789 3165 hierarchical.cpp:1853] Performed allocation for 1 agents in 235934ns
I0129 00:31:27.361882 3152 provider.cpp:790] Reconciling storage pools and volumes
I0129 00:31:27.364686 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call
I0129 00:31:27.367779 3152 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 9164103e-e341-424b-b6d8-81630cb0a623-S0
I0129 00:31:27.368139 3152 provider.cpp:748] Resource provider d4f6324b-ca34-42b5-958d-bb02a95f2930 is in READY state
I0129 00:31:27.368121 3157 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.3:46419/slave(1250)/api/v1/resource_provider
I0129 00:31:27.368216 3166 status_update_manager_process.hpp:385] Resuming operation status update manager
I0129 00:31:27.368876 3154 provider.cpp:1235] Updating profiles { test } for resource provider d4f6324b-ca34-42b5-958d-bb02a95f2930
I0129 00:31:27.369572 3155 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider'
I0129 00:31:27.370132 3159 provider.cpp:790] Reconciling storage pools and volumes
I0129 00:31:27.371217 3153 http.cpp:1405] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.3:33282
I0129 00:31:27.371894 3151 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider d4f6324b-ca34-42b5-958d-bb02a95f2930
I0129 00:31:27.372153 3166 slave.cpp:8559] Handling resource provider message 'UPDATE_STATE: d4f6324b-ca34-42b5-958d-bb02a95f2930 {}'
I0129 00:31:27.372259 3166 slave.cpp:8679] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0129 00:31:27.372440 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call
I0129 00:31:27.372803 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call
I0129 00:31:27.374163 3155 hierarchical.cpp:1110] Grew agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 by {} (total), { } (used)
I0129 00:31:27.374579 3155 hierarchical.cpp:1067] Agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 (1a3d67eabb35) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0129 00:31:27.377897 3159 hierarchical.cpp:1853] Performed allocation for 1 agents in 242415ns
I0129 00:31:27.378154 3156 provider.cpp:790] Reconciling storage pools and volumes
I0129 00:31:27.380285 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call
I0129 00:31:27.380888 14676 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call
I0129 00:31:27.391206 3161 slave.cpp:989] Agent terminating
I0129 00:31:27.391939 3161 manager.cpp:127] Terminating resource provider d4f6324b-ca34-42b5-958d-bb02a95f2930
I0129 00:31:27.392407 3153 master.cpp:1299] Agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 at slave(1250)@172.17.0.3:46419 (1a3d67eabb35) disconnected
I0129 00:31:27.392447 3153 master.cpp:3368] Disconnecting agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 at slave(1250)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:27.392527 3153 master.cpp:3387] Deactivating agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 at slave(1250)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:27.392649 3165 hierarchical.cpp:1156] Agent 9164103e-e341-424b-b6d8-81630cb0a623-S0 deactivated
E0129 00:31:27.392973 3152 http_connection.hpp:449] End-Of-File received
I0129 00:31:27.393391 3152 http_connection.hpp:217] Re-detecting endpoint
I0129 00:31:27.393787 3152 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0129 00:31:27.393846 3164 provider.cpp:488] Disconnected from resource provider manager
I0129 00:31:27.393882 3152 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0129 00:31:27.393962 3152 http_connection.hpp:227] New endpoint detected at http://172.17.0.3:46419/slave(1250)/api/v1/resource_provider
I0129 00:31:27.394018 3162 status_update_manager_process.hpp:379] Pausing operation status update manager
I0129 00:31:27.395519 3155 containerizer.cpp:2619] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0129 00:31:27.395586 3155 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.582806016secs
I0129 00:31:27.396024 3155 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:27.396824 3161 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.3:46419/slave(1250)/api/v1/resource_provider
I0129 00:31:27.397428 3163 provider.cpp:476] Connected to resource provider manager
I0129 00:31:27.398152 3151 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.3:46419/slave(1250)/api/v1/resource_provider
I0129 00:31:27.399022 3167 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1/resource_provider'
E0129 00:31:27.400393 3164 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0129 00:31:27.425447 3166 hierarchical.cpp:1853] Performed allocation for 1 agents in 157328ns
I0129 00:31:27.475783 3161 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0129 00:31:27.476275 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 139241ns
I0129 00:31:27.477697 3164 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:27.481112 3154 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'
I0129 00:31:27.481308 3154 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-p3p9Pv/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:27.481529 3156 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:27.484742 3167 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1'
I0129 00:31:27.496157 3150 master.cpp:1140] Master terminating
I0129 00:31:27.496583 3152 hierarchical.cpp:1132] Removed all filters for agent 9164103e-e341-424b-b6d8-81630cb0a623-S0
I0129 00:31:27.496610 3152 hierarchical.cpp:1008] Removed agent 9164103e-e341-424b-b6d8-81630cb0a623-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (939 ms)
[ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v1
I0129 00:31:27.529675 3150 cluster.cpp:180] Creating default 'local' authorizer
I0129 00:31:27.536123 3151 master.cpp:443] Master 4519a442-4e9b-487f-99d6-57d67031e9d9 (1a3d67eabb35) started on 172.17.0.3:46419
I0129 00:31:27.536161 3151 master.cpp:446] 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/KHaqMA/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="/tmp/SRC/build/mesos-1.10.0/_inst/share/mesos/webui" --work_dir="/tmp/KHaqMA/master" --zk_session_timeout="10secs"
I0129 00:31:27.536636 3151 master.cpp:495] Master only allowing authenticated frameworks to register
I0129 00:31:27.536654 3151 master.cpp:501] Master only allowing authenticated agents to register
I0129 00:31:27.536665 3151 master.cpp:507] Master only allowing authenticated HTTP frameworks to register
I0129 00:31:27.536677 3151 credentials.hpp:37] Loading credentials for authentication from '/tmp/KHaqMA/credentials'
I0129 00:31:27.555562 3151 master.cpp:551] Using default 'crammd5' authenticator
I0129 00:31:27.555778 3151 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0129 00:31:27.556012 3151 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0129 00:31:27.556205 3151 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0129 00:31:27.556380 3151 master.cpp:632] Authorization enabled
I0129 00:31:27.556713 3159 hierarchical.cpp:567] Initialized hierarchical allocator process
I0129 00:31:27.556723 3160 whitelist_watcher.cpp:77] No whitelist given
I0129 00:31:27.559728 3163 master.cpp:2172] Elected as the leading master!
I0129 00:31:27.559767 3163 master.cpp:1668] Recovering from registrar
I0129 00:31:27.560078 3166 registrar.cpp:339] Recovering registrar
I0129 00:31:27.561072 3166 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0129 00:31:27.561239 3166 registrar.cpp:487] Applied 1 operations in 53080ns; attempting to update the registry
I0129 00:31:27.562106 3166 registrar.cpp:544] Successfully updated the registry in 0ns
I0129 00:31:27.562281 3166 registrar.cpp:416] Successfully recovered registrar
I0129 00:31:27.562882 3160 master.cpp:1821] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
I0129 00:31:27.562944 3159 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover
W0129 00:31:27.575731 3150 process.cpp:2877] Attempted to spawn already running process files@172.17.0.3:46419
I0129 00:31:27.577410 3150 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0129 00:31:27.578280 3150 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0129 00:31:27.578317 3150 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0129 00:31:27.578339 3150 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0129 00:31:27.578380 3150 provisioner.cpp:294] Using default backend 'copy'
I0129 00:31:27.582556 3150 cluster.cpp:527] Creating default 'local' authorizer
I0129 00:31:27.585551 3152 slave.cpp:270] Mesos agent started on (1251)@172.17.0.3:46419
I0129 00:31:27.585582 3152 slave.cpp:271] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/KHaqMA/y9qrC4/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/KHaqMA/y9qrC4/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/KHaqMA/y9qrC4/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/KHaqMA/y9qrC4/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/KHaqMA/y9qrC4/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/KHaqMA/y9qrC4/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posi
x" --launcher_dir="/tmp/SRC/build/mesos-1.10.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/KHaqMA/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_E94HCc" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLoca
lResourceProviderTest_Update_v1_uHCZCk" --zk_session_timeout="10secs"
I0129 00:31:27.586141 3152 credentials.hpp:86] Loading credential for authentication from '/tmp/KHaqMA/y9qrC4/credential'
I0129 00:31:27.586313 3152 slave.cpp:303] Agent using credential for: test-principal
I0129 00:31:27.586338 3152 credentials.hpp:37] Loading credentials for authentication from '/tmp/KHaqMA/y9qrC4/http_credentials'
I0129 00:31:27.586621 3152 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0129 00:31:27.587004 3152 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0129 00:31:27.587762 3151 hierarchical.cpp:1853] Performed allocation for 0 agents in 109530ns
I0129 00:31:27.588762 3161 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0129 00:31:27.588572 3152 slave.cpp:618] 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"}]
I0129 00:31:27.588847 3152 slave.cpp:626] Agent attributes: [ ]
I0129 00:31:27.588867 3152 slave.cpp:635] Agent hostname: 1a3d67eabb35
I0129 00:31:27.589112 3162 status_update_manager_process.hpp:379] Pausing operation status update manager
I0129 00:31:27.589131 3157 task_status_update_manager.cpp:181] Pausing sending task status updates
I0129 00:31:27.590654 3153 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_uHCZCk/meta'
I0129 00:31:27.590920 3155 slave.cpp:7568] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_uHCZCk/meta', beginning agent recovery
I0129 00:31:27.591509 3156 task_status_update_manager.cpp:207] Recovering task status update manager
I0129 00:31:27.592133 3159 containerizer.cpp:820] Recovering Mesos containers
I0129 00:31:27.592497 3159 containerizer.cpp:1160] Recovering isolators
I0129 00:31:27.593477 3165 containerizer.cpp:1199] Recovering provisioner
I0129 00:31:27.594245 3156 provisioner.cpp:518] Provisioner recovery complete
I0129 00:31:27.595257 3163 composing.cpp:339] Finished recovering all containerizers
I0129 00:31:27.595620 3152 slave.cpp:8050] Recovering executors
I0129 00:31:27.595727 3152 slave.cpp:8203] Finished recovery
I0129 00:31:27.596559 3160 task_status_update_manager.cpp:181] Pausing sending task status updates
I0129 00:31:27.596575 3151 status_update_manager_process.hpp:379] Pausing operation status update manager
I0129 00:31:27.596587 3165 slave.cpp:1416] New master detected at master@172.17.0.3:46419
I0129 00:31:27.596763 3165 slave.cpp:1481] Detecting new master
I0129 00:31:27.602231 3154 slave.cpp:1508] Authenticating with master master@172.17.0.3:46419
I0129 00:31:27.602382 3154 slave.cpp:1517] Using default CRAM-MD5 authenticatee
I0129 00:31:27.602764 3162 authenticatee.cpp:121] Creating new client SASL connection
I0129 00:31:27.603135 3162 master.cpp:10159] Authenticating slave(1251)@172.17.0.3:46419
I0129 00:31:27.603288 3157 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2110)@172.17.0.3:46419
I0129 00:31:27.603617 3164 authenticator.cpp:98] Creating new server SASL connection
I0129 00:31:27.603884 3163 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0129 00:31:27.603926 3163 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0129 00:31:27.604127 3159 authenticator.cpp:204] Received SASL authentication start
I0129 00:31:27.604226 3159 authenticator.cpp:326] Authentication requires more steps
I0129 00:31:27.604379 3159 authenticatee.cpp:259] Received SASL authentication step
I0129 00:31:27.604509 3159 authenticator.cpp:232] Received SASL authentication step
I0129 00:31:27.604545 3159 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '1a3d67eabb35' server FQDN: '1a3d67eabb35' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0129 00:31:27.604559 3159 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0129 00:31:27.604619 3159 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0129 00:31:27.604655 3159 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '1a3d67eabb35' server FQDN: '1a3d67eabb35' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0129 00:31:27.604673 3159 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0129 00:31:27.604682 3159 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0129 00:31:27.604699 3159 authenticator.cpp:318] Authentication success
I0129 00:31:27.604849 3153 authenticatee.cpp:299] Authentication success
I0129 00:31:27.604995 3160 master.cpp:10191] Successfully authenticated principal 'test-principal' at slave(1251)@172.17.0.3:46419
I0129 00:31:27.605042 3161 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2110)@172.17.0.3:46419
I0129 00:31:27.605214 3151 slave.cpp:1608] Successfully authenticated with master master@172.17.0.3:46419
I0129 00:31:27.605655 3151 slave.cpp:2058] Will retry registration in 855008ns if necessary
I0129 00:31:27.605823 3166 master.cpp:6629] Received register agent message from slave(1251)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:27.606215 3166 master.cpp:3712] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0129 00:31:27.606956 3163 master.cpp:6696] Authorized registration of agent at slave(1251)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:27.607059 3163 master.cpp:6808] Registering agent at slave(1251)@172.17.0.3:46419 (1a3d67eabb35) with id 4519a442-4e9b-487f-99d6-57d67031e9d9-S0
I0129 00:31:27.607296 3155 slave.cpp:2058] Will retry registration in 25.513896ms if necessary
I0129 00:31:27.607465 3160 master.cpp:6622] Ignoring register agent message from slave(1251)@172.17.0.3:46419 (1a3d67eabb35) as registration is already in progress
I0129 00:31:27.607666 3163 registrar.cpp:487] Applied 1 operations in 203637ns; attempting to update the registry
I0129 00:31:27.608363 3163 registrar.cpp:544] Successfully updated the registry in 619008ns
I0129 00:31:27.608575 3161 master.cpp:6856] Admitted agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 at slave(1251)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:27.609416 3161 master.cpp:6901] Registered agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 at slave(1251)@172.17.0.3:46419 (1a3d67eabb35) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0129 00:31:27.609536 3151 slave.cpp:1641] Registered with master master@172.17.0.3:46419; given agent ID 4519a442-4e9b-487f-99d6-57d67031e9d9-S0
I0129 00:31:27.609642 3157 hierarchical.cpp:959] Added agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 (1a3d67eabb35) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
I0129 00:31:27.609694 3162 task_status_update_manager.cpp:188] Resuming sending task status updates
I0129 00:31:27.609961 3157 hierarchical.cpp:1853] Performed allocation for 1 agents in 136382ns
I0129 00:31:27.639408 3164 hierarchical.cpp:1853] Performed allocation for 1 agents in 132829ns
I0129 00:31:27.645102 3151 slave.cpp:1676] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_uHCZCk/meta/slaves/4519a442-4e9b-487f-99d6-57d67031e9d9-S0/slave.info'
I0129 00:31:27.645237 3152 status_update_manager_process.hpp:385] Resuming operation status update manager
I0129 00:31:27.646188 3151 slave.cpp:1728] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"TvbbK07zRoW+3ZVcpB2BTw=="},"slave_id":{"value":"4519a442-4e9b-487f-99d6-57d67031e9d9-S0"},"update_oversubscribed_resources":false}
I0129 00:31:27.647461 3156 master.cpp:8039] Ignoring update on agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 at slave(1251)@172.17.0.3:46419 (1a3d67eabb35) as it reports no changes
I0129 00:31:27.651139 3165 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1'
I0129 00:31:27.652463 3154 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.3:33346
I0129 00:31:27.653023 3154 http.cpp:2296] Processing GET_CONTAINERS call
I0129 00:31:27.659405 3154 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:27.662097 3155 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1'
I0129 00:31:27.663311 3152 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.3:33354
I0129 00:31:27.664018 3152 http.cpp:2756] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:27.664980 3165 http.cpp:2860] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_uHCZCk/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:27.665838 3156 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:27.666473 3156 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 267008ns
I0129 00:31:27.667186 3156 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_E94HCc/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0129 00:31:27.667233 3156 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 762112ns
I0129 00:31:27.670490 3164 containerizer.cpp:2099] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_4bLoEs","--available_capacity=0B","--volumes=","--forward=unix:///tmp/KHaqMA/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_uHCZCk/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-OYHNiz/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_uHCZCk/containers/o
rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="107" --pipe_write="108" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_E94HCc/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0129 00:31:27.679608 3164 launcher.cpp:145] Forked child with pid '14685' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:27.680516 3164 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 13.272064ms
I0129 00:31:27.681799 3164 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 1.277952ms
I0129 00:31:27.682086 3155 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_uHCZCk/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:27.683398 3157 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 1.517056ms
I0129 00:31:27.686317 3153 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'
I0129 00:31:27.686671 3163 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-OYHNiz/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:27.690747 3156 hierarchical.cpp:1853] Performed allocation for 1 agents in 205392ns
I0129 00:31:27.741829 3161 hierarchical.cpp:1853] Performed allocation for 1 agents in 193998ns
I0129 00:31:27.792656 3166 hierarchical.cpp:1853] Performed allocation for 1 agents in 181802ns
I0129 00:31:27.843962 3162 hierarchical.cpp:1853] Performed allocation for 1 agents in 194581ns
I0129 00:31:27.895112 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 191078ns
I0129 00:31:27.946425 3164 hierarchical.cpp:1853] Performed allocation for 1 agents in 223375ns
I0129 00:31:27.997471 3152 hierarchical.cpp:1853] Performed allocation for 1 agents in 217623ns
I0129 00:31:28.028158 3166 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-OYHNiz/endpoint.sock' with CSI v1
I0129 00:31:28.030222 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call
I0129 00:31:28.033380 3155 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:28.036022 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call
I0129 00:31:28.036512 3154 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1'
I0129 00:31:28.037837 3155 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.3:33406
I0129 00:31:28.038394 3155 http.cpp:2974] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:28.040330 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
I0129 00:31:28.040693 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
I0129 00:31:28.042485 3164 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {}
I0129 00:31:28.043040 3164 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {}
I0129 00:31:28.045125 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
I0129 00:31:28.048712 3156 hierarchical.cpp:1853] Performed allocation for 1 agents in 190454ns
I0129 00:31:28.048830 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call
I0129 00:31:28.052361 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call
I0129 00:31:28.054864 3161 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0129 00:31:28.054975 3157 status_update_manager_process.hpp:379] Pausing operation status update manager
I0129 00:31:28.055358 3161 http_connection.hpp:227] New endpoint detected at http://172.17.0.3:46419/slave(1251)/api/v1/resource_provider
I0129 00:31:28.058372 3156 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.3:46419/slave(1251)/api/v1/resource_provider
I0129 00:31:28.059104 3155 provider.cpp:476] Connected to resource provider manager
I0129 00:31:28.059860 3153 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.3:46419/slave(1251)/api/v1/resource_provider
I0129 00:31:28.061095 3161 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1/resource_provider'
I0129 00:31:28.062671 3151 http.cpp:1405] HTTP POST for /slave(1251)/api/v1/resource_provider from 172.17.0.3:33410
I0129 00:31:28.099726 3152 hierarchical.cpp:1853] Performed allocation for 1 agents in 177729ns
I0129 00:31:28.145604 3157 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_4bLoEs","--available_capacity=0B","--volumes=","--forward=unix:///tmp/KHaqMA/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}
I0129 00:31:28.151162 3165 hierarchical.cpp:1853] Performed allocation for 1 agents in 198301ns
I0129 00:31:28.203161 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 188782ns
I0129 00:31:28.207752 3152 slave.cpp:8559] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"ef6b76f3-0a64-48ee-845b-c2b40ddbafb3"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_4bLoEs","--available_capacity=0B","--volumes=","--forward=unix:///tmp/KHaqMA/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}'
I0129 00:31:28.210047 3153 provider.cpp:498] Received SUBSCRIBED event
I0129 00:31:28.210119 3153 provider.cpp:1309] Subscribed with ID ef6b76f3-0a64-48ee-845b-c2b40ddbafb3
I0129 00:31:28.217667 3165 status_update_manager_process.hpp:314] Recovering operation status update manager
I0129 00:31:28.254570 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 266302ns
I0129 00:31:28.306474 3164 hierarchical.cpp:1853] Performed allocation for 1 agents in 244663ns
I0129 00:31:28.357899 3162 hierarchical.cpp:1853] Performed allocation for 1 agents in 187842ns
I0129 00:31:28.409312 3159 hierarchical.cpp:1853] Performed allocation for 1 agents in 208322ns
I0129 00:31:28.460752 3157 hierarchical.cpp:1853] Performed allocation for 1 agents in 205560ns
I0129 00:31:28.512850 3163 hierarchical.cpp:1853] Performed allocation for 1 agents in 226514ns
I0129 00:31:28.564110 3166 hierarchical.cpp:1853] Performed allocation for 1 agents in 131832ns
I0129 00:31:28.615052 3155 hierarchical.cpp:1853] Performed allocation for 1 agents in 173606ns
I0129 00:31:28.666456 3161 hierarchical.cpp:1853] Performed allocation for 1 agents in 235580ns
I0129 00:31:28.718199 3165 hierarchical.cpp:1853] Performed allocation for 1 agents in 142211ns
I0129 00:31:28.769663 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 226648ns
I0129 00:31:28.821400 3164 hierarchical.cpp:1853] Performed allocation for 1 agents in 209381ns
I0129 00:31:28.843276 3158 provider.cpp:790] Reconciling storage pools and volumes
I0129 00:31:28.846215 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0129 00:31:28.849529 3162 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0
I0129 00:31:28.849907 3156 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.3:46419/slave(1251)/api/v1/resource_provider
I0129 00:31:28.849944 3162 provider.cpp:748] Resource provider ef6b76f3-0a64-48ee-845b-c2b40ddbafb3 is in READY state
I0129 00:31:28.850066 3158 status_update_manager_process.hpp:385] Resuming operation status update manager
I0129 00:31:28.850967 3155 provider.cpp:1235] Updating profiles { test } for resource provider ef6b76f3-0a64-48ee-845b-c2b40ddbafb3
I0129 00:31:28.851593 3151 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1/resource_provider'
I0129 00:31:28.852433 3158 provider.cpp:790] Reconciling storage pools and volumes
I0129 00:31:28.853366 3154 http.cpp:1405] HTTP POST for /slave(1251)/api/v1/resource_provider from 172.17.0.3:33408
I0129 00:31:28.853936 3160 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider ef6b76f3-0a64-48ee-845b-c2b40ddbafb3
I0129 00:31:28.854173 3152 slave.cpp:8559] Handling resource provider message 'UPDATE_STATE: ef6b76f3-0a64-48ee-845b-c2b40ddbafb3 {}'
I0129 00:31:28.854277 3152 slave.cpp:8679] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0129 00:31:28.854735 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0129 00:31:28.855134 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
I0129 00:31:28.856089 3154 hierarchical.cpp:1110] Grew agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 by {} (total), { } (used)
I0129 00:31:28.856485 3154 hierarchical.cpp:1067] Agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 (1a3d67eabb35) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0129 00:31:28.868286 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 287732ns
I0129 00:31:28.868543 3151 provider.cpp:790] Reconciling storage pools and volumes
I0129 00:31:28.871201 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0129 00:31:28.871532 14689 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
I0129 00:31:28.882133 3150 slave.cpp:989] Agent terminating
I0129 00:31:28.883150 3150 manager.cpp:127] Terminating resource provider ef6b76f3-0a64-48ee-845b-c2b40ddbafb3
I0129 00:31:28.883800 3159 master.cpp:1299] Agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 at slave(1251)@172.17.0.3:46419 (1a3d67eabb35) disconnected
I0129 00:31:28.883852 3159 master.cpp:3368] Disconnecting agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 at slave(1251)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:28.883934 3159 master.cpp:3387] Deactivating agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 at slave(1251)@172.17.0.3:46419 (1a3d67eabb35)
I0129 00:31:28.884104 3160 hierarchical.cpp:1156] Agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0 deactivated
E0129 00:31:28.884512 3164 http_connection.hpp:449] End-Of-File received
I0129 00:31:28.884982 3164 http_connection.hpp:217] Re-detecting endpoint
I0129 00:31:28.885409 3164 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0129 00:31:28.885484 3164 http_connection.hpp:227] New endpoint detected at http://172.17.0.3:46419/slave(1251)/api/v1/resource_provider
I0129 00:31:28.885529 3166 provider.cpp:488] Disconnected from resource provider manager
I0129 00:31:28.885694 3161 status_update_manager_process.hpp:379] Pausing operation status update manager
I0129 00:31:28.885731 3164 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0129 00:31:28.887104 3158 containerizer.cpp:2619] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0129 00:31:28.887154 3158 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 16.20385408secs
I0129 00:31:28.887578 3158 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:28.888391 3163 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.3:46419/slave(1251)/api/v1/resource_provider
I0129 00:31:28.889016 3155 provider.cpp:476] Connected to resource provider manager
I0129 00:31:28.889770 3154 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.3:46419/slave(1251)/api/v1/resource_provider
I0129 00:31:28.890733 3167 process.cpp:2781] Returning '404 Not Found' for '/slave(1251)/api/v1/resource_provider'
E0129 00:31:28.892081 3166 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0129 00:31:28.908339 3161 hierarchical.cpp:1853] Performed allocation for 1 agents in 169321ns
I0129 00:31:28.958461 3160 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0129 00:31:28.960271 3156 hierarchical.cpp:1853] Performed allocation for 1 agents in 124665ns
I0129 00:31:28.960420 3166 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:28.989751 3153 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'
I0129 00:31:28.989984 3160 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-OYHNiz/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0129 00:31:28.990275 3156 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0129 00:31:28.993063 3167 process.cpp:2781] Returning '404 Not Found' for '/slave(1251)/api/v1'
I0129 00:31:29.005688 3150 master.cpp:1140] Master terminating
I0129 00:31:29.006098 3154 hierarchical.cpp:1132] Removed all filters for agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0
I0129 00:31:29.006139 3154 hierarchical.cpp:1008] Removed agent 4519a442-4e9b-487f-99d6-57d67031e9d9-S0
[ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1526 ms)
[----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (115148 ms total)
[----------] Global test environment tear-down
[==========] 2320 tests from 222 test cases ran. (1173929 ms total)
[ PASSED ] 2319 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] OversubscriptionTest.FixedResourceEstimator
1 FAILED TEST
YOU HAVE 34 DISABLED TESTS
I0129 00:31:29.146199 3167 process.cpp:935] Stopped the socket accept loop
Makefile:15957: recipe for target 'check-local' failed
make[4]: *** [check-local] Error 1
make[4]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src'
Makefile:15073: recipe for target 'check-am' failed
make[3]: *** [check-am] Error 2
make[3]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src'
Makefile:15077: recipe for target 'check' failed
make[2]: *** [check] Error 2
make[2]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src'
Makefile:791: recipe for target 'check-recursive' failed
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub'
Makefile:997: recipe for target 'distcheck' failed
make: *** [distcheck] Error 1
Untagged: mesos/mesos-build:ubuntu-16.04
Untagged: mesos/mesos-build@sha256:fa967cbcfb44f55708a3cbc87f245c6d29dd891464db558af56a03ee321526bb
Deleted: sha256:e895c0531b9a9a288fabe479a49f7059aed83645351ac99ec2ea2616822c9f97
Deleted: sha256:09119b0b314a69ba6ec6251f2e89f4199fe1e874c84f9abf07dcbd23dbc3f1c1
Deleted: sha256:562fe6af5a3883058be9c784a839392215ed4185a21d21f1d99df0d17f3ae6e7
Deleted: sha256:0dcdfbe322a4f332f73ac70905d557300ec6dae3bd19586758772c750c7b4a19
Deleted: sha256:c66652d605f01094e2db53d62505dbd524e076d5aa69b89d5e620003803eb149
Deleted: sha256:a2cf79bfb9593c05fd7142ddb49afef77ea4ad5d2464e841f09fe62ffee396e0
Deleted: sha256:f7a904214b390f39d98573882f631dc908df8b2b540cf04e1062f8182c1efffd
Deleted: sha256:ce1f6fcaa83dfce189d76e08f184085732eab4eeb2562d2399953958405c5bec
Deleted: sha256:cce92fda689ab9033f0b8db214bc63edd1ae3e05831a0f3a9418976d7dc7ccdd
Deleted: sha256:d22094bbd65447c59a42c580eaa3a44cee9cd855f00905f59409be21bcefc745
Deleted: sha256:b8976847450013f3eb5e9a81a5778f73ed7bef67e6393049712ef17102b4b7b7
Deleted: sha256:b8c891f0ffec910a12757d733b178e3f62d81dbbde2b31d3b754071c416108ed
Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/6819/console
- Mesos Reviewbot
On Jan. 28, 2020, 7:19 p.m., Benjamin Mahler wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72056/
> -----------------------------------------------------------
>
> (Updated Jan. 28, 2020, 7:19 p.m.)
>
>
> Review request for mesos, Andrei Sekretenko and Greg Mann.
>
>
> Bugs: MESOS-10026
> https://issues.apache.org/jira/browse/MESOS-10026
>
>
> Repository: mesos
>
>
> Description
> -------
>
> This follow the same approach used for the master's GetMetrics call:
>
> https://github.com/apache/mesos/commit/469f2ebaf65b1642d1eb4a1df81a
> https://github.com/apache/mesos/commit/3dda3622f5ed01e8c132dc5ca594
>
> That is, serializing directly to protobuf or json from the in-memory
> v0 state.
>
>
> Diffs
> -----
>
> src/slave/http.cpp 04ad0d816618a1880913857a6f0ff38c4643c488
>
>
> Diff: https://reviews.apache.org/r/72056/diff/1/
>
>
> Testing
> -------
>
> make check
>
>
> Thanks,
>
> Benjamin Mahler
>
>