You are viewing a plain text version of this content. The canonical link for it is here.
Posted to reviews@mesos.apache.org by Benjamin Mahler <bm...@apache.org> on 2020/02/13 02:05:30 UTC
Review Request 72124: Added logging of tasks and operations during
agent drain initiation.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72124/
-----------------------------------------------------------
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
Re: Review Request 72124: Added logging of tasks and operations
during agent drain initiation.
Posted by Mesos Reviewbot <re...@mesos.apache.org>.
-----------------------------------------------------------
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
>
>
Re: Review Request 72124: Added logging of tasks and operations
during agent drain initiation.
Posted by Joseph Wu <jo...@mesosphere.io>.
-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/72124/#review219658
-----------------------------------------------------------
Fix it, then Ship it!
src/master/http.cpp
Lines 4083-4086 (patched)
<https://reviews.apache.org/r/72124/#comment307868>
We should only be able to skip through this condition if the agent is removed between calling DrainAgent and committing the change to the registrar. So instead of this TODO, perhaps we should add a comment saying so. (Also, the DrainSlaveMessage would be sent when/if the agent comes back).
- Joseph Wu
On Feb. 12, 2020, 6:05 p.m., Benjamin Mahler wrote:
>
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/72124/
> -----------------------------------------------------------
>
> (Updated Feb. 12, 2020, 6:05 p.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
>
>