----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/71983/#review219238 -----------------------------------------------------------
Bad patch! Reviews applied: [71855, 71931, 71856, 71858, 71884, 71885, 71886, 71943, 71944, 71950, 71951, 71952, 71953, 71955, 71956, 71983] Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:14.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/docker-build.sh 2>&1 | tee build_71983"] Error: ...<truncated>... for 5secs I0113 14:42:50.135164 18746 slave.cpp:8649] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: fd3922bf-da98-42dc-9580-c844ec08d423) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0113 14:42:50.141620 18746 slave.cpp:9102] Updating the state of operation with no ID (uuid: fd3922bf-da98-42dc-9580-c844ec08d423) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0113 14:42:50.141710 18746 slave.cpp:8856] Forwarding status update of operation with no ID (operation_uuid: fd3922bf-da98-42dc-9580-c844ec08d423) for an operator API call I0113 14:42:50.142206 18740 master.cpp:11789] Updating the state of operation '' (uuid: fd3922bf-da98-42dc-9580-c844ec08d423) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0113 14:42:50.143069 18746 slave.cpp:4504] Ignoring new checkpointed resources and operations identical to the current version I0113 14:42:50.145885 18742 master.cpp:12137] Sending operation '' (uuid: 610118ba-c9c5-4038-af95-618974e68148) to agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 at slave(1252)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:50.146699 18750 slave.cpp:4504] Ignoring new checkpointed resources and operations identical to the current version I0113 14:42:50.149614 18735 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0113 14:42:50.150440 18735 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 84eb7230-1cb5-4427-be3e-4d06541a4c49) for stream fd3922bf-da98-42dc-9580-c844ec08d423 I0113 14:42:50.150903 18735 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 84eb7230-1cb5-4427-be3e-4d06541a4c49) for operation UUID fd3922bf-da98-42dc-9580-c844ec08d423 on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.151826 18751 provider.cpp:498] Received APPLY_OPERATION event I0113 14:42:50.151877 18751 provider.cpp:1351] Received CREATE operation '' (uuid: 610118ba-c9c5-4038-af95-618974e68148) I0113 14:42:50.152490 18734 master.cpp:5959] Processing REVIVE call for framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 I0113 14:42:50.153231 18734 hierarchical.cpp:1721] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 I0113 14:42:50.155328 18734 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.775707ms I0113 14:42:50.156787 18734 master.cpp:9975] Sending offers [ b00a682f-f28c-4094-b628-fc274d7f3dab-O4 ] to framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 I0113 14:42:50.158025 18734 sched.cpp:934] Scheduler::resourceOffers took 123096ns I0113 14:42:50.171032 18743 hierarchical.cpp:1853] Performed allocation for 1 agents in 389864ns I0113 14:42:50.235703 18735 status_update_manager_process.hpp:490] Cleaning up operation status update stream fd3922bf-da98-42dc-9580-c844ec08d423 I0113 14:42:50.295411 18739 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 4b993a71-5380-4d75-b388-1002ffdbfee5) for operation UUID 610118ba-c9c5-4038-af95-618974e68148 on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.296057 18739 status_update_manager_process.hpp:414] Creating operation status update stream 610118ba-c9c5-4038-af95-618974e68148 checkpoint=true I0113 14:42:50.296684 18739 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 4b993a71-5380-4d75-b388-1002ffdbfee5) for operation UUID 610118ba-c9c5-4038-af95-618974e68148 on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.354960 18739 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 4b993a71-5380-4d75-b388-1002ffdbfee5) for operation UUID 610118ba-c9c5-4038-af95-618974e68148 on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.356869 18731 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:38425/slave(1252)/api/v1/resource_provider I0113 14:42:50.358801 18747 process.cpp:3671] Handling HTTP event for process 'slave(1252)' with path: '/slave(1252)/api/v1/resource_provider' I0113 14:42:50.365479 18740 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0113 14:42:50.369163 18742 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:48020 I0113 14:42:50.369716 18742 http.cpp:276] Processing call DESTROY_VOLUMES I0113 14:42:50.371076 18742 master.cpp:3713] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"07d1e258-e000-43ac-8bab-dd175ebfe759"},"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":"605edc41-ed74-4afd-9c5f-f94fdd4a98e8","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_qFDguo/2GB-f675ca38-4cbf-47a2-8eab-9cf7721e7fef","profile":"test"}}}} I0113 14:42:50.374749 18734 master.cpp:12272] Removing offer b00a682f-f28c-4094-b628-fc274d7f3dab-O4 I0113 14:42:50.375229 18733 sched.cpp:960] Rescinded offer b00a682f-f28c-4094-b628-fc274d7f3dab-O4 I0113 14:42:50.380172 18733 sched.cpp:971] Scheduler::offerRescinded took 45577ns I0113 14:42:50.376068 18736 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_qFDguo/2GB-f675ca38-4cbf-47a2-8eab-9cf7721e7fef,test),605edc41-ed74-4afd-9c5f-f94fdd4a98e8: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_qFDguo/2GB-f675ca38-4cbf-47a2-8eab-9cf7721e7fef,test),605edc41-ed74-4afd-9c5f-f94fdd4a98e8:volume]:2048, offered or allocated: {}) on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 from framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 I0113 14:42:50.383327 18736 hierarchical.cpp:1625] Framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 filtered agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 for 5secs I0113 14:42:50.388327 18736 master.cpp:12137] Sending operation '' (uuid: 37735f09-0469-418c-981b-ee2edabecabb) to agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 at slave(1252)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:50.390223 18738 slave.cpp:4504] Ignoring new checkpointed resources and operations identical to the current version I0113 14:42:50.411435 18744 http.cpp:1405] HTTP POST for /slave(1252)/api/v1/resource_provider from 172.17.0.2:48006 I0113 14:42:50.412521 18740 provider.cpp:498] Received APPLY_OPERATION event I0113 14:42:50.412590 18740 provider.cpp:1351] Received DESTROY operation '' (uuid: 37735f09-0469-418c-981b-ee2edabecabb) I0113 14:42:50.413499 18744 slave.cpp:8649] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 610118ba-c9c5-4038-af95-618974e68148) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0113 14:42:50.413748 18744 slave.cpp:9102] Updating the state of operation with no ID (uuid: 610118ba-c9c5-4038-af95-618974e68148) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0113 14:42:50.413810 18744 slave.cpp:8856] Forwarding status update of operation with no ID (operation_uuid: 610118ba-c9c5-4038-af95-618974e68148) for an operator API call I0113 14:42:50.414381 18744 master.cpp:11789] Updating the state of operation '' (uuid: 610118ba-c9c5-4038-af95-618974e68148) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0113 14:42:50.416014 18745 slave.cpp:4504] Ignoring new checkpointed resources and operations identical to the current version I0113 14:42:50.423218 18732 master.cpp:9975] Sending offers [ b00a682f-f28c-4094-b628-fc274d7f3dab-O5 ] to framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 I0113 14:42:50.424294 18732 sched.cpp:934] Scheduler::resourceOffers took 108984ns I0113 14:42:50.424582 18749 hierarchical.cpp:1853] Performed allocation for 1 agents in 6.108395ms I0113 14:42:50.514293 18742 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 8a145707-fa01-4856-898c-d390e3d36d59) for operation UUID 37735f09-0469-418c-981b-ee2edabecabb on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.514446 18742 status_update_manager_process.hpp:414] Creating operation status update stream 37735f09-0469-418c-981b-ee2edabecabb checkpoint=true I0113 14:42:50.514987 18742 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 8a145707-fa01-4856-898c-d390e3d36d59) for operation UUID 37735f09-0469-418c-981b-ee2edabecabb on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.515506 18740 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0113 14:42:50.580731 18742 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 8a145707-fa01-4856-898c-d390e3d36d59) for operation UUID 37735f09-0469-418c-981b-ee2edabecabb on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.581408 18742 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 4b993a71-5380-4d75-b388-1002ffdbfee5) for stream 610118ba-c9c5-4038-af95-618974e68148 I0113 14:42:50.581518 18742 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 4b993a71-5380-4d75-b388-1002ffdbfee5) for operation UUID 610118ba-c9c5-4038-af95-618974e68148 on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.582700 18738 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:38425/slave(1252)/api/v1/resource_provider I0113 14:42:50.584414 18744 process.cpp:3671] Handling HTTP event for process 'slave(1252)' with path: '/slave(1252)/api/v1/resource_provider' I0113 14:42:50.625059 18745 http.cpp:1405] HTTP POST for /slave(1252)/api/v1/resource_provider from 172.17.0.2:48006 I0113 14:42:50.627074 18745 slave.cpp:8649] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 37735f09-0469-418c-981b-ee2edabecabb) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0113 14:42:50.627348 18745 slave.cpp:9102] Updating the state of operation with no ID (uuid: 37735f09-0469-418c-981b-ee2edabecabb) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0113 14:42:50.627413 18745 slave.cpp:8856] Forwarding status update of operation with no ID (operation_uuid: 37735f09-0469-418c-981b-ee2edabecabb) for an operator API call I0113 14:42:50.627873 18732 master.cpp:11789] Updating the state of operation '' (uuid: 37735f09-0469-418c-981b-ee2edabecabb) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0113 14:42:50.631657 18745 slave.cpp:4504] Ignoring new checkpointed resources and operations identical to the current version I0113 14:42:50.632710 18742 status_update_manager_process.hpp:490] Cleaning up operation status update stream 610118ba-c9c5-4038-af95-618974e68148 I0113 14:42:50.690786 18748 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0113 14:42:50.691233 18748 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 8a145707-fa01-4856-898c-d390e3d36d59) for stream 37735f09-0469-418c-981b-ee2edabecabb I0113 14:42:50.691378 18748 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 8a145707-fa01-4856-898c-d390e3d36d59) for operation UUID 37735f09-0469-418c-981b-ee2edabecabb on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.740547 18748 status_update_manager_process.hpp:490] Cleaning up operation status update stream 37735f09-0469-418c-981b-ee2edabecabb I0113 14:42:50.789002 18735 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0113 14:42:50.792510 18735 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:48028 I0113 14:42:50.793066 18735 http.cpp:276] Processing call UNRESERVE_RESOURCES I0113 14:42:50.794275 18735 master.cpp:3713] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"07d1e258-e000-43ac-8bab-dd175ebfe759"},"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_qFDguo/2GB-f675ca38-4cbf-47a2-8eab-9cf7721e7fef","profile":"test"}}}} I0113 14:42:50.797659 18749 sched.cpp:960] Rescinded offer b00a682f-f28c-4094-b628-fc274d7f3dab-O5 I0113 14:42:50.797782 18749 sched.cpp:971] Scheduler::offerRescinded took 31924ns I0113 14:42:50.798754 18746 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_qFDguo/2GB-f675ca38-4cbf-47a2-8eab-9cf7721e7fef,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_qFDguo/2GB-f675ca38-4cbf-47a2-8eab-9cf7721e7fef,test)]:2048, offered or allocated: {}) on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 from framework b00a6 82f-f28c-4094-b628-fc274d7f3dab-0000 I0113 14:42:50.800923 18746 hierarchical.cpp:1625] Framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 filtered agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 for 5secs I0113 14:42:50.802237 18735 master.cpp:12272] Removing offer b00a682f-f28c-4094-b628-fc274d7f3dab-O5 I0113 14:42:50.810978 18735 master.cpp:12137] Sending operation '' (uuid: 8f28d9e5-794f-4e90-abc2-973adeb5ed09) to agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 at slave(1252)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:50.812220 18735 slave.cpp:4504] Ignoring new checkpointed resources and operations identical to the current version I0113 14:42:50.817654 18730 provider.cpp:498] Received APPLY_OPERATION event I0113 14:42:50.818075 18730 provider.cpp:1351] Received UNRESERVE operation '' (uuid: 8f28d9e5-794f-4e90-abc2-973adeb5ed09) I0113 14:42:50.818470 18747 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.912987ms I0113 14:42:50.819558 18747 master.cpp:9975] Sending offers [ b00a682f-f28c-4094-b628-fc274d7f3dab-O6 ] to framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 I0113 14:42:50.820523 18747 sched.cpp:934] Scheduler::resourceOffers took 110438ns I0113 14:42:50.917697 18741 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: e4c7ae34-a1cd-4e35-a248-a39289632c9f) for operation UUID 8f28d9e5-794f-4e90-abc2-973adeb5ed09 on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.917857 18741 status_update_manager_process.hpp:414] Creating operation status update stream 8f28d9e5-794f-4e90-abc2-973adeb5ed09 checkpoint=true I0113 14:42:50.918388 18741 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: e4c7ae34-a1cd-4e35-a248-a39289632c9f) for operation UUID 8f28d9e5-794f-4e90-abc2-973adeb5ed09 on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.984450 18741 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: e4c7ae34-a1cd-4e35-a248-a39289632c9f) for operation UUID 8f28d9e5-794f-4e90-abc2-973adeb5ed09 on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:50.986050 18741 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:38425/slave(1252)/api/v1/resource_provider I0113 14:42:50.987897 18745 process.cpp:3671] Handling HTTP event for process 'slave(1252)' with path: '/slave(1252)/api/v1/resource_provider' I0113 14:42:50.988636 18745 master.cpp:1414] Framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 disconnected I0113 14:42:50.988692 18745 master.cpp:3333] Deactivating framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 I0113 14:42:50.989382 18735 hierarchical.cpp:813] Deactivated framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 I0113 14:42:50.989825 18729 slave.cpp:992] Agent terminating I0113 14:42:50.989970 18745 master.cpp:12272] Removing offer b00a682f-f28c-4094-b628-fc274d7f3dab-O6 I0113 14:42:50.990062 18745 master.cpp:3310] Disconnecting framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 I0113 14:42:50.990183 18745 master.cpp:1429] Giving framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 0ns to failover I0113 14:42:50.990125 18735 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_qFDguo/2GB-f675ca38-4cbf-47a2-8eab-9cf7721e7fef,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_qFDguo/2GB-f675ca38-4cbf-47a2-8eab-9cf7721e7fef,test)]:2048, offered or allocated: {}) on agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 from framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 I0113 14:42:50.991156 18729 manager.cpp:127] Terminating resource provider 07d1e258-e000-43ac-8bab-dd175ebfe759 I0113 14:42:50.991711 18730 master.cpp:1299] Agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 at slave(1252)@172.17.0.2:38425 (c27cf6ba285d) disconnected I0113 14:42:50.991752 18730 master.cpp:3368] Disconnecting agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 at slave(1252)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:50.991845 18730 master.cpp:3387] Deactivating agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 at slave(1252)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:50.992800 18735 hierarchical.cpp:1156] Agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 deactivated I0113 14:42:50.992916 18749 master.cpp:9761] Framework failover timeout, removing framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 I0113 14:42:50.992977 18749 master.cpp:10763] Removing framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 (default) at [email protected]:38425 E0113 14:42:50.994490 18749 http_connection.hpp:449] End-Of-File received I0113 14:42:50.995090 18749 http_connection.hpp:217] Re-detecting endpoint I0113 14:42:50.995637 18749 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38425/slave(1252)/api/v1/resource_provider E0113 14:42:50.997594 18749 provider.cpp:2258] Failed to send status update for operation (uuid: 8f28d9e5-794f-4e90-abc2-973adeb5ed09): Disconnected I0113 14:42:50.998031 18749 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0113 14:42:50.998066 18734 provider.cpp:488] Disconnected from resource provider manager I0113 14:42:50.998102 18749 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0113 14:42:51.000947 18749 status_update_manager_process.hpp:379] Pausing operation status update manager I0113 14:42:51.001063 18735 hierarchical.cpp:1777] Allocation paused I0113 14:42:51.001715 18735 hierarchical.cpp:757] Removed framework b00a682f-f28c-4094-b628-fc274d7f3dab-0000 I0113 14:42:51.001790 18735 hierarchical.cpp:1787] Allocation resumed I0113 14:42:51.002425 18753 containerizer.cpp:2624] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0113 14:42:51.002511 18753 containerizer.cpp:3322] 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.980435328secs I0113 14:42:51.003144 18753 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:51.008755 18734 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38425/slave(1252)/api/v1/resource_provider I0113 14:42:51.011088 18734 hierarchical.cpp:1853] Performed allocation for 1 agents in 272772ns I0113 14:42:51.011335 18746 provider.cpp:476] Connected to resource provider manager I0113 14:42:51.012737 18746 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38425/slave(1252)/api/v1/resource_provider I0113 14:42:51.014516 18754 process.cpp:2781] Returning '404 Not Found' for '/slave(1252)/api/v1/resource_provider' E0113 14:42:51.020839 18749 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0113 14:42:51.065898 18733 hierarchical.cpp:1853] Performed allocation for 1 agents in 434834ns I0113 14:42:51.116461 18739 containerizer.cpp:3160] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0113 14:42:51.118826 18747 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 I0113 14:42:51.122705 18737 hierarchical.cpp:1853] Performed allocation for 1 agents in 270770ns I0113 14:42:51.123324 18731 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' I0113 14:42:51.123646 18731 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-ATORe9/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:51.123960 18731 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:51.143693 18754 process.cpp:2781] Returning '404 Not Found' for '/slave(1252)/api/v1' E0113 14:42:51.156848 18735 container_daemon.cpp:150] Failed to launch container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE': Failed to launch container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE': Unexpected response '404 Not Found' (404 Not Found.) E0113 14:42:51.157241 18735 service_manager.cpp:751] Container daemon for 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' failed: Failed to launch container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE': Unexpected response '404 Not Found' (404 Not Found.) I0113 14:42:51.230733 18729 master.cpp:1140] Master terminating I0113 14:42:51.232583 18743 hierarchical.cpp:1132] Removed all filters for agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 I0113 14:42:51.232620 18743 hierarchical.cpp:1008] Removed agent b00a682f-f28c-4094-b628-fc274d7f3dab-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2991 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 I0113 14:42:51.274760 18729 cluster.cpp:180] Creating default 'local' authorizer I0113 14:42:51.281255 18752 master.cpp:443] Master 06aca33b-b2a8-4b6e-93e2-eb643eaacb75 (c27cf6ba285d) started on 172.17.0.2:38425 I0113 14:42:51.281318 18752 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/6sCJlA/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/mesos/mesos-1.10.0/_inst/share/mesos/webui" --work_dir="/tmp/6sCJlA/master" --zk_session_timeout="10secs" I0113 14:42:51.281850 18752 master.cpp:495] Master only allowing authenticated frameworks to register I0113 14:42:51.281869 18752 master.cpp:501] Master only allowing authenticated agents to register I0113 14:42:51.281882 18752 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0113 14:42:51.281894 18752 credentials.hpp:37] Loading credentials for authentication from '/tmp/6sCJlA/credentials' I0113 14:42:51.282343 18752 master.cpp:551] Using default 'crammd5' authenticator I0113 14:42:51.282651 18752 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0113 14:42:51.282914 18752 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0113 14:42:51.283089 18752 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0113 14:42:51.283260 18752 master.cpp:632] Authorization enabled I0113 14:42:51.284281 18751 hierarchical.cpp:567] Initialized hierarchical allocator process I0113 14:42:51.284524 18751 whitelist_watcher.cpp:77] No whitelist given I0113 14:42:51.293404 18735 master.cpp:2172] Elected as the leading master! I0113 14:42:51.293486 18735 master.cpp:1668] Recovering from registrar I0113 14:42:51.293992 18735 registrar.cpp:339] Recovering registrar I0113 14:42:51.296021 18749 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0113 14:42:51.296270 18749 registrar.cpp:487] Applied 1 operations in 66641ns; attempting to update the registry I0113 14:42:51.297683 18749 registrar.cpp:544] Successfully updated the registry in 0ns I0113 14:42:51.297909 18749 registrar.cpp:416] Successfully recovered registrar I0113 14:42:51.299145 18746 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover I0113 14:42:51.299238 18749 master.cpp:1821] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister W0113 14:42:51.314967 18729 process.cpp:2877] Attempted to spawn already running process [email protected]:38425 I0113 14:42:51.317582 18729 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0113 14:42:51.318459 18729 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0113 14:42:51.318496 18729 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0113 14:42:51.318665 18729 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0113 14:42:51.318715 18729 provisioner.cpp:294] Using default backend 'copy' I0113 14:42:51.321965 18729 cluster.cpp:527] Creating default 'local' authorizer I0113 14:42:51.326220 18734 slave.cpp:273] Mesos agent started on (1253)@172.17.0.2:38425 I0113 14:42:51.326799 18734 slave.cpp:274] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/6sCJlA/behYgS/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/6sCJlA/behYgS/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/6sCJlA/behYgS/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/6sCJlA/behYgS/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/6sCJlA/behYgS/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/6sCJlA/behYgS/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="/mesos/mesos-1.10.0/_build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/6sCJlA/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_VjPCLN" --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_StorageLocalResourcePro viderTest_Update_v0_I8cigJ" --zk_session_timeout="10secs" I0113 14:42:51.327469 18734 credentials.hpp:86] Loading credential for authentication from '/tmp/6sCJlA/behYgS/credential' I0113 14:42:51.327769 18734 slave.cpp:306] Agent using credential for: test-principal I0113 14:42:51.327796 18734 credentials.hpp:37] Loading credentials for authentication from '/tmp/6sCJlA/behYgS/http_credentials' I0113 14:42:51.328040 18734 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0113 14:42:51.328482 18734 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0113 14:42:51.330682 18746 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0113 14:42:51.331048 18735 hierarchical.cpp:1853] Performed allocation for 0 agents in 162003ns I0113 14:42:51.331039 18734 slave.cpp:621] 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"}] I0113 14:42:51.331259 18734 slave.cpp:629] Agent attributes: [ ] I0113 14:42:51.331275 18734 slave.cpp:638] Agent hostname: c27cf6ba285d I0113 14:42:51.331502 18752 task_status_update_manager.cpp:181] Pausing sending task status updates I0113 14:42:51.331568 18752 status_update_manager_process.hpp:379] Pausing operation status update manager I0113 14:42:51.333706 18748 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_I8cigJ/meta' I0113 14:42:51.334197 18734 slave.cpp:7658] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_I8cigJ/meta', beginning agent recovery I0113 14:42:51.334854 18732 task_status_update_manager.cpp:207] Recovering task status update manager I0113 14:42:51.335793 18732 containerizer.cpp:823] Recovering Mesos containers I0113 14:42:51.336205 18732 containerizer.cpp:1163] Recovering isolators I0113 14:42:51.337172 18751 containerizer.cpp:1202] Recovering provisioner I0113 14:42:51.338249 18751 provisioner.cpp:518] Provisioner recovery complete I0113 14:42:51.339264 18743 composing.cpp:343] Finished recovering all containerizers I0113 14:42:51.339740 18743 slave.cpp:8140] Recovering executors I0113 14:42:51.339872 18743 slave.cpp:8293] Finished recovery I0113 14:42:51.341467 18740 slave.cpp:1419] New master detected at [email protected]:38425 I0113 14:42:51.341673 18731 task_status_update_manager.cpp:181] Pausing sending task status updates I0113 14:42:51.341765 18731 status_update_manager_process.hpp:379] Pausing operation status update manager I0113 14:42:51.342031 18740 slave.cpp:1484] Detecting new master I0113 14:42:51.349992 18744 slave.cpp:1511] Authenticating with master [email protected]:38425 I0113 14:42:51.350589 18744 slave.cpp:1520] Using default CRAM-MD5 authenticatee I0113 14:42:51.351495 18744 authenticatee.cpp:121] Creating new client SASL connection I0113 14:42:51.352039 18744 master.cpp:10160] Authenticating slave(1253)@172.17.0.2:38425 I0113 14:42:51.352303 18744 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2117)@172.17.0.2:38425 I0113 14:42:51.352835 18744 authenticator.cpp:98] Creating new server SASL connection I0113 14:42:51.353157 18744 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0113 14:42:51.353196 18744 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0113 14:42:51.353364 18738 authenticator.cpp:204] Received SASL authentication start I0113 14:42:51.353442 18738 authenticator.cpp:326] Authentication requires more steps I0113 14:42:51.353560 18744 authenticatee.cpp:259] Received SASL authentication step I0113 14:42:51.353721 18736 authenticator.cpp:232] Received SASL authentication step I0113 14:42:51.353757 18736 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c27cf6ba285d' server FQDN: 'c27cf6ba285d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0113 14:42:51.353775 18736 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0113 14:42:51.353830 18736 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0113 14:42:51.353863 18736 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c27cf6ba285d' server FQDN: 'c27cf6ba285d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0113 14:42:51.353878 18736 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0113 14:42:51.353890 18736 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0113 14:42:51.353919 18736 authenticator.cpp:318] Authentication success I0113 14:42:51.354202 18736 master.cpp:10192] Successfully authenticated principal 'test-principal' at slave(1253)@172.17.0.2:38425 I0113 14:42:51.354254 18742 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2117)@172.17.0.2:38425 I0113 14:42:51.354341 18744 authenticatee.cpp:299] Authentication success I0113 14:42:51.369580 18745 slave.cpp:1611] Successfully authenticated with master [email protected]:38425 I0113 14:42:51.370312 18745 slave.cpp:2061] Will retry registration in 7.494023ms if necessary I0113 14:42:51.370880 18745 master.cpp:6630] Received register agent message from slave(1253)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:51.371439 18745 master.cpp:3713] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0113 14:42:51.372969 18745 master.cpp:6697] Authorized registration of agent at slave(1253)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:51.373121 18745 master.cpp:6809] Registering agent at slave(1253)@172.17.0.2:38425 (c27cf6ba285d) with id 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 I0113 14:42:51.374416 18742 registrar.cpp:487] Applied 1 operations in 390001ns; attempting to update the registry I0113 14:42:51.375819 18742 registrar.cpp:544] Successfully updated the registry in 1.28512ms I0113 14:42:51.376189 18742 master.cpp:6857] Admitted agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 at slave(1253)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:51.377424 18742 master.cpp:6902] Registered agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 at slave(1253)@172.17.0.2:38425 (c27cf6ba285d) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0113 14:42:51.377707 18742 slave.cpp:1644] Registered with master [email protected]:38425; given agent ID 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 I0113 14:42:51.377912 18748 task_status_update_manager.cpp:188] Resuming sending task status updates I0113 14:42:51.377835 18738 hierarchical.cpp:959] Added agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 (c27cf6ba285d) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0113 14:42:51.378425 18742 slave.cpp:1679] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_I8cigJ/meta/slaves/06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0/slave.info' I0113 14:42:51.378487 18738 hierarchical.cpp:1853] Performed allocation for 1 agents in 204544ns I0113 14:42:51.378608 18736 status_update_manager_process.hpp:385] Resuming operation status update manager I0113 14:42:51.382953 18743 hierarchical.cpp:1853] Performed allocation for 1 agents in 241379ns I0113 14:42:51.386998 18742 slave.cpp:1731] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"LDMN64qXSoydzeIaYwiIdA=="},"slave_id":{"value":"06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0"},"update_oversubscribed_resources":false} I0113 14:42:51.388962 18742 master.cpp:8040] Ignoring update on agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 at slave(1253)@172.17.0.2:38425 (c27cf6ba285d) as it reports no changes I0113 14:42:51.395970 18741 process.cpp:3671] Handling HTTP event for process 'slave(1253)' with path: '/slave(1253)/api/v1' I0113 14:42:51.397748 18744 http.cpp:1405] HTTP POST for /slave(1253)/api/v1 from 172.17.0.2:48040 I0113 14:42:51.398488 18744 http.cpp:2146] Processing GET_CONTAINERS call I0113 14:42:51.409752 18738 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:51.418107 18739 process.cpp:3671] Handling HTTP event for process 'slave(1253)' with path: '/slave(1253)/api/v1' I0113 14:42:51.420250 18731 http.cpp:1405] HTTP POST for /slave(1253)/api/v1 from 172.17.0.2:48042 I0113 14:42:51.421885 18731 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' I0113 14:42:51.423945 18749 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_I8cigJ/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:51.425920 18749 containerizer.cpp:1398] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:51.427420 18749 containerizer.cpp:3322] 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 472064ns I0113 14:42:51.429091 18749 containerizer.cpp:1576] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_VjPCLN/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0113 14:42:51.429260 18749 containerizer.cpp:3322] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.74592ms I0113 14:42:51.435124 18748 containerizer.cpp:2102] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_PPzZKE","--available_capacity=0B","--volumes=","--forward=unix:///tmp/6sCJlA/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_I8cigJ/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-9QJ9Xa/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_I8cigJ/containers/org-apache-mesos-rp-local -storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="94" --pipe_write="95" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_VjPCLN/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0113 14:42:51.447937 18736 hierarchical.cpp:1853] Performed allocation for 1 agents in 313678ns I0113 14:42:51.449479 18748 launcher.cpp:145] Forked child with pid '33118' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:51.450887 18748 containerizer.cpp:3322] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 21.720832ms I0113 14:42:51.458063 18748 containerizer.cpp:3322] 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 7.14624ms I0113 14:42:51.458487 18743 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_I8cigJ/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:51.460095 18748 containerizer.cpp:3322] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 2.063872ms I0113 14:42:51.465284 18745 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' I0113 14:42:51.465636 18746 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-9QJ9Xa/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:51.506835 18744 hierarchical.cpp:1853] Performed allocation for 1 agents in 254824ns I0113 14:42:51.563304 18732 hierarchical.cpp:1853] Performed allocation for 1 agents in 263457ns I0113 14:42:51.615244 18735 hierarchical.cpp:1853] Performed allocation for 1 agents in 290618ns I0113 14:42:51.666703 18745 hierarchical.cpp:1853] Performed allocation for 1 agents in 247842ns I0113 14:42:51.719758 18733 hierarchical.cpp:1853] Performed allocation for 1 agents in 276191ns I0113 14:42:51.771785 18751 hierarchical.cpp:1853] Performed allocation for 1 agents in 241546ns I0113 14:42:51.830888 18748 hierarchical.cpp:1853] Performed allocation for 1 agents in 274101ns I0113 14:42:51.882508 18745 hierarchical.cpp:1853] Performed allocation for 1 agents in 274837ns I0113 14:42:51.935029 18731 hierarchical.cpp:1853] Performed allocation for 1 agents in 276279ns I0113 14:42:51.987540 18747 hierarchical.cpp:1853] Performed allocation for 1 agents in 259424ns I0113 14:42:52.038738 18735 hierarchical.cpp:1853] Performed allocation for 1 agents in 266124ns I0113 14:42:52.090991 18745 hierarchical.cpp:1853] Performed allocation for 1 agents in 259840ns I0113 14:42:52.107151 18739 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-9QJ9Xa/endpoint.sock' with CSI v1 I0113 14:42:52.115890 18733 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-9QJ9Xa/endpoint.sock' with CSI v0 I0113 14:42:52.119076 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/Probe call I0113 14:42:52.127532 18751 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:52.131412 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginCapabilities call I0113 14:42:52.138077 18736 process.cpp:3671] Handling HTTP event for process 'slave(1253)' with path: '/slave(1253)/api/v1' I0113 14:42:52.140209 18736 http.cpp:1405] HTTP POST for /slave(1253)/api/v1 from 172.17.0.2:48050 I0113 14:42:52.140940 18736 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' I0113 14:42:52.145391 18747 hierarchical.cpp:1853] Performed allocation for 1 agents in 297867ns I0113 14:42:52.152547 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0113 14:42:52.152904 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0113 14:42:52.161824 18734 v0_volume_manager.cpp:628] NODE_SERVICE loaded: {} I0113 14:42:52.164440 18735 v0_volume_manager.cpp:628] CONTROLLER_SERVICE loaded: {} I0113 14:42:52.170903 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ControllerGetCapabilities call I0113 14:42:52.195288 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetCapabilities call I0113 14:42:52.199335 18747 hierarchical.cpp:1853] Performed allocation for 1 agents in 380837ns I0113 14:42:52.205054 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetId call I0113 14:42:52.213567 18749 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0113 14:42:52.214108 18748 status_update_manager_process.hpp:379] Pausing operation status update manager I0113 14:42:52.214850 18749 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38425/slave(1253)/api/v1/resource_provider I0113 14:42:52.224906 18750 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38425/slave(1253)/api/v1/resource_provider I0113 14:42:52.225883 18736 provider.cpp:476] Connected to resource provider manager I0113 14:42:52.227247 18736 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38425/slave(1253)/api/v1/resource_provider I0113 14:42:52.230543 18740 process.cpp:3671] Handling HTTP event for process 'slave(1253)' with path: '/slave(1253)/api/v1/resource_provider' I0113 14:42:52.233350 18740 http.cpp:1405] HTTP POST for /slave(1253)/api/v1/resource_provider from 172.17.0.2:48054 I0113 14:42:52.234762 18740 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_PPzZKE","--available_capacity=0B","--volumes=","--forward=unix:///tmp/6sCJlA/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"} I0113 14:42:52.251087 18733 hierarchical.cpp:1853] Performed allocation for 1 agents in 267258ns I0113 14:42:52.273356 18745 slave.cpp:8649] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"2af3c38a-f58b-4d8e-9365-0d9d5f743071"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_PPzZKE","--available_capacity=0B","--volumes=","--forward=unix:///tmp/6sCJlA/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}' I0113 14:42:52.282369 18734 provider.cpp:498] Received SUBSCRIBED event I0113 14:42:52.282925 18734 provider.cpp:1309] Subscribed with ID 2af3c38a-f58b-4d8e-9365-0d9d5f743071 I0113 14:42:52.284572 18749 status_update_manager_process.hpp:314] Recovering operation status update manager I0113 14:42:52.303194 18740 hierarchical.cpp:1853] Performed allocation for 1 agents in 264444ns I0113 14:42:52.339458 18749 provider.cpp:790] Reconciling storage pools and volumes I0113 14:42:52.342929 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0113 14:42:52.347322 18753 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 I0113 14:42:52.348294 18735 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:38425/slave(1253)/api/v1/resource_provider I0113 14:42:52.348410 18753 provider.cpp:748] Resource provider 2af3c38a-f58b-4d8e-9365-0d9d5f743071 is in READY state I0113 14:42:52.348486 18737 status_update_manager_process.hpp:385] Resuming operation status update manager I0113 14:42:52.350607 18731 process.cpp:3671] Handling HTTP event for process 'slave(1253)' with path: '/slave(1253)/api/v1/resource_provider' I0113 14:42:52.352214 18736 provider.cpp:1235] Updating profiles { test } for resource provider 2af3c38a-f58b-4d8e-9365-0d9d5f743071 I0113 14:42:52.354157 18744 http.cpp:1405] HTTP POST for /slave(1253)/api/v1/resource_provider from 172.17.0.2:48052 I0113 14:42:52.354426 18732 provider.cpp:790] Reconciling storage pools and volumes I0113 14:42:52.355621 18739 hierarchical.cpp:1853] Performed allocation for 1 agents in 277035ns I0113 14:42:52.357650 18744 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 2af3c38a-f58b-4d8e-9365-0d9d5f743071 I0113 14:42:52.358613 18730 slave.cpp:8649] Handling resource provider message 'UPDATE_STATE: 2af3c38a-f58b-4d8e-9365-0d9d5f743071 {}' I0113 14:42:52.359105 18730 slave.cpp:8769] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0113 14:42:52.361613 18750 hierarchical.cpp:1110] Grew agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 by {} (total), { } (used) I0113 14:42:52.362095 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0113 14:42:52.362166 18750 hierarchical.cpp:1067] Agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 (c27cf6ba285d) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0113 14:42:52.362717 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0113 14:42:52.372797 18753 hierarchical.cpp:1853] Performed allocation for 1 agents in 274213ns I0113 14:42:52.377334 18743 provider.cpp:790] Reconciling storage pools and volumes I0113 14:42:52.384377 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0113 14:42:52.385061 33122 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0113 14:42:52.395401 18751 slave.cpp:992] Agent terminating I0113 14:42:52.398449 18751 manager.cpp:127] Terminating resource provider 2af3c38a-f58b-4d8e-9365-0d9d5f743071 I0113 14:42:52.399176 18751 master.cpp:1299] Agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 at slave(1253)@172.17.0.2:38425 (c27cf6ba285d) disconnected I0113 14:42:52.399227 18751 master.cpp:3368] Disconnecting agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 at slave(1253)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:52.399325 18751 master.cpp:3387] Deactivating agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 at slave(1253)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:52.399667 18751 hierarchical.cpp:1156] Agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 deactivated I0113 14:42:52.400485 18752 containerizer.cpp:2624] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0113 14:42:52.400590 18752 containerizer.cpp:3322] 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.940489984secs I0113 14:42:52.401188 18752 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE E0113 14:42:52.407397 18750 http_connection.hpp:449] End-Of-File received I0113 14:42:52.407975 18750 http_connection.hpp:217] Re-detecting endpoint I0113 14:42:52.409368 18750 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0113 14:42:52.409721 18750 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0113 14:42:52.410046 18750 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38425/slave(1253)/api/v1/resource_provider I0113 14:42:52.411722 18750 provider.cpp:488] Disconnected from resource provider manager I0113 14:42:52.412166 18750 status_update_manager_process.hpp:379] Pausing operation status update manager I0113 14:42:52.422261 18742 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38425/slave(1253)/api/v1/resource_provider I0113 14:42:52.435153 18742 provider.cpp:476] Connected to resource provider manager I0113 14:42:52.436408 18742 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38425/slave(1253)/api/v1/resource_provider I0113 14:42:52.437125 18740 hierarchical.cpp:1853] Performed allocation for 1 agents in 365740ns I0113 14:42:52.437837 18754 process.cpp:2781] Returning '404 Not Found' for '/slave(1253)/api/v1/resource_provider' E0113 14:42:52.448066 18752 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0113 14:42:52.471693 18749 containerizer.cpp:3160] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0113 14:42:52.474740 18741 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 I0113 14:42:52.489569 18743 hierarchical.cpp:1853] Performed allocation for 1 agents in 219450ns I0113 14:42:52.492197 18738 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' I0113 14:42:52.493140 18738 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-9QJ9Xa/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:52.493782 18738 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:52.511926 18754 process.cpp:2781] Returning '404 Not Found' for '/slave(1253)/api/v1' I0113 14:42:52.590833 18729 master.cpp:1140] Master terminating I0113 14:42:52.592082 18734 hierarchical.cpp:1132] Removed all filters for agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 I0113 14:42:52.592387 18734 hierarchical.cpp:1008] Removed agent 06aca33b-b2a8-4b6e-93e2-eb643eaacb75-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (1375 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 I0113 14:42:52.658872 18729 cluster.cpp:180] Creating default 'local' authorizer I0113 14:42:52.670215 18743 master.cpp:443] Master d304b033-27db-475a-ab80-832252f79070 (c27cf6ba285d) started on 172.17.0.2:38425 I0113 14:42:52.670954 18743 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/I2huqI/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/mesos/mesos-1.10.0/_inst/share/mesos/webui" --work_dir="/tmp/I2huqI/master" --zk_session_timeout="10secs" I0113 14:42:52.672039 18743 master.cpp:495] Master only allowing authenticated frameworks to register I0113 14:42:52.672474 18743 master.cpp:501] Master only allowing authenticated agents to register I0113 14:42:52.672885 18743 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0113 14:42:52.672981 18743 credentials.hpp:37] Loading credentials for authentication from '/tmp/I2huqI/credentials' I0113 14:42:52.673512 18743 master.cpp:551] Using default 'crammd5' authenticator I0113 14:42:52.674043 18743 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0113 14:42:52.674645 18743 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0113 14:42:52.675101 18743 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0113 14:42:52.675356 18743 master.cpp:632] Authorization enabled I0113 14:42:52.677011 18733 whitelist_watcher.cpp:77] No whitelist given I0113 14:42:52.677078 18736 hierarchical.cpp:567] Initialized hierarchical allocator process I0113 14:42:52.685433 18743 master.cpp:2172] Elected as the leading master! I0113 14:42:52.686103 18743 master.cpp:1668] Recovering from registrar I0113 14:42:52.686911 18753 registrar.cpp:339] Recovering registrar I0113 14:42:52.688393 18753 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0113 14:42:52.688954 18753 registrar.cpp:487] Applied 1 operations in 65071ns; attempting to update the registry I0113 14:42:52.690443 18753 registrar.cpp:544] Successfully updated the registry in 0ns I0113 14:42:52.691017 18753 registrar.cpp:416] Successfully recovered registrar I0113 14:42:52.692129 18743 master.cpp:1821] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0113 14:42:52.692673 18743 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover W0113 14:42:52.704015 18729 process.cpp:2877] Attempted to spawn already running process [email protected]:38425 I0113 14:42:52.707638 18729 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0113 14:42:52.708855 18729 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0113 14:42:52.709136 18729 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0113 14:42:52.709646 18729 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0113 14:42:52.709928 18729 provisioner.cpp:294] Using default backend 'copy' I0113 14:42:52.714345 18729 cluster.cpp:527] Creating default 'local' authorizer I0113 14:42:52.719143 18736 slave.cpp:273] Mesos agent started on (1254)@172.17.0.2:38425 I0113 14:42:52.719573 18736 slave.cpp:274] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/I2huqI/HbtvVb/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/I2huqI/HbtvVb/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/I2huqI/HbtvVb/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/I2huqI/HbtvVb/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/I2huqI/HbtvVb/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/I2huqI/HbtvVb/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="/mesos/mesos-1.10.0/_build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/I2huqI/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_UiWxl5" --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_StorageLocalResourcePro viderTest_Update_v1_4pqrFX" --zk_session_timeout="10secs" I0113 14:42:52.720789 18736 credentials.hpp:86] Loading credential for authentication from '/tmp/I2huqI/HbtvVb/credential' I0113 14:42:52.721334 18736 slave.cpp:306] Agent using credential for: test-principal I0113 14:42:52.721582 18736 credentials.hpp:37] Loading credentials for authentication from '/tmp/I2huqI/HbtvVb/http_credentials' I0113 14:42:52.722170 18736 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0113 14:42:52.723289 18736 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0113 14:42:52.725883 18736 slave.cpp:621] 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"}] I0113 14:42:52.726244 18736 slave.cpp:629] Agent attributes: [ ] I0113 14:42:52.726271 18736 slave.cpp:638] Agent hostname: c27cf6ba285d I0113 14:42:52.726523 18737 task_status_update_manager.cpp:181] Pausing sending task status updates I0113 14:42:52.726522 18747 status_update_manager_process.hpp:379] Pausing operation status update manager I0113 14:42:52.727138 18734 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0113 14:42:52.727257 18750 hierarchical.cpp:1853] Performed allocation for 0 agents in 172329ns I0113 14:42:52.730304 18736 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_4pqrFX/meta' I0113 14:42:52.731202 18736 slave.cpp:7658] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_4pqrFX/meta', beginning agent recovery I0113 14:42:52.732133 18745 task_status_update_manager.cpp:207] Recovering task status update manager I0113 14:42:52.733261 18751 containerizer.cpp:823] Recovering Mesos containers I0113 14:42:52.733961 18751 containerizer.cpp:1163] Recovering isolators I0113 14:42:52.735970 18746 containerizer.cpp:1202] Recovering provisioner I0113 14:42:52.737340 18746 provisioner.cpp:518] Provisioner recovery complete I0113 14:42:52.738792 18741 composing.cpp:343] Finished recovering all containerizers I0113 14:42:52.739537 18741 slave.cpp:8140] Recovering executors I0113 14:42:52.739686 18741 slave.cpp:8293] Finished recovery I0113 14:42:52.741192 18743 task_status_update_manager.cpp:181] Pausing sending task status updates I0113 14:42:52.741277 18743 status_update_manager_process.hpp:379] Pausing operation status update manager I0113 14:42:52.741500 18730 slave.cpp:1419] New master detected at [email protected]:38425 I0113 14:42:52.741755 18730 slave.cpp:1484] Detecting new master I0113 14:42:52.746053 18737 slave.cpp:1511] Authenticating with master [email protected]:38425 I0113 14:42:52.746291 18737 slave.cpp:1520] Using default CRAM-MD5 authenticatee I0113 14:42:52.747252 18737 authenticatee.cpp:121] Creating new client SASL connection I0113 14:42:52.747764 18737 master.cpp:10160] Authenticating slave(1254)@172.17.0.2:38425 I0113 14:42:52.748131 18737 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2118)@172.17.0.2:38425 I0113 14:42:52.748716 18737 authenticator.cpp:98] Creating new server SASL connection I0113 14:42:52.749085 18737 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0113 14:42:52.749181 18737 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0113 14:42:52.749341 18737 authenticator.cpp:204] Received SASL authentication start I0113 14:42:52.749428 18737 authenticator.cpp:326] Authentication requires more steps I0113 14:42:52.749572 18737 authenticatee.cpp:259] Received SASL authentication step I0113 14:42:52.749725 18737 authenticator.cpp:232] Received SASL authentication step I0113 14:42:52.749768 18737 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c27cf6ba285d' server FQDN: 'c27cf6ba285d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0113 14:42:52.749790 18737 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0113 14:42:52.749856 18737 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0113 14:42:52.749981 18737 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'c27cf6ba285d' server FQDN: 'c27cf6ba285d' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0113 14:42:52.750010 18737 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0113 14:42:52.750028 18737 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0113 14:42:52.750061 18737 authenticator.cpp:318] Authentication success I0113 14:42:52.750435 18737 authenticatee.cpp:299] Authentication success I0113 14:42:52.750798 18744 master.cpp:10192] Successfully authenticated principal 'test-principal' at slave(1254)@172.17.0.2:38425 I0113 14:42:52.750846 18737 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2118)@172.17.0.2:38425 I0113 14:42:52.751361 18744 slave.cpp:1611] Successfully authenticated with master [email protected]:38425 I0113 14:42:52.751938 18744 slave.cpp:2061] Will retry registration in 6.381132ms if necessary I0113 14:42:52.752413 18744 master.cpp:6630] Received register agent message from slave(1254)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:52.752923 18744 master.cpp:3713] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0113 14:42:52.754113 18753 master.cpp:6697] Authorized registration of agent at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:52.754560 18753 master.cpp:6809] Registering agent at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) with id d304b033-27db-475a-ab80-832252f79070-S0 I0113 14:42:52.755869 18753 registrar.cpp:487] Applied 1 operations in 424577ns; attempting to update the registry I0113 14:42:52.757498 18753 registrar.cpp:544] Successfully updated the registry in 1.291008ms I0113 14:42:52.758469 18753 master.cpp:6857] Admitted agent d304b033-27db-475a-ab80-832252f79070-S0 at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:52.760121 18735 slave.cpp:2061] Will retry registration in 32.066528ms if necessary I0113 14:42:52.760766 18735 slave.cpp:1644] Registered with master [email protected]:38425; given agent ID d304b033-27db-475a-ab80-832252f79070-S0 I0113 14:42:52.761023 18740 hierarchical.cpp:959] Added agent d304b033-27db-475a-ab80-832252f79070-S0 (c27cf6ba285d) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0113 14:42:52.760159 18753 master.cpp:6902] Registered agent d304b033-27db-475a-ab80-832252f79070-S0 at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0113 14:42:52.761466 18753 master.cpp:6630] Received register agent message from slave(1254)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:52.761744 18740 hierarchical.cpp:1853] Performed allocation for 1 agents in 359305ns I0113 14:42:52.761970 18740 task_status_update_manager.cpp:188] Resuming sending task status updates I0113 14:42:52.762053 18753 master.cpp:3713] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0113 14:42:52.763195 18737 master.cpp:6697] Authorized registration of agent at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:52.763474 18737 master.cpp:6788] Agent d304b033-27db-475a-ab80-832252f79070-S0 at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) already registered, resending acknowledgement I0113 14:42:52.763722 18735 slave.cpp:1679] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_4pqrFX/meta/slaves/d304b033-27db-475a-ab80-832252f79070-S0/slave.info' I0113 14:42:52.763797 18744 status_update_manager_process.hpp:385] Resuming operation status update manager I0113 14:42:52.766243 18735 slave.cpp:1731] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"wEQUYLpCRtetIKvSI4EH7w=="},"slave_id":{"value":"d304b033-27db-475a-ab80-832252f79070-S0"},"update_oversubscribed_resources":false} I0113 14:42:52.767549 18730 master.cpp:8040] Ignoring update on agent d304b033-27db-475a-ab80-832252f79070-S0 at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) as it reports no changes W0113 14:42:52.767763 18735 slave.cpp:1713] Already registered with master [email protected]:38425 I0113 14:42:52.767971 18735 slave.cpp:1731] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"wEQUYLpCRtetIKvSI4EH7w=="},"slave_id":{"value":"d304b033-27db-475a-ab80-832252f79070-S0"},"update_oversubscribed_resources":false} I0113 14:42:52.768878 18746 master.cpp:8040] Ignoring update on agent d304b033-27db-475a-ab80-832252f79070-S0 at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) as it reports no changes I0113 14:42:52.775416 18737 process.cpp:3671] Handling HTTP event for process 'slave(1254)' with path: '/slave(1254)/api/v1' I0113 14:42:52.778529 18730 hierarchical.cpp:1853] Performed allocation for 1 agents in 275752ns I0113 14:42:52.779848 18737 http.cpp:1405] HTTP POST for /slave(1254)/api/v1 from 172.17.0.2:48062 I0113 14:42:52.781015 18737 http.cpp:2146] Processing GET_CONTAINERS call I0113 14:42:52.792093 18747 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:52.800745 18742 process.cpp:3671] Handling HTTP event for process 'slave(1254)' with path: '/slave(1254)/api/v1' I0113 14:42:52.803377 18738 http.cpp:1405] HTTP POST for /slave(1254)/api/v1 from 172.17.0.2:48064 I0113 14:42:52.804888 18738 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' I0113 14:42:52.807065 18738 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_4pqrFX/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:52.808236 18746 containerizer.cpp:1398] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:52.809168 18746 containerizer.cpp:3322] 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 353024ns I0113 14:42:52.810369 18746 containerizer.cpp:1576] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_UiWxl5/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0113 14:42:52.810770 18746 containerizer.cpp:3322] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.604864ms I0113 14:42:52.816999 18750 containerizer.cpp:2102] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_7Y6mZP","--available_capacity=0B","--volumes=","--forward=unix:///tmp/I2huqI/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_4pqrFX/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-nrVqjH/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_4pqrFX/containers/org-apache-mesos-rp-local -storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="94" --pipe_write="95" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_UiWxl5/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0113 14:42:52.833920 18750 launcher.cpp:145] Forked child with pid '33131' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:52.835454 18732 hierarchical.cpp:1853] Performed allocation for 1 agents in 311048ns I0113 14:42:52.836273 18750 containerizer.cpp:3322] 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 25.50016ms I0113 14:42:52.839495 18750 containerizer.cpp:3322] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 2.882048ms I0113 14:42:52.840389 18750 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_4pqrFX/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:52.841956 18750 containerizer.cpp:3322] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 2.800896ms I0113 14:42:52.846179 18745 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' I0113 14:42:52.846411 18745 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-nrVqjH/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:52.887511 18742 hierarchical.cpp:1853] Performed allocation for 1 agents in 282960ns I0113 14:42:52.941581 18753 hierarchical.cpp:1853] Performed allocation for 1 agents in 269894ns I0113 14:42:52.992956 18731 hierarchical.cpp:1853] Performed allocation for 1 agents in 253982ns I0113 14:42:53.045382 18737 hierarchical.cpp:1853] Performed allocation for 1 agents in 285356ns I0113 14:42:53.098109 18736 hierarchical.cpp:1853] Performed allocation for 1 agents in 268297ns I0113 14:42:53.152884 18734 hierarchical.cpp:1853] Performed allocation for 1 agents in 246162ns I0113 14:42:53.205729 18731 hierarchical.cpp:1853] Performed allocation for 1 agents in 248759ns I0113 14:42:53.261921 18732 hierarchical.cpp:1853] Performed allocation for 1 agents in 3.907578ms I0113 14:42:53.314386 18749 hierarchical.cpp:1853] Performed allocation for 1 agents in 282952ns I0113 14:42:53.368366 18740 hierarchical.cpp:1853] Performed allocation for 1 agents in 286586ns I0113 14:42:53.420532 18733 hierarchical.cpp:1853] Performed allocation for 1 agents in 243266ns I0113 14:42:53.473583 18739 hierarchical.cpp:1853] Performed allocation for 1 agents in 251628ns I0113 14:42:53.514802 18749 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-nrVqjH/endpoint.sock' with CSI v1 I0113 14:42:53.529433 18736 hierarchical.cpp:1853] Performed allocation for 1 agents in 246192ns I0113 14:42:53.531514 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call I0113 14:42:53.550107 18746 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:53.555071 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call I0113 14:42:53.563411 18739 process.cpp:3671] Handling HTTP event for process 'slave(1254)' with path: '/slave(1254)/api/v1' I0113 14:42:53.565699 18742 http.cpp:1405] HTTP POST for /slave(1254)/api/v1 from 172.17.0.2:48074 I0113 14:42:53.567152 18742 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' I0113 14:42:53.570345 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0113 14:42:53.571106 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0113 14:42:53.576637 18745 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {} I0113 14:42:53.577150 18745 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {} I0113 14:42:53.581506 18753 hierarchical.cpp:1853] Performed allocation for 1 agents in 249865ns I0113 14:42:53.583001 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call I0113 14:42:53.591493 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call I0113 14:42:53.597582 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call I0113 14:42:53.601186 18740 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0113 14:42:53.601722 18740 status_update_manager_process.hpp:379] Pausing operation status update manager I0113 14:42:53.602059 18734 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38425/slave(1254)/api/v1/resource_provider I0113 14:42:53.608202 18732 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38425/slave(1254)/api/v1/resource_provider I0113 14:42:53.609179 18732 provider.cpp:476] Connected to resource provider manager I0113 14:42:53.610040 18749 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38425/slave(1254)/api/v1/resource_provider I0113 14:42:53.614382 18735 process.cpp:3671] Handling HTTP event for process 'slave(1254)' with path: '/slave(1254)/api/v1/resource_provider' I0113 14:42:53.618360 18735 http.cpp:1405] HTTP POST for /slave(1254)/api/v1/resource_provider from 172.17.0.2:48078 I0113 14:42:53.620195 18746 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_7Y6mZP","--available_capacity=0B","--volumes=","--forward=unix:///tmp/I2huqI/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"} I0113 14:42:53.634052 18730 hierarchical.cpp:1853] Performed allocation for 1 agents in 279234ns I0113 14:42:53.661465 18739 slave.cpp:8649] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"5945b303-1aeb-4bd5-adb8-129b25a7b384"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_7Y6mZP","--available_capacity=0B","--volumes=","--forward=unix:///tmp/I2huqI/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}' I0113 14:42:53.668753 18749 provider.cpp:498] Received SUBSCRIBED event I0113 14:42:53.668841 18749 provider.cpp:1309] Subscribed with ID 5945b303-1aeb-4bd5-adb8-129b25a7b384 I0113 14:42:53.670459 18749 status_update_manager_process.hpp:314] Recovering operation status update manager I0113 14:42:53.687217 18733 hierarchical.cpp:1853] Performed allocation for 1 agents in 282678ns I0113 14:42:53.727186 18742 provider.cpp:790] Reconciling storage pools and volumes I0113 14:42:53.730680 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0113 14:42:53.736024 18732 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent d304b033-27db-475a-ab80-832252f79070-S0 I0113 14:42:53.737198 18732 provider.cpp:748] Resource provider 5945b303-1aeb-4bd5-adb8-129b25a7b384 is in READY state I0113 14:42:53.737319 18749 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:38425/slave(1254)/api/v1/resource_provider I0113 14:42:53.738926 18751 provider.cpp:1235] Updating profiles { test } for resource provider 5945b303-1aeb-4bd5-adb8-129b25a7b384 I0113 14:42:53.737443 18731 status_update_manager_process.hpp:385] Resuming operation status update manager I0113 14:42:53.740752 18738 provider.cpp:790] Reconciling storage pools and volumes I0113 14:42:53.743726 18737 hierarchical.cpp:1853] Performed allocation for 1 agents in 233019ns I0113 14:42:53.744216 18743 process.cpp:3671] Handling HTTP event for process 'slave(1254)' with path: '/slave(1254)/api/v1/resource_provider' I0113 14:42:53.745936 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0113 14:42:53.747088 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0113 14:42:53.747850 18743 http.cpp:1405] HTTP POST for /slave(1254)/api/v1/resource_provider from 172.17.0.2:48076 I0113 14:42:53.748821 18747 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 5945b303-1aeb-4bd5-adb8-129b25a7b384 I0113 14:42:53.751243 18743 slave.cpp:8649] Handling resource provider message 'UPDATE_STATE: 5945b303-1aeb-4bd5-adb8-129b25a7b384 {}' I0113 14:42:53.751370 18743 slave.cpp:8769] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0113 14:42:53.753378 18743 hierarchical.cpp:1110] Grew agent d304b033-27db-475a-ab80-832252f79070-S0 by {} (total), { } (used) I0113 14:42:53.753820 18743 hierarchical.cpp:1067] Agent d304b033-27db-475a-ab80-832252f79070-S0 (c27cf6ba285d) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0113 14:42:53.768395 18747 hierarchical.cpp:1853] Performed allocation for 1 agents in 250677ns I0113 14:42:53.770217 18740 provider.cpp:790] Reconciling storage pools and volumes I0113 14:42:53.779047 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0113 14:42:53.779583 33135 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0113 14:42:53.789710 18753 slave.cpp:992] Agent terminating I0113 14:42:53.790668 18753 manager.cpp:127] Terminating resource provider 5945b303-1aeb-4bd5-adb8-129b25a7b384 I0113 14:42:53.791383 18753 master.cpp:1299] Agent d304b033-27db-475a-ab80-832252f79070-S0 at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) disconnected I0113 14:42:53.791433 18753 master.cpp:3368] Disconnecting agent d304b033-27db-475a-ab80-832252f79070-S0 at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:53.791533 18753 master.cpp:3387] Deactivating agent d304b033-27db-475a-ab80-832252f79070-S0 at slave(1254)@172.17.0.2:38425 (c27cf6ba285d) I0113 14:42:53.791797 18751 hierarchical.cpp:1156] Agent d304b033-27db-475a-ab80-832252f79070-S0 deactivated E0113 14:42:53.793084 18739 http_connection.hpp:449] End-Of-File received I0113 14:42:53.793817 18739 http_connection.hpp:217] Re-detecting endpoint I0113 14:42:53.795648 18739 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0113 14:42:53.796059 18730 provider.cpp:488] Disconnected from resource provider manager I0113 14:42:53.797628 18730 status_update_manager_process.hpp:379] Pausing operation status update manager I0113 14:42:53.797838 18739 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0113 14:42:53.798102 18739 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38425/slave(1254)/api/v1/resource_provider I0113 14:42:53.801748 18751 containerizer.cpp:2624] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0113 14:42:53.801828 18751 containerizer.cpp:3322] 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.95987712secs I0113 14:42:53.802803 18751 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:53.803695 18744 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38425/slave(1254)/api/v1/resource_provider I0113 14:42:53.803956 18734 hierarchical.cpp:1853] Performed allocation for 1 agents in 225593ns I0113 14:42:53.806648 18744 provider.cpp:476] Connected to resource provider manager I0113 14:42:53.807679 18744 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38425/slave(1254)/api/v1/resource_provider I0113 14:42:53.810262 18754 process.cpp:2781] Returning '404 Not Found' for '/slave(1254)/api/v1/resource_provider' E0113 14:42:53.814851 18752 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0113 14:42:53.853549 18745 containerizer.cpp:3160] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0113 14:42:53.856293 18747 hierarchical.cpp:1853] Performed allocation for 1 agents in 230919ns I0113 14:42:53.858067 18753 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 I0113 14:42:53.863559 18741 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' I0113 14:42:53.863797 18741 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-nrVqjH/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0113 14:42:53.864094 18741 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0113 14:42:53.880404 18754 process.cpp:2781] Returning '404 Not Found' for '/slave(1254)/api/v1' E0113 14:42:53.885957 18734 container_daemon.cpp:150] Failed to launch container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE': Failed to launch container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE': Unexpected response '404 Not Found' (404 Not Found.) E0113 14:42:53.886819 18734 service_manager.cpp:751] Container daemon for 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' failed: Failed to launch container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE': Unexpected response '404 Not Found' (404 Not Found.) I0113 14:42:54.006775 18750 master.cpp:1140] Master terminating I0113 14:42:54.007381 18733 hierarchical.cpp:1132] Removed all filters for agent d304b033-27db-475a-ab80-832252f79070-S0 I0113 14:42:54.008004 18733 hierarchical.cpp:1008] Removed agent d304b033-27db-475a-ab80-832252f79070-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1411 ms) [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (151103 ms total) [----------] Global test environment tear-down [==========] 2326 tests from 222 test cases ran. (1404245 ms total) [ PASSED ] 2325 tests. [ FAILED ] 1 test, listed below: [ FAILED ] bool/MasterTestPrePostReservationRefinement.StateEndpointPendingTasks/1, where GetParam() = false 1 FAILED TEST YOU HAVE 34 DISABLED TESTS I0113 14:42:54.278795 18754 process.cpp:935] Stopped the socket accept loop make[4]: *** [check-local] Error 1 make[4]: Leaving directory `/mesos/mesos-1.10.0/_build/src' make[3]: *** [check-am] Error 2 make[3]: Leaving directory `/mesos/mesos-1.10.0/_build/src' make[2]: *** [check] Error 2 make[2]: Leaving directory `/mesos/mesos-1.10.0/_build/src' make[1]: *** [check-recursive] Error 1 make[1]: Leaving directory `/mesos/mesos-1.10.0/_build' make: *** [distcheck] Error 1 + docker rmi --force mesos-1578919754-16107 Untagged: mesos-1578919754-16107:latest Deleted: sha256:ce2d82af5ce2d6d1b02202e98c013fa04251fe4fae95c4e32bdb8a718234340e Deleted: sha256:37c9041ba253b7a9a478e3b5b5a71fe2c554f3eadc9e5d2421f7658ff19c474c Deleted: sha256:4a0c23e448ae21ffde5ad997b5b1a33a29fd517a9a4ed84e323f3350b7764c46 Deleted: sha256:ef36d4dda50fc5dbfacfa6e737059422f3e2b608130489e97a14e1c662ef5327 Deleted: sha256:62a1150d14f2404fb9024f85a799442dc342783a8b520e30f9926bcf366ce860 Deleted: sha256:7babf36319d09ac7c619a2533c67a71ef8e8f6bd7a31c62b03104dd7ca5fbeab Deleted: sha256:b6ae37f1e2e2742972962acf3b2e6c243b56c47a13e09177e9433163d987223e Deleted: sha256:25c1a388205ad89bcf70980300c4467f35f1e70682dac9df2a565542a6810bdb Deleted: sha256:9ed7968dfc2b2f3db81e731e115093a65403d51cd959b6fd852c0f67754f41f6 Deleted: sha256:9f201c873f7944bc07d5eaffc441e286439a19609c7af2960d5f67f4b55a4670 Deleted: sha256:0aa1a830f1e15e8ab6d23f343f2d1de3b56a26e31083606fde8c4eba4ba03e24 Deleted: sha256:755e30ae670d8cd217f52dfc61eee0ee3030b3961268bc6c3d1f2f16fa59df62 Deleted: sha256:f2fd2823c6f1866bbd491c882a2fbbd4efedd2038ea4de9b1021f1e57317bb93 Deleted: sha256:7a2b0d763ced9504aea6d8c3317624fc12058b1e7d63705d325d6c1100b837c6 Deleted: sha256:51fb8069f4c964964a45e16a9c5a49d236802f1534dae158b6114db6e237ac77 Deleted: sha256:0a6f6deaf3294d985015c193091ba05b5125694bb25df43c25a57bdd3426f6a1 Deleted: sha256:7e4add352166f3b5a53bd401145c5bcf3c26ba70ca50d8c3cfa685c944f3e1cb Deleted: sha256:df1edcac54580c64c61509fe868d21caf09a8fdb38c2ebd038a93094a0929116 Deleted: sha256:140929ac7bd4eda62ac601de158ce1b397414a105ad36437187c75b9bafd2bdb Deleted: sha256:89d65d3ea38186ed2491b102e5690ad8554c6ce2b421bb039b567dde95456fda Deleted: sha256:9fe4925e33b0f5830e880dc61ecd59eb4228a2d5a5f6cbd390ca99436a183133 Deleted: sha256:69ccb037cc24ca435e609fe4f52cfe2fbe3958b1d4e557b63c48002ee9ab1324 Deleted: sha256:91c6acfc9ae5ca9919f9314226ccf91eb48e5f19d172d48b5d1b71409c68800d Deleted: sha256:c5e78e8ff67b83f25f9b5bb27bea9cf963fdbf7cd8456f9bb14e6a397816ff19 Deleted: sha256:ba6044c6a0b84535407c9f16c04de34d1728221283df92529e92e82292670074 Deleted: sha256:f615feab061061b0c9f9f7a53293badaf6134fd65dd06bde9f6b051bc2854dec Deleted: sha256:9b2d2cb9459a24af3f2b122073a1a5d23ca7d116543c0cf8e1d013f2c19cda87 Deleted: sha256:931b64af69b47941b600a5be94d88846cb47d3d1dbdf581b624f49e7c9bd7bd7 Deleted: sha256:8c0e3bd0967d8a572db934df08d2232d0356953a1f45e13662afec3a1610ff0a Deleted: sha256:7066c01e0172bb6e4f818b58498a9bede8d7e04bc637b87a65d5c575df0e9fa1 Deleted: sha256:8d98038d624d3128befdb0ec976cafcde396bcc7e4f58514f5ef8ab70899cff6 Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/6438/console - Mesos Reviewbot On Jan. 13, 2020, 8:06 a.m., Qian Zhang wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/71983/ > ----------------------------------------------------------- > > (Updated Jan. 13, 2020, 8:06 a.m.) > > > Review request for mesos, Andrei Budnik and Greg Mann. > > > Bugs: MESOS-10050 > https://issues.apache.org/jira/browse/MESOS-10050 > > > Repository: mesos > > > Description > ------- > > Added a test `CgroupsIsolatorTest.ROOT_CGROUPS_CFS_TaskGroupLimits`. > > > Diffs > ----- > > src/tests/containerizer/cgroups_isolator_tests.cpp > f72e6cdab417368e63349915114aeed586e0ef0e > > > Diff: https://reviews.apache.org/r/71983/diff/2/ > > > Testing > ------- > > sudo make check > > > Thanks, > > Qian Zhang > >
