mesos-reviews mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Mesos Reviewbot <revi...@mesos.apache.org>
Subject Re: Review Request 72124: Added logging of tasks and operations during agent drain initiation.
Date Thu, 13 Feb 2020 04:27:05 GMT

-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72124/#review219566
-----------------------------------------------------------



Bad patch!

Reviews applied: [72116, 72124]

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_72124"]

Error:
...<truncated>...
atus UUID: 669821c1-5489-478b-80e8-1dd91595fcc9) for operation UUID 2ad6f8ef-7e07-4cb2-9ed6-6e4fedef7ac1 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:48.713289  3212 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:35463/slave(1249)/api/v1/resource_provider
I0213 04:26:48.714692  3207 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider'
I0213 04:26:48.717862  3201 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.105794ms
I0213 04:26:48.718572  3205 master.cpp:9984] Sending offers [ 151edfad-ed42-4be7-ab8c-7ba386418c27-O3 ] to framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463
I0213 04:26:48.719197  3213 sched.cpp:934] Scheduler::resourceOffers took 80091ns
I0213 04:26:48.722455  3202 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0213 04:26:48.724655  3204 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:58734
I0213 04:26:48.724882  3204 http.cpp:277] Processing call CREATE_VOLUMES
I0213 04:26:48.725682  3204 master.cpp:3712] Authorizing principal 'test-principal' to perform action CREATE_VOLUME on object {"value":"storage/default-role","resource":{"provider_id":{"value":"e6055421-9a82-47dd-a6f7-081093bd1dce"},"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":"6fbc7ae9-a342-48df-8cc9-e38c2c917e8f","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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e","profile":"test"}}}}
I0213 04:26:48.727363  3213 sched.cpp:960] Rescinded offer 151edfad-ed42-4be7-ab8c-7ba386418c27-O3
I0213 04:26:48.727440  3213 sched.cpp:971] Scheduler::offerRescinded took 22012ns
I0213 04:26:48.727886  3201 master.cpp:12283] Removing offer 151edfad-ed42-4be7-ab8c-7ba386418c27-O3
I0213 04:26:48.728142  3208 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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e,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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e,test)]:2048, offered or allocated: {}) on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 from framework 151ed
 fad-ed42-4be7-ab8c-7ba386418c27-0000
I0213 04:26:48.730003  3208 hierarchical.cpp:1625] Framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 filtered agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 for 5secs
I0213 04:26:48.733232  3202 master.cpp:12148] Sending operation '' (uuid: 10892765-5e3f-429e-971d-91c24de982d1) to agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 at slave(1249)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:48.734086  3209 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0213 04:26:48.737071  3200 provider.cpp:498] Received APPLY_OPERATION event
I0213 04:26:48.737115  3200 provider.cpp:1351] Received CREATE operation '' (uuid: 10892765-5e3f-429e-971d-91c24de982d1)
I0213 04:26:48.740974  3214 master.cpp:5968] Processing REVIVE call for framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463
I0213 04:26:48.741410  3214 hierarchical.cpp:1721] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000
I0213 04:26:48.742600  3214 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.027555ms
I0213 04:26:48.742954  3214 hierarchical.cpp:1853] Performed allocation for 1 agents in 137777ns
I0213 04:26:48.743592  3212 master.cpp:9984] Sending offers [ 151edfad-ed42-4be7-ab8c-7ba386418c27-O4 ] to framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463
I0213 04:26:48.744463  3211 sched.cpp:934] Scheduler::resourceOffers took 104069ns
I0213 04:26:48.757935  3203 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:58728
I0213 04:26:48.758998  3205 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 2ad6f8ef-7e07-4cb2-9ed6-6e4fedef7ac1) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0213 04:26:48.759193  3205 slave.cpp:9050] Updating the state of operation with no ID (uuid: 2ad6f8ef-7e07-4cb2-9ed6-6e4fedef7ac1) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0213 04:26:48.759253  3205 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: 2ad6f8ef-7e07-4cb2-9ed6-6e4fedef7ac1) for an operator API call
I0213 04:26:48.759621  3206 master.cpp:11800] Updating the state of operation '' (uuid: 2ad6f8ef-7e07-4cb2-9ed6-6e4fedef7ac1) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0213 04:26:48.760272  3202 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0213 04:26:48.855254  3205 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: a92444a0-5ce3-475c-a112-0cbb03225b0b) for operation UUID 10892765-5e3f-429e-971d-91c24de982d1 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:48.855324  3205 status_update_manager_process.hpp:414] Creating operation status update stream 10892765-5e3f-429e-971d-91c24de982d1 checkpoint=true
I0213 04:26:48.855330  3200 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0213 04:26:48.855583  3205 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: a92444a0-5ce3-475c-a112-0cbb03225b0b) for operation UUID 10892765-5e3f-429e-971d-91c24de982d1 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:48.993577  3205 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: a92444a0-5ce3-475c-a112-0cbb03225b0b) for operation UUID 10892765-5e3f-429e-971d-91c24de982d1 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:48.994222  3205 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 669821c1-5489-478b-80e8-1dd91595fcc9) for stream 2ad6f8ef-7e07-4cb2-9ed6-6e4fedef7ac1
I0213 04:26:48.994341  3205 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 669821c1-5489-478b-80e8-1dd91595fcc9) for operation UUID 2ad6f8ef-7e07-4cb2-9ed6-6e4fedef7ac1 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:48.994956  3206 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:35463/slave(1249)/api/v1/resource_provider
I0213 04:26:48.996517  3212 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider'
I0213 04:26:49.037899  3213 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:58728
I0213 04:26:49.038931  3204 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 10892765-5e3f-429e-971d-91c24de982d1) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0213 04:26:49.039180  3204 slave.cpp:9050] Updating the state of operation with no ID (uuid: 10892765-5e3f-429e-971d-91c24de982d1) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0213 04:26:49.039239  3204 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: 10892765-5e3f-429e-971d-91c24de982d1) for an operator API call
I0213 04:26:49.039630  3200 master.cpp:11800] Updating the state of operation '' (uuid: 10892765-5e3f-429e-971d-91c24de982d1) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0213 04:26:49.040450  3206 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0213 04:26:49.042018  3213 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0213 04:26:49.072816  3205 status_update_manager_process.hpp:490] Cleaning up operation status update stream 2ad6f8ef-7e07-4cb2-9ed6-6e4fedef7ac1
I0213 04:26:49.073174  3205 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: a92444a0-5ce3-475c-a112-0cbb03225b0b) for stream 10892765-5e3f-429e-971d-91c24de982d1
I0213 04:26:49.073289  3205 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: a92444a0-5ce3-475c-a112-0cbb03225b0b) for operation UUID 10892765-5e3f-429e-971d-91c24de982d1 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.123417  3205 status_update_manager_process.hpp:490] Cleaning up operation status update stream 10892765-5e3f-429e-971d-91c24de982d1
I0213 04:26:49.184592  3206 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0213 04:26:49.186825  3202 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:58736
I0213 04:26:49.187237  3202 http.cpp:277] Processing call DESTROY_VOLUMES
I0213 04:26:49.188421  3202 master.cpp:3712] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"e6055421-9a82-47dd-a6f7-081093bd1dce"},"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":"6fbc7ae9-a342-48df-8cc9-e38c2c917e8f","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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e","profile":"test"}}}}
I0213 04:26:49.190248  3205 sched.cpp:960] Rescinded offer 151edfad-ed42-4be7-ab8c-7ba386418c27-O4
I0213 04:26:49.190357  3205 sched.cpp:971] Scheduler::offerRescinded took 32106ns
I0213 04:26:49.190759  3204 master.cpp:12283] Removing offer 151edfad-ed42-4be7-ab8c-7ba386418c27-O4
I0213 04:26:49.190897  3203 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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e,test),6fbc7ae9-a342-48df-8cc9-e38c2c917e8f: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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e,test),6fbc7ae9-a342-48df-8cc9-e38c2c917e8f:volume]:2048, offered
  or allocated: {}) on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 from framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000
I0213 04:26:49.192636  3203 hierarchical.cpp:1625] Framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 filtered agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 for 5secs
I0213 04:26:49.195909  3200 master.cpp:12148] Sending operation '' (uuid: 4011826d-c410-4135-87ae-4199e4647a9f) to agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 at slave(1249)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:49.196568  3206 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0213 04:26:49.199961  3214 provider.cpp:498] Received APPLY_OPERATION event
I0213 04:26:49.200009  3214 provider.cpp:1351] Received DESTROY operation '' (uuid: 4011826d-c410-4135-87ae-4199e4647a9f)
I0213 04:26:49.205132  3211 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.499615ms
I0213 04:26:49.205956  3212 master.cpp:9984] Sending offers [ 151edfad-ed42-4be7-ab8c-7ba386418c27-O5 ] to framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463
I0213 04:26:49.206737  3200 sched.cpp:934] Scheduler::resourceOffers took 95430ns
I0213 04:26:49.274662  3215 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 26a001aa-2e5f-4783-afce-b7d6b29f80a7) for operation UUID 4011826d-c410-4135-87ae-4199e4647a9f on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.274830  3215 status_update_manager_process.hpp:414] Creating operation status update stream 4011826d-c410-4135-87ae-4199e4647a9f checkpoint=true
I0213 04:26:49.275250  3215 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 26a001aa-2e5f-4783-afce-b7d6b29f80a7) for operation UUID 4011826d-c410-4135-87ae-4199e4647a9f on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.336695  3215 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 26a001aa-2e5f-4783-afce-b7d6b29f80a7) for operation UUID 4011826d-c410-4135-87ae-4199e4647a9f on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.338199  3206 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:35463/slave(1249)/api/v1/resource_provider
I0213 04:26:49.339920  3207 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider'
I0213 04:26:49.343899  3213 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0213 04:26:49.346374  3212 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:58738
I0213 04:26:49.346715  3212 http.cpp:277] Processing call UNRESERVE_RESOURCES
I0213 04:26:49.347602  3212 master.cpp:3712] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"e6055421-9a82-47dd-a6f7-081093bd1dce"},"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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e","profile":"test"}}}}
I0213 04:26:49.349293  3210 sched.cpp:960] Rescinded offer 151edfad-ed42-4be7-ab8c-7ba386418c27-O5
I0213 04:26:49.349404  3210 sched.cpp:971] Scheduler::offerRescinded took 30767ns
I0213 04:26:49.349872  3206 master.cpp:12283] Removing offer 151edfad-ed42-4be7-ab8c-7ba386418c27-O5
I0213 04:26:49.349825  3207 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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e,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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e,test)]:2048, offered or allocated: {}) on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 from framework 151ed
 fad-ed42-4be7-ab8c-7ba386418c27-0000
I0213 04:26:49.351501  3207 hierarchical.cpp:1625] Framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 filtered agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 for 5secs
I0213 04:26:49.354372  3208 master.cpp:12148] Sending operation '' (uuid: d9ae65aa-c6ed-4ca8-8f94-da8762379579) to agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 at slave(1249)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:49.355154  3211 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0213 04:26:49.358501  3205 provider.cpp:498] Received APPLY_OPERATION event
I0213 04:26:49.358569  3205 provider.cpp:1351] Received UNRESERVE operation '' (uuid: d9ae65aa-c6ed-4ca8-8f94-da8762379579)
I0213 04:26:49.364490  3213 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.339321ms
I0213 04:26:49.365231  3208 master.cpp:9984] Sending offers [ 151edfad-ed42-4be7-ab8c-7ba386418c27-O6 ] to framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463
I0213 04:26:49.365917  3208 sched.cpp:934] Scheduler::resourceOffers took 89456ns
I0213 04:26:49.381501  3201 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:58728
I0213 04:26:49.382490  3210 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 4011826d-c410-4135-87ae-4199e4647a9f) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0213 04:26:49.382668  3210 slave.cpp:9050] Updating the state of operation with no ID (uuid: 4011826d-c410-4135-87ae-4199e4647a9f) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0213 04:26:49.382711  3210 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: 4011826d-c410-4135-87ae-4199e4647a9f) for an operator API call
I0213 04:26:49.383102  3214 master.cpp:11800] Updating the state of operation '' (uuid: 4011826d-c410-4135-87ae-4199e4647a9f) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0213 04:26:49.383754  3207 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0213 04:26:49.458861  3210 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 5e7b641c-0c2b-43b6-bf40-a6cd8183f977) for operation UUID d9ae65aa-c6ed-4ca8-8f94-da8762379579 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.458920  3210 status_update_manager_process.hpp:414] Creating operation status update stream d9ae65aa-c6ed-4ca8-8f94-da8762379579 checkpoint=true
I0213 04:26:49.459008  3205 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0213 04:26:49.459226  3210 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 5e7b641c-0c2b-43b6-bf40-a6cd8183f977) for operation UUID d9ae65aa-c6ed-4ca8-8f94-da8762379579 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.534001  3210 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 5e7b641c-0c2b-43b6-bf40-a6cd8183f977) for operation UUID d9ae65aa-c6ed-4ca8-8f94-da8762379579 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.534304  3210 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 26a001aa-2e5f-4783-afce-b7d6b29f80a7) for stream 4011826d-c410-4135-87ae-4199e4647a9f
I0213 04:26:49.534384  3210 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 26a001aa-2e5f-4783-afce-b7d6b29f80a7) for operation UUID 4011826d-c410-4135-87ae-4199e4647a9f on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.534688  3213 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:35463/slave(1249)/api/v1/resource_provider
I0213 04:26:49.535948  3202 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider'
I0213 04:26:49.577675  3211 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:58728
I0213 04:26:49.578591  3206 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: d9ae65aa-c6ed-4ca8-8f94-da8762379579) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0213 04:26:49.578894  3206 slave.cpp:9050] Updating the state of operation with no ID (uuid: d9ae65aa-c6ed-4ca8-8f94-da8762379579) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0213 04:26:49.578971  3206 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: d9ae65aa-c6ed-4ca8-8f94-da8762379579) for an operator API call
I0213 04:26:49.579349  3201 master.cpp:11800] Updating the state of operation '' (uuid: d9ae65aa-c6ed-4ca8-8f94-da8762379579) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0213 04:26:49.579838  3214 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0213 04:26:49.581287  3212 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0213 04:26:49.582345  3210 status_update_manager_process.hpp:490] Cleaning up operation status update stream 4011826d-c410-4135-87ae-4199e4647a9f
I0213 04:26:49.582538  3210 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 5e7b641c-0c2b-43b6-bf40-a6cd8183f977) for stream d9ae65aa-c6ed-4ca8-8f94-da8762379579
I0213 04:26:49.582602  3210 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 5e7b641c-0c2b-43b6-bf40-a6cd8183f977) for operation UUID d9ae65aa-c6ed-4ca8-8f94-da8762379579 on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.633093  3210 status_update_manager_process.hpp:490] Cleaning up operation status update stream d9ae65aa-c6ed-4ca8-8f94-da8762379579
I0213 04:26:49.684736  3206 master.cpp:1414] Framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463 disconnected
I0213 04:26:49.684798  3206 master.cpp:3333] Deactivating framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463
I0213 04:26:49.685256  3203 hierarchical.cpp:813] Deactivated framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000
I0213 04:26:49.685847  3199 slave.cpp:995] Agent terminating
I0213 04:26:49.685974  3203 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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e,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_u1qWwL/2GB-2dbf5c35-ae2d-4808-8b1a-51b3270cbd3e,test)]:2048, offered or allocated: {}) on agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 from framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000
I0213 04:26:49.686148  3206 master.cpp:12283] Removing offer 151edfad-ed42-4be7-ab8c-7ba386418c27-O6
I0213 04:26:49.686264  3206 master.cpp:3310] Disconnecting framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463
I0213 04:26:49.686338  3206 master.cpp:1429] Giving framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463 0ns to failover
I0213 04:26:49.686923  3199 manager.cpp:127] Terminating resource provider e6055421-9a82-47dd-a6f7-081093bd1dce
I0213 04:26:49.687378  3200 master.cpp:1299] Agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 at slave(1249)@172.17.0.2:35463 (9a146ed47ce9) disconnected
I0213 04:26:49.687417  3200 master.cpp:3368] Disconnecting agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 at slave(1249)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:49.687517  3200 master.cpp:3387] Deactivating agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 at slave(1249)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:49.687747  3200 master.cpp:9770] Framework failover timeout, removing framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463
I0213 04:26:49.687786  3200 master.cpp:10772] Removing framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000 (default) at scheduler-8ab851ab-c24e-431d-bd4a-9dbeea720968@172.17.0.2:35463
E0213 04:26:49.688015  3211 http_connection.hpp:449] End-Of-File received
I0213 04:26:49.688069  3203 hierarchical.cpp:1156] Agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0 deactivated
I0213 04:26:49.688297  3201 hierarchical.cpp:1777] Allocation paused
I0213 04:26:49.688580  3211 http_connection.hpp:217] Re-detecting endpoint
I0213 04:26:49.688735  3201 hierarchical.cpp:757] Removed framework 151edfad-ed42-4be7-ab8c-7ba386418c27-0000
I0213 04:26:49.688848  3201 hierarchical.cpp:1787] Allocation resumed
I0213 04:26:49.689106  3211 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0213 04:26:49.689172  3211 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0213 04:26:49.689210  3209 provider.cpp:488] Disconnected from resource provider manager
I0213 04:26:49.689249  3211 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35463/slave(1249)/api/v1/resource_provider
I0213 04:26:49.689313  3214 status_update_manager_process.hpp:379] Pausing operation status update manager
I0213 04:26:49.690642  3213 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
I0213 04:26:49.690708  3213 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 2.497627008secs
I0213 04:26:49.691169  3213 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:49.692636  3210 hierarchical.cpp:1853] Performed allocation for 1 agents in 179223ns
I0213 04:26:49.692984  3212 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35463/slave(1249)/api/v1/resource_provider
I0213 04:26:49.693608  3202 provider.cpp:476] Connected to resource provider manager
I0213 04:26:49.694547  3206 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35463/slave(1249)/api/v1/resource_provider
I0213 04:26:49.695549  3216 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1/resource_provider'
E0213 04:26:49.696811  3204 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0213 04:26:49.743690  3205 hierarchical.cpp:1853] Performed allocation for 1 agents in 144859ns
I0213 04:26:49.795258  3211 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0213 04:26:49.795437  3201 hierarchical.cpp:1853] Performed allocation for 1 agents in 138246ns
I0213 04:26:49.797081  3213 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
I0213 04:26:49.799796  3215 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'
I0213 04:26:49.800132  3207 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-3UGeYg/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:49.800458  3207 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:49.803198  3216 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1'
I0213 04:26:49.816155  3199 master.cpp:1140] Master terminating
I0213 04:26:49.817059  3215 hierarchical.cpp:1132] Removed all filters for agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
I0213 04:26:49.817090  3215 hierarchical.cpp:1008] Removed agent 151edfad-ed42-4be7-ab8c-7ba386418c27-S0
[       OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2382 ms)
[ RUN      ] CSIVersion/StorageLocalResourceProviderTest.Update/v0
I0213 04:26:49.831480  3199 cluster.cpp:186] Creating default 'local' authorizer
I0213 04:26:49.836259  3203 master.cpp:443] Master d56eed47-9d96-441a-ad11-41e6d963193e (9a146ed47ce9) started on 172.17.0.2:35463
I0213 04:26:49.836305  3203 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/uZpIWb/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/uZpIWb/master" --zk_session_timeout="10secs"
I0213 04:26:49.837040  3203 master.cpp:495] Master only allowing authenticated frameworks to register
I0213 04:26:49.837102  3203 master.cpp:501] Master only allowing authenticated agents to register
I0213 04:26:49.837152  3203 master.cpp:507] Master only allowing authenticated HTTP frameworks to register
I0213 04:26:49.837178  3203 credentials.hpp:37] Loading credentials for authentication from '/tmp/uZpIWb/credentials'
I0213 04:26:49.837702  3203 master.cpp:551] Using default 'crammd5' authenticator
I0213 04:26:49.838032  3203 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0213 04:26:49.838376  3203 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0213 04:26:49.838670  3203 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0213 04:26:49.838951  3203 master.cpp:632] Authorization enabled
I0213 04:26:49.839534  3202 hierarchical.cpp:567] Initialized hierarchical allocator process
I0213 04:26:49.839587  3210 whitelist_watcher.cpp:77] No whitelist given
I0213 04:26:49.844841  3213 master.cpp:2172] Elected as the leading master!
I0213 04:26:49.844880  3213 master.cpp:1668] Recovering from registrar
I0213 04:26:49.845137  3209 registrar.cpp:339] Recovering registrar
I0213 04:26:49.846180  3209 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0213 04:26:49.846326  3209 registrar.cpp:487] Applied 1 operations in 54439ns; attempting to update the registry
I0213 04:26:49.847141  3209 registrar.cpp:544] Successfully updated the registry in 0ns
I0213 04:26:49.847275  3209 registrar.cpp:416] Successfully recovered registrar
I0213 04:26:49.847839  3212 master.cpp:1821] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
I0213 04:26:49.847890  3208 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover
W0213 04:26:49.853590  3199 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:35463
I0213 04:26:49.855123  3199 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0213 04:26:49.855664  3199 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0213 04:26:49.855690  3199 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0213 04:26:49.855705  3199 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0213 04:26:49.855736  3199 provisioner.cpp:294] Using default backend 'copy'
I0213 04:26:49.858400  3199 cluster.cpp:533] Creating default 'local' authorizer
I0213 04:26:49.860903  3206 slave.cpp:274] Mesos agent started on (1250)@172.17.0.2:35463
I0213 04:26:49.860937  3206 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/uZpIWb/idRNma/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/uZpIWb/idRNma/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/uZpIWb/idRNma/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/uZpIWb/idRNma/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/uZpIWb/idRNma/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/uZpIWb/idRNma/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/uZpIWb/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_FKJjfq" --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_GYiQ7F" --zk_session_timeout="10secs"
I0213 04:26:49.861574  3206 credentials.hpp:86] Loading credential for authentication from '/tmp/uZpIWb/idRNma/credential'
I0213 04:26:49.861781  3206 slave.cpp:307] Agent using credential for: test-principal
I0213 04:26:49.861810  3206 credentials.hpp:37] Loading credentials for authentication from '/tmp/uZpIWb/idRNma/http_credentials'
I0213 04:26:49.862105  3206 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0213 04:26:49.862608  3206 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0213 04:26:49.864470  3203 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0213 04:26:49.864526  3206 slave.cpp:622] 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"}]
I0213 04:26:49.864791  3206 slave.cpp:630] Agent attributes: [  ]
I0213 04:26:49.864820  3206 slave.cpp:639] Agent hostname: 9a146ed47ce9
I0213 04:26:49.865046  3215 status_update_manager_process.hpp:379] Pausing operation status update manager
I0213 04:26:49.865116  3205 task_status_update_manager.cpp:181] Pausing sending task status updates
I0213 04:26:49.866847  3207 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_GYiQ7F/meta'
I0213 04:26:49.867115  3204 slave.cpp:7606] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_GYiQ7F/meta', beginning agent recovery
I0213 04:26:49.867835  3210 task_status_update_manager.cpp:207] Recovering task status update manager
I0213 04:26:49.868147  3201 hierarchical.cpp:1853] Performed allocation for 0 agents in 108646ns
I0213 04:26:49.868366  3212 containerizer.cpp:820] Recovering Mesos containers
I0213 04:26:49.868818  3212 containerizer.cpp:1160] Recovering isolators
I0213 04:26:49.869772  3204 containerizer.cpp:1199] Recovering provisioner
I0213 04:26:49.870668  3201 provisioner.cpp:518] Provisioner recovery complete
I0213 04:26:49.871513  3205 composing.cpp:339] Finished recovering all containerizers
I0213 04:26:49.871866  3212 slave.cpp:8088] Recovering executors
I0213 04:26:49.872027  3212 slave.cpp:8241] Finished recovery
I0213 04:26:49.872931  3214 task_status_update_manager.cpp:181] Pausing sending task status updates
I0213 04:26:49.872951  3202 status_update_manager_process.hpp:379] Pausing operation status update manager
I0213 04:26:49.872974  3204 slave.cpp:1454] New master detected at master@172.17.0.2:35463
I0213 04:26:49.873129  3204 slave.cpp:1519] Detecting new master
I0213 04:26:49.882612  3213 slave.cpp:1546] Authenticating with master master@172.17.0.2:35463
I0213 04:26:49.882726  3213 slave.cpp:1555] Using default CRAM-MD5 authenticatee
I0213 04:26:49.883085  3200 authenticatee.cpp:121] Creating new client SASL connection
I0213 04:26:49.883440  3201 master.cpp:10169] Authenticating slave(1250)@172.17.0.2:35463
I0213 04:26:49.883658  3211 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2109)@172.17.0.2:35463
I0213 04:26:49.884167  3207 authenticator.cpp:98] Creating new server SASL connection
I0213 04:26:49.884423  3205 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0213 04:26:49.884467  3205 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0213 04:26:49.884634  3203 authenticator.cpp:204] Received SASL authentication start
I0213 04:26:49.884722  3203 authenticator.cpp:326] Authentication requires more steps
I0213 04:26:49.884892  3203 authenticatee.cpp:259] Received SASL authentication step
I0213 04:26:49.885079  3212 authenticator.cpp:232] Received SASL authentication step
I0213 04:26:49.885125  3212 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9a146ed47ce9' server FQDN: '9a146ed47ce9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0213 04:26:49.885146  3212 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0213 04:26:49.885200  3212 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0213 04:26:49.885234  3212 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9a146ed47ce9' server FQDN: '9a146ed47ce9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0213 04:26:49.885253  3212 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0213 04:26:49.885264  3212 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0213 04:26:49.885287  3212 authenticator.cpp:318] Authentication success
I0213 04:26:49.885416  3210 authenticatee.cpp:299] Authentication success
I0213 04:26:49.885527  3208 master.cpp:10201] Successfully authenticated principal 'test-principal' at slave(1250)@172.17.0.2:35463
I0213 04:26:49.885565  3214 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2109)@172.17.0.2:35463
I0213 04:26:49.886005  3212 slave.cpp:1646] Successfully authenticated with master master@172.17.0.2:35463
I0213 04:26:49.886476  3212 slave.cpp:2096] Will retry registration in 5.413136ms if necessary
I0213 04:26:49.886664  3201 master.cpp:6639] Received register agent message from slave(1250)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:49.887115  3201 master.cpp:3712] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0213 04:26:49.887976  3209 master.cpp:6706] Authorized registration of agent at slave(1250)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:49.888106  3209 master.cpp:6818] Registering agent at slave(1250)@172.17.0.2:35463 (9a146ed47ce9) with id d56eed47-9d96-441a-ad11-41e6d963193e-S0
I0213 04:26:49.888957  3202 registrar.cpp:487] Applied 1 operations in 288761ns; attempting to update the registry
I0213 04:26:49.889698  3213 registrar.cpp:544] Successfully updated the registry in 663040ns
I0213 04:26:49.889919  3200 master.cpp:6866] Admitted agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 at slave(1250)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:49.890785  3200 master.cpp:6911] Registered agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 at slave(1250)@172.17.0.2:35463 (9a146ed47ce9) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0213 04:26:49.890954  3214 slave.cpp:1679] Registered with master master@172.17.0.2:35463; given agent ID d56eed47-9d96-441a-ad11-41e6d963193e-S0
I0213 04:26:49.891089  3212 hierarchical.cpp:959] Added agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 (9a146ed47ce9) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
I0213 04:26:49.891144  3201 task_status_update_manager.cpp:188] Resuming sending task status updates
I0213 04:26:49.891476  3214 slave.cpp:1714] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_GYiQ7F/meta/slaves/d56eed47-9d96-441a-ad11-41e6d963193e-S0/slave.info'
I0213 04:26:49.891482  3212 hierarchical.cpp:1853] Performed allocation for 1 agents in 164176ns
I0213 04:26:49.891608  3205 status_update_manager_process.hpp:385] Resuming operation status update manager
I0213 04:26:49.892967  3214 slave.cpp:1766] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"K/nFeOm0Quys9WAz1IbiYA=="},"slave_id":{"value":"d56eed47-9d96-441a-ad11-41e6d963193e-S0"},"update_oversubscribed_resources":false}
I0213 04:26:49.893788  3204 master.cpp:8049] Ignoring update on agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 at slave(1250)@172.17.0.2:35463 (9a146ed47ce9) as it reports no changes
I0213 04:26:49.898011  3212 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1'
I0213 04:26:49.899482  3213 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:58746
I0213 04:26:49.900028  3213 http.cpp:2146] Processing GET_CONTAINERS call
I0213 04:26:49.906186  3213 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:49.908845  3210 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1'
I0213 04:26:49.910040  3209 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:58748
I0213 04:26:49.910943  3209 http.cpp:2606] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:49.911972  3214 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_GYiQ7F/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:49.920094  3208 hierarchical.cpp:1853] Performed allocation for 1 agents in 157365ns
I0213 04:26:49.943642  3213 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:49.944270  3213 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 232960ns
I0213 04:26:49.944917  3213 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_FKJjfq/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0213 04:26:49.944967  3213 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 698112ns
I0213 04:26:49.947528  3205 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_BR0n0V","--available_capacity=0B","--volumes=","--forward=unix:///tmp/uZpIWb/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_GYiQ7F/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-v40Ci9/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_GYiQ7F/containers/o
 rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="108" --pipe_write="109" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_FKJjfq/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0213 04:26:49.956470  3205 launcher.cpp:145] Forked child with pid '14810' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:49.957469  3205 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 12.489984ms
I0213 04:26:49.958994  3205 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.529088ms
I0213 04:26:49.959386  3201 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_GYiQ7F/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:49.971487  3203 hierarchical.cpp:1853] Performed allocation for 1 agents in 212351ns
I0213 04:26:49.986850  3206 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 27.823872ms
I0213 04:26:49.989017  3200 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'
I0213 04:26:49.989248  3213 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-v40Ci9/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:50.023263  3215 hierarchical.cpp:1853] Performed allocation for 1 agents in 218291ns
I0213 04:26:50.075073  3204 hierarchical.cpp:1853] Performed allocation for 1 agents in 313642ns
I0213 04:26:50.126235  3201 hierarchical.cpp:1853] Performed allocation for 1 agents in 140427ns
I0213 04:26:50.178263  3214 hierarchical.cpp:1853] Performed allocation for 1 agents in 227700ns
I0213 04:26:50.229642  3213 hierarchical.cpp:1853] Performed allocation for 1 agents in 170198ns
I0213 04:26:50.281378  3212 hierarchical.cpp:1853] Performed allocation for 1 agents in 186752ns
I0213 04:26:50.300426  3204 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-v40Ci9/endpoint.sock' with CSI v1
I0213 04:26:50.303153  3205 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-v40Ci9/endpoint.sock' with CSI v0
I0213 04:26:50.304383 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/Probe call
I0213 04:26:50.307516  3207 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:50.310528 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginCapabilities call
I0213 04:26:50.311131  3202 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1'
I0213 04:26:50.312417  3200 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:58750
I0213 04:26:50.312952  3200 http.cpp:2824] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:50.315188 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call
I0213 04:26:50.315517 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call
I0213 04:26:50.317335  3203 v0_volume_manager.cpp:628] NODE_SERVICE loaded: {}
I0213 04:26:50.317982  3203 v0_volume_manager.cpp:628] CONTROLLER_SERVICE loaded: {}
I0213 04:26:50.320160 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ControllerGetCapabilities call
I0213 04:26:50.323884 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetCapabilities call
I0213 04:26:50.327433 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetId call
I0213 04:26:50.329864  3203 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0213 04:26:50.330047  3212 status_update_manager_process.hpp:379] Pausing operation status update manager
I0213 04:26:50.330420  3206 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35463/slave(1250)/api/v1/resource_provider
I0213 04:26:50.332549  3214 hierarchical.cpp:1853] Performed allocation for 1 agents in 182384ns
I0213 04:26:50.333824  3211 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35463/slave(1250)/api/v1/resource_provider
I0213 04:26:50.334504  3215 provider.cpp:476] Connected to resource provider manager
I0213 04:26:50.335208  3204 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35463/slave(1250)/api/v1/resource_provider
I0213 04:26:50.336412  3203 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider'
I0213 04:26:50.338235  3207 http.cpp:1405] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:58754
I0213 04:26:50.338939  3207 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_BR0n0V","--available_capacity=0B","--volumes=","--forward=unix:///tmp/uZpIWb/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"}
I0213 04:26:50.384809  3206 hierarchical.cpp:1853] Performed allocation for 1 agents in 154819ns
I0213 04:26:50.386968  3214 slave.cpp:8597] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"d9598664-0e4a-47fb-b853-013755d81a7e"},"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_BR0n0V","--available_capacity=0B","--volumes=","--forward=unix:///tmp/uZpIWb/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"}'
I0213 04:26:50.388593  3215 provider.cpp:498] Received SUBSCRIBED event
I0213 04:26:50.388646  3215 provider.cpp:1309] Subscribed with ID d9598664-0e4a-47fb-b853-013755d81a7e
I0213 04:26:50.389500  3204 status_update_manager_process.hpp:314] Recovering operation status update manager
I0213 04:26:50.428577  3206 provider.cpp:790] Reconciling storage pools and volumes
I0213 04:26:50.431025 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call
I0213 04:26:50.433893  3203 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent d56eed47-9d96-441a-ad11-41e6d963193e-S0
I0213 04:26:50.434182  3206 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:35463/slave(1250)/api/v1/resource_provider
I0213 04:26:50.434242  3203 provider.cpp:748] Resource provider d9598664-0e4a-47fb-b853-013755d81a7e is in READY state
I0213 04:26:50.434298  3210 status_update_manager_process.hpp:385] Resuming operation status update manager
I0213 04:26:50.435017  3207 provider.cpp:1235] Updating profiles { test } for resource provider d9598664-0e4a-47fb-b853-013755d81a7e
I0213 04:26:50.435533  3200 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider'
I0213 04:26:50.436111  3211 provider.cpp:790] Reconciling storage pools and volumes
I0213 04:26:50.437115  3202 http.cpp:1405] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:58752
I0213 04:26:50.437641  3212 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider d9598664-0e4a-47fb-b853-013755d81a7e
I0213 04:26:50.437674  3202 hierarchical.cpp:1853] Performed allocation for 1 agents in 200734ns
I0213 04:26:50.437834  3205 slave.cpp:8597] Handling resource provider message 'UPDATE_STATE: d9598664-0e4a-47fb-b853-013755d81a7e {}'
I0213 04:26:50.437934  3205 slave.cpp:8717] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0213 04:26:50.438290 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call
I0213 04:26:50.438664 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call
I0213 04:26:50.439266  3214 hierarchical.cpp:1110] Grew agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 by {} (total), {  } (used)
I0213 04:26:50.439733  3214 hierarchical.cpp:1067] Agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 (9a146ed47ce9) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0213 04:26:50.444921  3210 hierarchical.cpp:1853] Performed allocation for 1 agents in 152503ns
I0213 04:26:50.445353  3200 provider.cpp:790] Reconciling storage pools and volumes
I0213 04:26:50.447358 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call
I0213 04:26:50.447849 14814 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call
I0213 04:26:50.458132  3203 slave.cpp:995] Agent terminating
I0213 04:26:50.458765  3203 manager.cpp:127] Terminating resource provider d9598664-0e4a-47fb-b853-013755d81a7e
I0213 04:26:50.459200  3208 master.cpp:1299] Agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 at slave(1250)@172.17.0.2:35463 (9a146ed47ce9) disconnected
I0213 04:26:50.459233  3208 master.cpp:3368] Disconnecting agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 at slave(1250)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:50.459314  3208 master.cpp:3387] Deactivating agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 at slave(1250)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:50.459470  3206 hierarchical.cpp:1156] Agent d56eed47-9d96-441a-ad11-41e6d963193e-S0 deactivated
E0213 04:26:50.459745  3211 http_connection.hpp:449] End-Of-File received
I0213 04:26:50.460325  3211 http_connection.hpp:217] Re-detecting endpoint
I0213 04:26:50.460866  3211 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0213 04:26:50.460942  3211 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0213 04:26:50.460970  3207 provider.cpp:488] Disconnected from resource provider manager
I0213 04:26:50.461004  3211 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35463/slave(1250)/api/v1/resource_provider
I0213 04:26:50.461077  3207 status_update_manager_process.hpp:379] Pausing operation status update manager
I0213 04:26:50.462508  3202 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
I0213 04:26:50.462589  3202 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.47577088secs
I0213 04:26:50.463042  3202 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:50.464071  3205 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35463/slave(1250)/api/v1/resource_provider
I0213 04:26:50.464577  3208 provider.cpp:476] Connected to resource provider manager
I0213 04:26:50.465267  3211 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35463/slave(1250)/api/v1/resource_provider
I0213 04:26:50.466166  3216 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1/resource_provider'
E0213 04:26:50.467377  3210 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0213 04:26:50.490370  3212 hierarchical.cpp:1853] Performed allocation for 1 agents in 134589ns
I0213 04:26:50.541518  3209 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0213 04:26:50.542019  3201 hierarchical.cpp:1853] Performed allocation for 1 agents in 148564ns
I0213 04:26:50.543010  3202 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
I0213 04:26:50.545491  3215 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'
I0213 04:26:50.545796  3200 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-v40Ci9/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:50.546030  3200 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:50.548533  3216 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1'
I0213 04:26:50.558240  3199 master.cpp:1140] Master terminating
I0213 04:26:50.558620  3207 hierarchical.cpp:1132] Removed all filters for agent d56eed47-9d96-441a-ad11-41e6d963193e-S0
I0213 04:26:50.558647  3207 hierarchical.cpp:1008] Removed agent d56eed47-9d96-441a-ad11-41e6d963193e-S0
[       OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (740 ms)
[ RUN      ] CSIVersion/StorageLocalResourceProviderTest.Update/v1
I0213 04:26:50.572973  3199 cluster.cpp:186] Creating default 'local' authorizer
I0213 04:26:50.577627  3209 master.cpp:443] Master 2aaecfe9-c3b2-42f7-ad25-f230400a92ce (9a146ed47ce9) started on 172.17.0.2:35463
I0213 04:26:50.577661  3209 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/N95WkG/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/N95WkG/master" --zk_session_timeout="10secs"
I0213 04:26:50.578114  3209 master.cpp:495] Master only allowing authenticated frameworks to register
I0213 04:26:50.578138  3209 master.cpp:501] Master only allowing authenticated agents to register
I0213 04:26:50.578153  3209 master.cpp:507] Master only allowing authenticated HTTP frameworks to register
I0213 04:26:50.578169  3209 credentials.hpp:37] Loading credentials for authentication from '/tmp/N95WkG/credentials'
I0213 04:26:50.578495  3209 master.cpp:551] Using default 'crammd5' authenticator
I0213 04:26:50.578733  3209 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0213 04:26:50.578995  3209 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0213 04:26:50.579210  3209 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0213 04:26:50.579416  3209 master.cpp:632] Authorization enabled
I0213 04:26:50.579905  3210 whitelist_watcher.cpp:77] No whitelist given
I0213 04:26:50.580015  3201 hierarchical.cpp:567] Initialized hierarchical allocator process
I0213 04:26:50.583278  3208 master.cpp:2172] Elected as the leading master!
I0213 04:26:50.583315  3208 master.cpp:1668] Recovering from registrar
I0213 04:26:50.583503  3204 registrar.cpp:339] Recovering registrar
I0213 04:26:50.584357  3204 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0213 04:26:50.584503  3204 registrar.cpp:487] Applied 1 operations in 47690ns; attempting to update the registry
I0213 04:26:50.585281  3204 registrar.cpp:544] Successfully updated the registry in 0ns
I0213 04:26:50.585434  3204 registrar.cpp:416] Successfully recovered registrar
I0213 04:26:50.585990  3201 master.cpp:1821] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
I0213 04:26:50.586043  3206 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover
W0213 04:26:50.591876  3199 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:35463
I0213 04:26:50.593216  3199 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0213 04:26:50.593753  3199 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0213 04:26:50.593781  3199 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0213 04:26:50.593796  3199 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0213 04:26:50.593829  3199 provisioner.cpp:294] Using default backend 'copy'
I0213 04:26:50.596448  3199 cluster.cpp:533] Creating default 'local' authorizer
I0213 04:26:50.598861  3202 slave.cpp:274] Mesos agent started on (1251)@172.17.0.2:35463
I0213 04:26:50.598891  3202 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/N95WkG/h9zbvM/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/N95WkG/h9zbvM/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/N95WkG/h9zbvM/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/N95WkG/h9zbvM/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/N95WkG/h9zbvM/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/N95WkG/h9zbvM/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/N95WkG/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_MLmNr0" --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_ZyLpoe" --zk_session_timeout="10secs"
I0213 04:26:50.599292  3202 credentials.hpp:86] Loading credential for authentication from '/tmp/N95WkG/h9zbvM/credential'
I0213 04:26:50.599462  3202 slave.cpp:307] Agent using credential for: test-principal
I0213 04:26:50.599485  3202 credentials.hpp:37] Loading credentials for authentication from '/tmp/N95WkG/h9zbvM/http_credentials'
I0213 04:26:50.599685  3202 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0213 04:26:50.600088  3202 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0213 04:26:50.601589  3209 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0213 04:26:50.601541  3202 slave.cpp:622] 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"}]
I0213 04:26:50.601761  3202 slave.cpp:630] Agent attributes: [  ]
I0213 04:26:50.601776  3202 slave.cpp:639] Agent hostname: 9a146ed47ce9
I0213 04:26:50.601900  3212 status_update_manager_process.hpp:379] Pausing operation status update manager
I0213 04:26:50.601922  3208 task_status_update_manager.cpp:181] Pausing sending task status updates
I0213 04:26:50.603401  3205 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ZyLpoe/meta'
I0213 04:26:50.603606  3211 slave.cpp:7606] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ZyLpoe/meta', beginning agent recovery
I0213 04:26:50.604264  3200 task_status_update_manager.cpp:207] Recovering task status update manager
I0213 04:26:50.604914  3204 containerizer.cpp:820] Recovering Mesos containers
I0213 04:26:50.605329  3204 containerizer.cpp:1160] Recovering isolators
I0213 04:26:50.606374  3215 containerizer.cpp:1199] Recovering provisioner
I0213 04:26:50.607285  3203 provisioner.cpp:518] Provisioner recovery complete
I0213 04:26:50.608261  3214 composing.cpp:339] Finished recovering all containerizers
I0213 04:26:50.608721  3213 slave.cpp:8088] Recovering executors
I0213 04:26:50.608848  3213 slave.cpp:8241] Finished recovery
I0213 04:26:50.609772  3215 task_status_update_manager.cpp:181] Pausing sending task status updates
I0213 04:26:50.609798  3213 slave.cpp:1454] New master detected at master@172.17.0.2:35463
I0213 04:26:50.609805  3204 status_update_manager_process.hpp:379] Pausing operation status update manager
I0213 04:26:50.609994  3213 slave.cpp:1519] Detecting new master
I0213 04:26:50.610414  3201 hierarchical.cpp:1853] Performed allocation for 0 agents in 137611ns
I0213 04:26:50.615479  3203 slave.cpp:1546] Authenticating with master master@172.17.0.2:35463
I0213 04:26:50.615594  3203 slave.cpp:1555] Using default CRAM-MD5 authenticatee
I0213 04:26:50.616041  3212 authenticatee.cpp:121] Creating new client SASL connection
I0213 04:26:50.616401  3212 master.cpp:10169] Authenticating slave(1251)@172.17.0.2:35463
I0213 04:26:50.616626  3202 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2110)@172.17.0.2:35463
I0213 04:26:50.617029  3214 authenticator.cpp:98] Creating new server SASL connection
I0213 04:26:50.617285  3209 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0213 04:26:50.617326  3209 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0213 04:26:50.617487  3211 authenticator.cpp:204] Received SASL authentication start
I0213 04:26:50.617571  3211 authenticator.cpp:326] Authentication requires more steps
I0213 04:26:50.617704  3211 authenticatee.cpp:259] Received SASL authentication step
I0213 04:26:50.617858  3211 authenticator.cpp:232] Received SASL authentication step
I0213 04:26:50.617902  3211 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9a146ed47ce9' server FQDN: '9a146ed47ce9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0213 04:26:50.617933  3211 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0213 04:26:50.618000  3211 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0213 04:26:50.618050  3211 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '9a146ed47ce9' server FQDN: '9a146ed47ce9' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0213 04:26:50.618082  3211 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0213 04:26:50.618105  3211 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0213 04:26:50.618139  3211 authenticator.cpp:318] Authentication success
I0213 04:26:50.618254  3206 authenticatee.cpp:299] Authentication success
I0213 04:26:50.618382  3215 master.cpp:10201] Successfully authenticated principal 'test-principal' at slave(1251)@172.17.0.2:35463
I0213 04:26:50.618417  3213 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2110)@172.17.0.2:35463
I0213 04:26:50.618726  3211 slave.cpp:1646] Successfully authenticated with master master@172.17.0.2:35463
I0213 04:26:50.619205  3211 slave.cpp:2096] Will retry registration in 13.600561ms if necessary
I0213 04:26:50.619458  3208 master.cpp:6639] Received register agent message from slave(1251)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:50.619933  3208 master.cpp:3712] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0213 04:26:50.620635  3209 master.cpp:6706] Authorized registration of agent at slave(1251)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:50.620769  3209 master.cpp:6818] Registering agent at slave(1251)@172.17.0.2:35463 (9a146ed47ce9) with id 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0
I0213 04:26:50.621507  3205 registrar.cpp:487] Applied 1 operations in 255333ns; attempting to update the registry
I0213 04:26:50.622318  3205 registrar.cpp:544] Successfully updated the registry in 730112ns
I0213 04:26:50.622539  3206 master.cpp:6866] Admitted agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 at slave(1251)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:50.623423  3206 master.cpp:6911] Registered agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 at slave(1251)@172.17.0.2:35463 (9a146ed47ce9) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0213 04:26:50.623500  3213 slave.cpp:1679] Registered with master master@172.17.0.2:35463; given agent ID 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0
I0213 04:26:50.623697  3202 task_status_update_manager.cpp:188] Resuming sending task status updates
I0213 04:26:50.623695  3207 hierarchical.cpp:959] Added agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 (9a146ed47ce9) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
I0213 04:26:50.624122  3213 slave.cpp:1714] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ZyLpoe/meta/slaves/2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0/slave.info'
I0213 04:26:50.624200  3207 hierarchical.cpp:1853] Performed allocation for 1 agents in 201874ns
I0213 04:26:50.624274  3208 status_update_manager_process.hpp:385] Resuming operation status update manager
I0213 04:26:50.625430  3213 slave.cpp:1766] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"XreDs5ZzTGG/R2VwzshZEw=="},"slave_id":{"value":"2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0"},"update_oversubscribed_resources":false}
I0213 04:26:50.626317  3204 master.cpp:8049] Ignoring update on agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 at slave(1251)@172.17.0.2:35463 (9a146ed47ce9) as it reports no changes
I0213 04:26:50.630641  3209 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1'
I0213 04:26:50.632127  3204 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.2:58762
I0213 04:26:50.632660  3204 http.cpp:2146] Processing GET_CONTAINERS call
I0213 04:26:50.639183  3204 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:50.641700  3202 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1'
I0213 04:26:50.642812  3213 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.2:58764
I0213 04:26:50.643546  3213 http.cpp:2606] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:50.644755  3205 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ZyLpoe/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:50.645663  3200 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:50.646350  3200 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 291072ns
I0213 04:26:50.647193  3200 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MLmNr0/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0213 04:26:50.647253  3200 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 904704ns
I0213 04:26:50.661769  3209 hierarchical.cpp:1853] Performed allocation for 1 agents in 148197ns
I0213 04:26:50.671901  3212 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_uHo3ks","--available_capacity=0B","--volumes=","--forward=unix:///tmp/N95WkG/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_ZyLpoe/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-uBCM7S/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ZyLpoe/containers/o
 rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="108" --pipe_write="109" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MLmNr0/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0213 04:26:50.681489  3212 launcher.cpp:145] Forked child with pid '14823' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:50.701040  3212 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 53.781248ms
I0213 04:26:50.702122  3212 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.079808ms
I0213 04:26:50.702374  3206 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_ZyLpoe/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:50.703533  3203 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.387264ms
I0213 04:26:50.705914  3211 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'
I0213 04:26:50.706075  3211 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-uBCM7S/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:50.713749  3208 hierarchical.cpp:1853] Performed allocation for 1 agents in 186365ns
I0213 04:26:50.765188  3205 hierarchical.cpp:1853] Performed allocation for 1 agents in 144414ns
I0213 04:26:50.816210  3208 hierarchical.cpp:1853] Performed allocation for 1 agents in 132314ns
I0213 04:26:50.868026  3209 hierarchical.cpp:1853] Performed allocation for 1 agents in 130232ns
I0213 04:26:50.919426  3204 hierarchical.cpp:1853] Performed allocation for 1 agents in 225872ns
I0213 04:26:50.970679  3213 hierarchical.cpp:1853] Performed allocation for 1 agents in 171186ns
I0213 04:26:51.021564  3202 hierarchical.cpp:1853] Performed allocation for 1 agents in 189680ns
I0213 04:26:51.028874  3207 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-uBCM7S/endpoint.sock' with CSI v1
I0213 04:26:51.030985 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call
I0213 04:26:51.034185  3208 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:51.037178 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call
I0213 04:26:51.038090  3215 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1'
I0213 04:26:51.039456  3208 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.2:58766
I0213 04:26:51.040005  3208 http.cpp:2824] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:51.041369 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
I0213 04:26:51.041733 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
I0213 04:26:51.043517  3200 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {}
I0213 04:26:51.044116  3200 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {}
I0213 04:26:51.046097 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
I0213 04:26:51.050067 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call
I0213 04:26:51.053671 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call
I0213 04:26:51.056046  3205 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0213 04:26:51.056250  3210 status_update_manager_process.hpp:379] Pausing operation status update manager
I0213 04:26:51.056625  3203 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35463/slave(1251)/api/v1/resource_provider
I0213 04:26:51.060204  3215 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35463/slave(1251)/api/v1/resource_provider
I0213 04:26:51.060925  3200 provider.cpp:476] Connected to resource provider manager
I0213 04:26:51.061656  3210 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35463/slave(1251)/api/v1/resource_provider
I0213 04:26:51.062871  3209 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1/resource_provider'
I0213 04:26:51.064865  3204 http.cpp:1405] HTTP POST for /slave(1251)/api/v1/resource_provider from 172.17.0.2:58770
I0213 04:26:51.065791  3214 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_uHo3ks","--available_capacity=0B","--volumes=","--forward=unix:///tmp/N95WkG/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"}
I0213 04:26:51.072805  3206 hierarchical.cpp:1853] Performed allocation for 1 agents in 186025ns
I0213 04:26:51.106544  3203 slave.cpp:8597] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"2329cb5a-a6ce-4e61-8d8c-c6132b772e0d"},"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_uHo3ks","--available_capacity=0B","--volumes=","--forward=unix:///tmp/N95WkG/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"}'
I0213 04:26:51.108395  3208 provider.cpp:498] Received SUBSCRIBED event
I0213 04:26:51.108450  3208 provider.cpp:1309] Subscribed with ID 2329cb5a-a6ce-4e61-8d8c-c6132b772e0d
I0213 04:26:51.109287  3211 status_update_manager_process.hpp:314] Recovering operation status update manager
I0213 04:26:51.124178  3212 hierarchical.cpp:1853] Performed allocation for 1 agents in 134616ns
I0213 04:26:51.175019  3215 hierarchical.cpp:1853] Performed allocation for 1 agents in 206504ns
I0213 04:26:51.201443  3210 provider.cpp:790] Reconciling storage pools and volumes
I0213 04:26:51.204073 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0213 04:26:51.206923  3207 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0
I0213 04:26:51.207329  3210 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:35463/slave(1251)/api/v1/resource_provider
I0213 04:26:51.207391  3207 provider.cpp:748] Resource provider 2329cb5a-a6ce-4e61-8d8c-c6132b772e0d is in READY state
I0213 04:26:51.207494  3201 status_update_manager_process.hpp:385] Resuming operation status update manager
I0213 04:26:51.208325  3214 provider.cpp:1235] Updating profiles { test } for resource provider 2329cb5a-a6ce-4e61-8d8c-c6132b772e0d
I0213 04:26:51.208588  3204 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1/resource_provider'
I0213 04:26:51.209595  3213 provider.cpp:790] Reconciling storage pools and volumes
I0213 04:26:51.210124  3205 http.cpp:1405] HTTP POST for /slave(1251)/api/v1/resource_provider from 172.17.0.2:58768
I0213 04:26:51.210796  3205 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 2329cb5a-a6ce-4e61-8d8c-c6132b772e0d
I0213 04:26:51.211025  3211 slave.cpp:8597] Handling resource provider message 'UPDATE_STATE: 2329cb5a-a6ce-4e61-8d8c-c6132b772e0d {}'
I0213 04:26:51.211130  3211 slave.cpp:8717] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0213 04:26:51.212251 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0213 04:26:51.212730 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
I0213 04:26:51.212726  3214 hierarchical.cpp:1110] Grew agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 by {} (total), {  } (used)
I0213 04:26:51.213199  3214 hierarchical.cpp:1067] Agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 (9a146ed47ce9) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0213 04:26:51.218809  3203 hierarchical.cpp:1853] Performed allocation for 1 agents in 189410ns
I0213 04:26:51.219166  3206 provider.cpp:790] Reconciling storage pools and volumes
I0213 04:26:51.221515 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0213 04:26:51.221858 14827 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
I0213 04:26:51.232313  3213 slave.cpp:995] Agent terminating
I0213 04:26:51.233172  3213 manager.cpp:127] Terminating resource provider 2329cb5a-a6ce-4e61-8d8c-c6132b772e0d
I0213 04:26:51.233676  3206 master.cpp:1299] Agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 at slave(1251)@172.17.0.2:35463 (9a146ed47ce9) disconnected
I0213 04:26:51.233736  3206 master.cpp:3368] Disconnecting agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 at slave(1251)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:51.233841  3206 master.cpp:3387] Deactivating agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 at slave(1251)@172.17.0.2:35463 (9a146ed47ce9)
I0213 04:26:51.234055  3214 hierarchical.cpp:1156] Agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0 deactivated
E0213 04:26:51.234330  3205 http_connection.hpp:449] End-Of-File received
I0213 04:26:51.234943  3205 http_connection.hpp:217] Re-detecting endpoint
I0213 04:26:51.235438  3205 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0213 04:26:51.235517  3205 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0213 04:26:51.235566  3202 provider.cpp:488] Disconnected from resource provider manager
I0213 04:26:51.235605  3205 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35463/slave(1251)/api/v1/resource_provider
I0213 04:26:51.235729  3210 status_update_manager_process.hpp:379] Pausing operation status update manager
I0213 04:26:51.237304  3201 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
I0213 04:26:51.237361  3201 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.533861888secs
I0213 04:26:51.237807  3201 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:51.239223  3203 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35463/slave(1251)/api/v1/resource_provider
I0213 04:26:51.239914  3205 provider.cpp:476] Connected to resource provider manager
I0213 04:26:51.240643  3209 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35463/slave(1251)/api/v1/resource_provider
I0213 04:26:51.241609  3216 process.cpp:2781] Returning '404 Not Found' for '/slave(1251)/api/v1/resource_provider'
E0213 04:26:51.242941  3213 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0213 04:26:51.264963  3210 hierarchical.cpp:1853] Performed allocation for 1 agents in 152124ns
I0213 04:26:51.315696  3207 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0213 04:26:51.316916  3200 hierarchical.cpp:1853] Performed allocation for 1 agents in 170914ns
I0213 04:26:51.317678  3213 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
I0213 04:26:51.320996  3212 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'
I0213 04:26:51.321271  3212 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-uBCM7S/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0213 04:26:51.321542  3213 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0213 04:26:51.324631  3216 process.cpp:2781] Returning '404 Not Found' for '/slave(1251)/api/v1'
I0213 04:26:51.336292  3199 master.cpp:1140] Master terminating
I0213 04:26:51.336724  3202 hierarchical.cpp:1132] Removed all filters for agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0
I0213 04:26:51.336753  3202 hierarchical.cpp:1008] Removed agent 2aaecfe9-c3b2-42f7-ad25-f230400a92ce-S0
[       OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (776 ms)
[----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (107301 ms total)

[----------] Global test environment tear-down
[==========] 2321 tests from 222 test cases ran. (1316562 ms total)
[  PASSED  ] 2320 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] OversubscriptionTest.FixedResourceEstimator

 1 FAILED TEST
  YOU HAVE 34 DISABLED TESTS

I0213 04:26:51.421592  3216 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/7191/console

- Mesos Reviewbot


On Feb. 13, 2020, 2:05 a.m., Benjamin Mahler wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72124/
> -----------------------------------------------------------
> 
> (Updated Feb. 13, 2020, 2:05 a.m.)
> 
> 
> Review request for mesos, Greg Mann and Joseph Wu.
> 
> 
> Bugs: MESOS-10095
>     https://issues.apache.org/jira/browse/MESOS-10095
> 
> 
> Repository: mesos
> 
> 
> Description
> -------
> 
> When draining an agent, it's hard to tell which tasks failed to
> terminate from the logs. The master prints a count of the tasks
> remaining (only as VLOG(1) however), but not the IDs.
> 
> This patch adds logging to the initiation of the drain on both the
> master and agent, that shows which tasks and operations are present.
> This makes it possible to then see which ones did not transition to
> a terminal state (with a bit of log analysis effort).
> 
> 
> Diffs
> -----
> 
>   src/master/http.cpp eeaac88c893b43170e655f8bff1d57dd0f7bbfb2 
>   src/slave/slave.cpp cce275a504effae7a6b71dd333ce8a300d1ce5be 
> 
> 
> Diff: https://reviews.apache.org/r/72124/diff/1/
> 
> 
> Testing
> -------
> 
> make check
> 
> Examples:
> 
> ```
> I0212 18:03:33.488853 14728 http.cpp:4102] Transitioning agent e1120790-a1cf-488d-8024-29cbaf1f63c4-S0 to the DRAINING state; agent has (pending tasks, tasks, operations) == ({  }, { e1120790-a1cf-488d-8024-29cbaf1f63c4-0000: { a3bcc29d-3f7c-4454-8363-4a5cccc39370 } }, {  })
> 
> I0212 18:03:32.496709 14720 slave.cpp:1097] Initiating drain with DrainConfig {"mark_gone":false}; agent has (pending tasks, queued tasks, launched tasks, operations) == ({  }, {  }, { 968682eb-95c3-4d1e-a2b6-d04cb1a16a94-0000: { 2d3e2ab5-b6ed-4a87-b390-9f88dda18b7a } }, {  })
> ```
> 
> 
> Thanks,
> 
> Benjamin Mahler
> 
>


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message