----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/72158/#review219631 -----------------------------------------------------------
Bad patch! Reviews applied: [72157, 72158] Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:16.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/jenkins/buildbot.sh 2>&1 | tee build_72158"] Error: ...<truncated>... a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:51.424973 3159 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:37949/slave(1249)/api/v1/resource_provider I0221 23:51:51.426478 3156 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I0221 23:51:51.429411 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 939684ns I0221 23:51:51.430021 3149 master.cpp:9971] Sending offers [ 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O3 ] to framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 I0221 23:51:51.430589 3149 sched.cpp:934] Scheduler::resourceOffers took 79599ns I0221 23:51:51.434162 3155 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0221 23:51:51.436239 3150 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:60246 I0221 23:51:51.436519 3150 http.cpp:277] Processing call CREATE_VOLUMES I0221 23:51:51.437567 3150 master.cpp:3709] Authorizing principal 'test-principal' to perform action CREATE_VOLUME on object {"value":"storage/default-role","resource":{"provider_id":{"value":"99429829-722b-4712-a211-da0a0624fe50"},"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":"bbfc0265-dc67-4815-a55e-be0694d1c7be","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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9","profile":"test"}}}} I0221 23:51:51.439491 3149 sched.cpp:960] Rescinded offer 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O3 I0221 23:51:51.439585 3149 sched.cpp:971] Scheduler::offerRescinded took 27402ns I0221 23:51:51.440320 3149 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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9,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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9,test)]:2048, offered or allocated: {}) on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 from framework 36be3 a27-afa5-4f98-9c61-0c63f4b85cf7-0000 I0221 23:51:51.440671 3151 master.cpp:12269] Removing offer 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O3 I0221 23:51:51.442364 3149 hierarchical.cpp:1625] Framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 filtered agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 for 5secs I0221 23:51:51.444981 3155 master.cpp:12134] Sending operation '' (uuid: 845926d5-bc26-409f-80ee-32ecc58a885f) to agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 at slave(1249)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:51.445665 3157 slave.cpp:4434] Ignoring new checkpointed resources and operations identical to the current version I0221 23:51:51.448736 3163 provider.cpp:498] Received APPLY_OPERATION event I0221 23:51:51.448786 3163 provider.cpp:1351] Received CREATE operation '' (uuid: 845926d5-bc26-409f-80ee-32ecc58a885f) I0221 23:51:51.452041 3153 master.cpp:5955] Processing REVIVE call for framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 I0221 23:51:51.452469 3153 hierarchical.cpp:1721] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 I0221 23:51:51.453856 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.218036ms I0221 23:51:51.454344 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 184025ns I0221 23:51:51.454805 3159 master.cpp:9971] Sending offers [ 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O4 ] to framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 I0221 23:51:51.455550 3159 sched.cpp:934] Scheduler::resourceOffers took 117726ns I0221 23:51:51.469553 3151 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:60240 I0221 23:51:51.470393 3149 slave.cpp:8565] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 201522b2-32bd-4634-be33-f1b4ba1d5914) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0221 23:51:51.470607 3149 slave.cpp:9018] Updating the state of operation with no ID (uuid: 201522b2-32bd-4634-be33-f1b4ba1d5914) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0221 23:51:51.470669 3149 slave.cpp:8772] Forwarding status update of operation with no ID (operation_uuid: 201522b2-32bd-4634-be33-f1b4ba1d5914) for an operator API call I0221 23:51:51.470957 3155 master.cpp:11786] Updating the state of operation '' (uuid: 201522b2-32bd-4634-be33-f1b4ba1d5914) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0221 23:51:51.471491 3162 slave.cpp:4434] Ignoring new checkpointed resources and operations identical to the current version I0221 23:51:51.553851 3151 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 843cc855-2920-45ef-8ed0-95231f1491c1) for operation UUID 845926d5-bc26-409f-80ee-32ecc58a885f on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:51.553908 3151 status_update_manager_process.hpp:414] Creating operation status update stream 845926d5-bc26-409f-80ee-32ecc58a885f checkpoint=true I0221 23:51:51.553926 3163 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0221 23:51:51.554141 3151 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 843cc855-2920-45ef-8ed0-95231f1491c1) for operation UUID 845926d5-bc26-409f-80ee-32ecc58a885f on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:51.654080 3151 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 843cc855-2920-45ef-8ed0-95231f1491c1) for operation UUID 845926d5-bc26-409f-80ee-32ecc58a885f on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:51.654433 3151 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 559ebedc-ab77-4e08-b859-857fe87e9bb2) for stream 201522b2-32bd-4634-be33-f1b4ba1d5914 I0221 23:51:51.654511 3151 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 559ebedc-ab77-4e08-b859-857fe87e9bb2) for operation UUID 201522b2-32bd-4634-be33-f1b4ba1d5914 on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:51.654968 3160 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:37949/slave(1249)/api/v1/resource_provider I0221 23:51:51.655975 3155 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I0221 23:51:51.697439 3154 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:60240 I0221 23:51:51.698338 3152 slave.cpp:8565] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 845926d5-bc26-409f-80ee-32ecc58a885f) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0221 23:51:51.698537 3152 slave.cpp:9018] Updating the state of operation with no ID (uuid: 845926d5-bc26-409f-80ee-32ecc58a885f) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0221 23:51:51.698592 3152 slave.cpp:8772] Forwarding status update of operation with no ID (operation_uuid: 845926d5-bc26-409f-80ee-32ecc58a885f) for an operator API call I0221 23:51:51.699092 3163 master.cpp:11786] Updating the state of operation '' (uuid: 845926d5-bc26-409f-80ee-32ecc58a885f) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0221 23:51:51.699620 3162 slave.cpp:4434] Ignoring new checkpointed resources and operations identical to the current version I0221 23:51:51.701004 3148 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0221 23:51:51.704182 3151 status_update_manager_process.hpp:490] Cleaning up operation status update stream 201522b2-32bd-4634-be33-f1b4ba1d5914 I0221 23:51:51.704385 3151 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 843cc855-2920-45ef-8ed0-95231f1491c1) for stream 845926d5-bc26-409f-80ee-32ecc58a885f I0221 23:51:51.704459 3151 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 843cc855-2920-45ef-8ed0-95231f1491c1) for operation UUID 845926d5-bc26-409f-80ee-32ecc58a885f on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:51.781472 3151 status_update_manager_process.hpp:490] Cleaning up operation status update stream 845926d5-bc26-409f-80ee-32ecc58a885f I0221 23:51:51.839223 3163 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0221 23:51:51.841296 3157 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:60248 I0221 23:51:51.841572 3157 http.cpp:277] Processing call DESTROY_VOLUMES I0221 23:51:51.842630 3157 master.cpp:3709] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"99429829-722b-4712-a211-da0a0624fe50"},"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":"bbfc0265-dc67-4815-a55e-be0694d1c7be","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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9","profile":"test"}}}} I0221 23:51:51.844622 3151 sched.cpp:960] Rescinded offer 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O4 I0221 23:51:51.844696 3151 sched.cpp:971] Scheduler::offerRescinded took 21708ns I0221 23:51:51.845293 3148 master.cpp:12269] Removing offer 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O4 I0221 23:51:51.845261 3152 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9,test),bbfc0265-dc67-4815-a55e-be0694d1c7be: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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9,test),bbfc0265-dc67-4815-a55e-be0694d1c7be:volume]:2048, offered or allocated: {}) on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 from framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 I0221 23:51:51.847352 3152 hierarchical.cpp:1625] Framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 filtered agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 for 5secs I0221 23:51:51.850883 3162 master.cpp:12134] Sending operation '' (uuid: b83ffa0b-f56d-4859-8957-33f160af16e5) to agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 at slave(1249)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:51.851578 3159 slave.cpp:4434] Ignoring new checkpointed resources and operations identical to the current version I0221 23:51:51.855101 3163 provider.cpp:498] Received APPLY_OPERATION event I0221 23:51:51.855154 3163 provider.cpp:1351] Received DESTROY operation '' (uuid: b83ffa0b-f56d-4859-8957-33f160af16e5) I0221 23:51:51.860421 3161 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.644629ms I0221 23:51:51.861208 3162 master.cpp:9971] Sending offers [ 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O5 ] to framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 I0221 23:51:51.861920 3162 sched.cpp:934] Scheduler::resourceOffers took 104985ns I0221 23:51:51.971655 3155 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 57331896-2067-4e9e-a32e-f1bb0d111f19) for operation UUID b83ffa0b-f56d-4859-8957-33f160af16e5 on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:51.971712 3155 status_update_manager_process.hpp:414] Creating operation status update stream b83ffa0b-f56d-4859-8957-33f160af16e5 checkpoint=true I0221 23:51:51.971985 3155 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 57331896-2067-4e9e-a32e-f1bb0d111f19) for operation UUID b83ffa0b-f56d-4859-8957-33f160af16e5 on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:52.030284 3155 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 57331896-2067-4e9e-a32e-f1bb0d111f19) for operation UUID b83ffa0b-f56d-4859-8957-33f160af16e5 on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:52.031113 3157 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:37949/slave(1249)/api/v1/resource_provider I0221 23:51:52.032111 3154 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I0221 23:51:52.034919 3148 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0221 23:51:52.036716 3150 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:60250 I0221 23:51:52.036969 3150 http.cpp:277] Processing call UNRESERVE_RESOURCES I0221 23:51:52.037797 3150 master.cpp:3709] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"99429829-722b-4712-a211-da0a0624fe50"},"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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9","profile":"test"}}}} I0221 23:51:52.039613 3156 sched.cpp:960] Rescinded offer 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O5 I0221 23:51:52.039683 3156 sched.cpp:971] Scheduler::offerRescinded took 20720ns I0221 23:51:52.040210 3154 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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9,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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9,test)]:2048, offered or allocated: {}) on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 from framework 36be3 a27-afa5-4f98-9c61-0c63f4b85cf7-0000 I0221 23:51:52.040351 3157 master.cpp:12269] Removing offer 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O5 I0221 23:51:52.041904 3154 hierarchical.cpp:1625] Framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 filtered agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 for 5secs I0221 23:51:52.044522 3158 master.cpp:12134] Sending operation '' (uuid: cdd37217-2dbf-4e45-a81c-8cbe337762a8) to agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 at slave(1249)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:52.045141 3152 slave.cpp:4434] Ignoring new checkpointed resources and operations identical to the current version I0221 23:51:52.048238 3160 provider.cpp:498] Received APPLY_OPERATION event I0221 23:51:52.048285 3160 provider.cpp:1351] Received UNRESERVE operation '' (uuid: cdd37217-2dbf-4e45-a81c-8cbe337762a8) I0221 23:51:52.056567 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.707797ms I0221 23:51:52.057163 3148 master.cpp:9971] Sending offers [ 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O6 ] to framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 I0221 23:51:52.057719 3148 sched.cpp:934] Scheduler::resourceOffers took 78043ns I0221 23:51:52.073406 3155 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:60240 I0221 23:51:52.074347 3149 slave.cpp:8565] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: b83ffa0b-f56d-4859-8957-33f160af16e5) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0221 23:51:52.074580 3149 slave.cpp:9018] Updating the state of operation with no ID (uuid: b83ffa0b-f56d-4859-8957-33f160af16e5) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0221 23:51:52.074638 3149 slave.cpp:8772] Forwarding status update of operation with no ID (operation_uuid: b83ffa0b-f56d-4859-8957-33f160af16e5) for an operator API call I0221 23:51:52.075011 3163 master.cpp:11786] Updating the state of operation '' (uuid: b83ffa0b-f56d-4859-8957-33f160af16e5) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0221 23:51:52.075582 3153 slave.cpp:4434] Ignoring new checkpointed resources and operations identical to the current version I0221 23:51:52.187927 3155 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: d4dd06e7-7515-47cd-8b6b-aa3d0fc0c7c2) for operation UUID cdd37217-2dbf-4e45-a81c-8cbe337762a8 on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:52.187980 3155 status_update_manager_process.hpp:414] Creating operation status update stream cdd37217-2dbf-4e45-a81c-8cbe337762a8 checkpoint=true I0221 23:51:52.188028 3160 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0221 23:51:52.188197 3155 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: d4dd06e7-7515-47cd-8b6b-aa3d0fc0c7c2) for operation UUID cdd37217-2dbf-4e45-a81c-8cbe337762a8 on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:52.271499 3155 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: d4dd06e7-7515-47cd-8b6b-aa3d0fc0c7c2) for operation UUID cdd37217-2dbf-4e45-a81c-8cbe337762a8 on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:52.271792 3155 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 57331896-2067-4e9e-a32e-f1bb0d111f19) for stream b83ffa0b-f56d-4859-8957-33f160af16e5 I0221 23:51:52.271870 3155 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 57331896-2067-4e9e-a32e-f1bb0d111f19) for operation UUID b83ffa0b-f56d-4859-8957-33f160af16e5 on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:52.272190 3149 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:37949/slave(1249)/api/v1/resource_provider I0221 23:51:52.273149 3154 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I0221 23:51:52.317348 3162 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:60240 I0221 23:51:52.318444 3159 slave.cpp:8565] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: cdd37217-2dbf-4e45-a81c-8cbe337762a8) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0221 23:51:52.318595 3159 slave.cpp:9018] Updating the state of operation with no ID (uuid: cdd37217-2dbf-4e45-a81c-8cbe337762a8) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0221 23:51:52.318639 3159 slave.cpp:8772] Forwarding status update of operation with no ID (operation_uuid: cdd37217-2dbf-4e45-a81c-8cbe337762a8) for an operator API call I0221 23:51:52.318966 3160 master.cpp:11786] Updating the state of operation '' (uuid: cdd37217-2dbf-4e45-a81c-8cbe337762a8) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0221 23:51:52.319430 3149 slave.cpp:4434] Ignoring new checkpointed resources and operations identical to the current version I0221 23:51:52.320899 3162 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0221 23:51:52.355093 3155 status_update_manager_process.hpp:490] Cleaning up operation status update stream b83ffa0b-f56d-4859-8957-33f160af16e5 I0221 23:51:52.355273 3155 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: d4dd06e7-7515-47cd-8b6b-aa3d0fc0c7c2) for stream cdd37217-2dbf-4e45-a81c-8cbe337762a8 I0221 23:51:52.355334 3155 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: d4dd06e7-7515-47cd-8b6b-aa3d0fc0c7c2) for operation UUID cdd37217-2dbf-4e45-a81c-8cbe337762a8 on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:52.439095 3155 status_update_manager_process.hpp:490] Cleaning up operation status update stream cdd37217-2dbf-4e45-a81c-8cbe337762a8 I0221 23:51:52.490456 3149 master.cpp:1415] Framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 disconnected I0221 23:51:52.490496 3149 master.cpp:3330] Deactivating framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 I0221 23:51:52.490819 3154 hierarchical.cpp:813] Deactivated framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 I0221 23:51:52.491161 3151 slave.cpp:995] Agent terminating I0221 23:51:52.491379 3149 master.cpp:12269] Removing offer 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-O6 I0221 23:51:52.491464 3149 master.cpp:3311] Disconnecting framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 I0221 23:51:52.491531 3149 master.cpp:1430] Giving framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 0ns to failover I0221 23:51:52.491508 3154 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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9,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_I7hhnf/2GB-28df2654-28e4-4832-a135-2712ae00b0d9,test)]:2048, offered or allocated: {}) on agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 from framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 I0221 23:51:52.492214 3151 manager.cpp:127] Terminating resource provider 99429829-722b-4712-a211-da0a0624fe50 I0221 23:51:52.492839 3161 master.cpp:9757] Framework failover timeout, removing framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 I0221 23:51:52.492889 3161 master.cpp:10759] Removing framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 (default) at [email protected]:37949 E0221 23:51:52.493253 3160 http_connection.hpp:449] End-Of-File received I0221 23:51:52.493315 3154 hierarchical.cpp:1777] Allocation paused I0221 23:51:52.493414 3161 master.cpp:1300] Agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 at slave(1249)@172.17.0.2:37949 (34e3cb60962b) disconnected I0221 23:51:52.493441 3161 master.cpp:3365] Disconnecting agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 at slave(1249)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:52.493535 3161 master.cpp:3384] Deactivating agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 at slave(1249)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:52.493769 3160 http_connection.hpp:217] Re-detecting endpoint I0221 23:51:52.493767 3154 hierarchical.cpp:757] Removed framework 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-0000 I0221 23:51:52.493845 3154 hierarchical.cpp:1787] Allocation resumed I0221 23:51:52.493912 3154 hierarchical.cpp:1156] Agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 deactivated I0221 23:51:52.494208 3160 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0221 23:51:52.494256 3160 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0221 23:51:52.494309 3160 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:37949/slave(1249)/api/v1/resource_provider I0221 23:51:52.494338 3148 provider.cpp:488] Disconnected from resource provider manager I0221 23:51:52.494479 3152 status_update_manager_process.hpp:379] Pausing operation status update manager I0221 23:51:52.495503 3157 containerizer.cpp:2619] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0221 23:51:52.495555 3157 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 2.597165952secs I0221 23:51:52.496026 3157 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:52.497133 3158 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:37949/slave(1249)/api/v1/resource_provider I0221 23:51:52.497958 3156 provider.cpp:476] Connected to resource provider manager I0221 23:51:52.498518 3160 hierarchical.cpp:1853] Performed allocation for 1 agents in 199253ns I0221 23:51:52.498636 3154 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:37949/slave(1249)/api/v1/resource_provider E0221 23:51:52.499416 3154 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Cannot process 'SUBSCRIBE' call as the driver is in state SUBSCRIBING I0221 23:51:52.499644 3164 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1/resource_provider' E0221 23:51:52.500933 3148 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0221 23:51:52.549930 3150 hierarchical.cpp:1853] Performed allocation for 1 agents in 140189ns I0221 23:51:52.599918 3155 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0221 23:51:52.601173 3155 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 I0221 23:51:52.601658 3157 hierarchical.cpp:1853] Performed allocation for 1 agents in 132322ns I0221 23:51:52.603595 3154 container_daemon.cpp:189] Invoking post-stop hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:52.603888 3163 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-OFgT1f/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:52.604120 3155 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:52.606756 3164 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1' I0221 23:51:52.619134 3147 master.cpp:1140] Master terminating I0221 23:51:52.620014 3160 hierarchical.cpp:1132] Removed all filters for agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 I0221 23:51:52.620048 3160 hierarchical.cpp:1008] Removed agent 36be3a27-afa5-4f98-9c61-0c63f4b85cf7-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2481 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 I0221 23:51:52.636538 3147 cluster.cpp:186] Creating default 'local' authorizer I0221 23:51:52.641104 3160 master.cpp:443] Master 994aab90-ae26-41a2-9582-f5c4cfbcaf16 (34e3cb60962b) started on 172.17.0.2:37949 I0221 23:51:52.641134 3160 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/5984rp/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.10.0/_inst/share/mesos/webui" --work_dir="/tmp/5984rp/master" --zk_session_timeout="10secs" I0221 23:51:52.641424 3160 master.cpp:495] Master only allowing authenticated frameworks to register I0221 23:51:52.641438 3160 master.cpp:501] Master only allowing authenticated agents to register I0221 23:51:52.641445 3160 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0221 23:51:52.641453 3160 credentials.hpp:37] Loading credentials for authentication from '/tmp/5984rp/credentials' I0221 23:51:52.641693 3160 master.cpp:551] Using default 'crammd5' authenticator I0221 23:51:52.641883 3160 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0221 23:51:52.642118 3160 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0221 23:51:52.642323 3160 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0221 23:51:52.642516 3160 master.cpp:632] Authorization enabled I0221 23:51:52.642886 3156 hierarchical.cpp:567] Initialized hierarchical allocator process I0221 23:51:52.642894 3155 whitelist_watcher.cpp:77] No whitelist given I0221 23:51:52.645645 3148 master.cpp:2173] Elected as the leading master! I0221 23:51:52.645682 3148 master.cpp:1669] Recovering from registrar I0221 23:51:52.645911 3158 registrar.cpp:339] Recovering registrar I0221 23:51:52.646592 3158 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0221 23:51:52.646711 3158 registrar.cpp:487] Applied 1 operations in 34998ns; attempting to update the registry I0221 23:51:52.647341 3158 registrar.cpp:544] Successfully updated the registry in 0ns I0221 23:51:52.647470 3158 registrar.cpp:416] Successfully recovered registrar I0221 23:51:52.647925 3156 master.cpp:1822] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0221 23:51:52.648028 3159 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover W0221 23:51:52.653525 3147 process.cpp:2877] Attempted to spawn already running process [email protected]:37949 I0221 23:51:52.654923 3147 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0221 23:51:52.655455 3147 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0221 23:51:52.655483 3147 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0221 23:51:52.655496 3147 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0221 23:51:52.655525 3147 provisioner.cpp:294] Using default backend 'copy' I0221 23:51:52.658020 3147 cluster.cpp:533] Creating default 'local' authorizer I0221 23:51:52.660339 3154 slave.cpp:274] Mesos agent started on (1250)@172.17.0.2:37949 I0221 23:51:52.660370 3154 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/5984rp/XIxAyP/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/5984rp/XIxAyP/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/5984rp/XIxAyP/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/5984rp/XIxAyP/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/5984rp/XIxAyP/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/5984rp/XIxAyP/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posi x" --launcher_dir="/tmp/SRC/build/mesos-1.10.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/5984rp/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_09Ub1I" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLoca lResourceProviderTest_Update_v0_Px0NtC" --zk_session_timeout="10secs" I0221 23:51:52.660818 3154 credentials.hpp:86] Loading credential for authentication from '/tmp/5984rp/XIxAyP/credential' I0221 23:51:52.661013 3154 slave.cpp:307] Agent using credential for: test-principal I0221 23:51:52.661049 3154 credentials.hpp:37] Loading credentials for authentication from '/tmp/5984rp/XIxAyP/http_credentials' I0221 23:51:52.661310 3154 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0221 23:51:52.661756 3154 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0221 23:51:52.664041 3160 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0221 23:51:52.664240 3154 slave.cpp:622] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] I0221 23:51:52.664530 3154 slave.cpp:630] Agent attributes: [ ] I0221 23:51:52.664549 3154 slave.cpp:639] Agent hostname: 34e3cb60962b I0221 23:51:52.664783 3157 status_update_manager_process.hpp:379] Pausing operation status update manager I0221 23:51:52.664791 3163 task_status_update_manager.cpp:181] Pausing sending task status updates I0221 23:51:52.666486 3150 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Px0NtC/meta' I0221 23:51:52.666798 3153 slave.cpp:7574] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Px0NtC/meta', beginning agent recovery I0221 23:51:52.667580 3151 task_status_update_manager.cpp:207] Recovering task status update manager I0221 23:51:52.668093 3155 containerizer.cpp:820] Recovering Mesos containers I0221 23:51:52.668488 3155 containerizer.cpp:1160] Recovering isolators I0221 23:51:52.669466 3161 containerizer.cpp:1199] Recovering provisioner I0221 23:51:52.670351 3149 provisioner.cpp:518] Provisioner recovery complete I0221 23:51:52.671183 3152 composing.cpp:339] Finished recovering all containerizers I0221 23:51:52.671540 3163 slave.cpp:8056] Recovering executors I0221 23:51:52.671679 3163 slave.cpp:8209] Finished recovery I0221 23:51:52.672641 3155 task_status_update_manager.cpp:181] Pausing sending task status updates I0221 23:51:52.672658 3151 hierarchical.cpp:1853] Performed allocation for 0 agents in 103718ns I0221 23:51:52.672674 3149 status_update_manager_process.hpp:379] Pausing operation status update manager I0221 23:51:52.672675 3163 slave.cpp:1422] New master detected at [email protected]:37949 I0221 23:51:52.672838 3163 slave.cpp:1487] Detecting new master I0221 23:51:52.677346 3157 slave.cpp:1514] Authenticating with master [email protected]:37949 I0221 23:51:52.677453 3157 slave.cpp:1523] Using default CRAM-MD5 authenticatee I0221 23:51:52.677772 3160 authenticatee.cpp:121] Creating new client SASL connection I0221 23:51:52.678117 3156 master.cpp:10156] Authenticating slave(1250)@172.17.0.2:37949 I0221 23:51:52.678311 3148 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2110)@172.17.0.2:37949 I0221 23:51:52.678673 3152 authenticator.cpp:98] Creating new server SASL connection I0221 23:51:52.678946 3162 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0221 23:51:52.678992 3162 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0221 23:51:52.679109 3162 authenticator.cpp:204] Received SASL authentication start I0221 23:51:52.679172 3162 authenticator.cpp:326] Authentication requires more steps I0221 23:51:52.679282 3162 authenticatee.cpp:259] Received SASL authentication step I0221 23:51:52.679414 3162 authenticator.cpp:232] Received SASL authentication step I0221 23:51:52.679450 3162 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '34e3cb60962b' server FQDN: '34e3cb60962b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0221 23:51:52.679464 3162 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0221 23:51:52.679519 3162 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0221 23:51:52.679551 3162 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '34e3cb60962b' server FQDN: '34e3cb60962b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0221 23:51:52.679569 3162 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0221 23:51:52.679579 3162 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0221 23:51:52.679600 3162 authenticator.cpp:318] Authentication success I0221 23:51:52.679733 3158 authenticatee.cpp:299] Authentication success I0221 23:51:52.679782 3155 master.cpp:10188] Successfully authenticated principal 'test-principal' at slave(1250)@172.17.0.2:37949 I0221 23:51:52.679829 3149 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2110)@172.17.0.2:37949 I0221 23:51:52.680198 3163 slave.cpp:1614] Successfully authenticated with master [email protected]:37949 I0221 23:51:52.680606 3163 slave.cpp:2064] Will retry registration in 12.702011ms if necessary I0221 23:51:52.680764 3160 master.cpp:6626] Received register agent message from slave(1250)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:52.681143 3160 master.cpp:3709] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0221 23:51:52.681820 3153 master.cpp:6693] Authorized registration of agent at slave(1250)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:52.681946 3153 master.cpp:6805] Registering agent at slave(1250)@172.17.0.2:37949 (34e3cb60962b) with id 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 I0221 23:51:52.682773 3150 registrar.cpp:487] Applied 1 operations in 255372ns; attempting to update the registry I0221 23:51:52.683423 3150 registrar.cpp:544] Successfully updated the registry in 583936ns I0221 23:51:52.683598 3159 master.cpp:6853] Admitted agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 at slave(1250)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:52.684381 3159 master.cpp:6898] Registered agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 at slave(1250)@172.17.0.2:37949 (34e3cb60962b) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0221 23:51:52.684474 3149 slave.cpp:1647] Registered with master [email protected]:37949; given agent ID 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 I0221 23:51:52.684619 3158 hierarchical.cpp:959] Added agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 (34e3cb60962b) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0221 23:51:52.684681 3148 task_status_update_manager.cpp:188] Resuming sending task status updates I0221 23:51:52.685041 3149 slave.cpp:1682] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Px0NtC/meta/slaves/994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0/slave.info' I0221 23:51:52.685053 3158 hierarchical.cpp:1853] Performed allocation for 1 agents in 179709ns I0221 23:51:52.685111 3160 status_update_manager_process.hpp:385] Resuming operation status update manager I0221 23:51:52.686442 3149 slave.cpp:1734] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"UOlsAq8cTZK+1akGYSkcpQ=="},"slave_id":{"value":"994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0"},"update_oversubscribed_resources":false} I0221 23:51:52.687364 3155 master.cpp:8036] Ignoring update on agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 at slave(1250)@172.17.0.2:37949 (34e3cb60962b) as it reports no changes I0221 23:51:52.690975 3158 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1' I0221 23:51:52.692160 3155 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:60258 I0221 23:51:52.692663 3155 http.cpp:2146] Processing GET_CONTAINERS call I0221 23:51:52.719532 3155 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:52.721917 3160 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1' I0221 23:51:52.722985 3161 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:60260 I0221 23:51:52.723743 3161 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' I0221 23:51:52.723958 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 263672ns I0221 23:51:52.724768 3149 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Px0NtC/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:52.725630 3155 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:52.726315 3155 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 273920ns I0221 23:51:52.727217 3155 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_09Ub1I/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0221 23:51:52.727294 3155 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 973056ns I0221 23:51:52.758338 3153 containerizer.cpp:2099] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_SykrWv","--available_capacity=0B","--volumes=","--forward=unix:///tmp/5984rp/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Px0NtC/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-LJVU9f/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Px0NtC/containers/o rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="110" --pipe_write="111" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_09Ub1I/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0221 23:51:52.769338 3153 launcher.cpp:145] Forked child with pid '14712' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:52.770347 3153 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 43.046912ms I0221 23:51:52.772001 3153 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 1.639168ms I0221 23:51:52.772390 3155 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Px0NtC/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:52.773561 3157 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 1.435904ms I0221 23:51:52.775679 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 298811ns I0221 23:51:52.776657 3159 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' I0221 23:51:52.777006 3162 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-LJVU9f/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:52.827417 3152 hierarchical.cpp:1853] Performed allocation for 1 agents in 105913ns I0221 23:51:52.878860 3154 hierarchical.cpp:1853] Performed allocation for 1 agents in 134135ns I0221 23:51:52.930522 3152 hierarchical.cpp:1853] Performed allocation for 1 agents in 138022ns I0221 23:51:52.982127 3156 hierarchical.cpp:1853] Performed allocation for 1 agents in 159869ns I0221 23:51:53.032940 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 179298ns I0221 23:51:53.084269 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 171163ns I0221 23:51:53.109037 3149 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-LJVU9f/endpoint.sock' with CSI v1 I0221 23:51:53.111858 3148 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-LJVU9f/endpoint.sock' with CSI v0 I0221 23:51:53.113229 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/Probe call I0221 23:51:53.116317 3160 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:53.119138 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginCapabilities call I0221 23:51:53.119515 3149 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1' I0221 23:51:53.120887 3152 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:60262 I0221 23:51:53.121450 3152 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' I0221 23:51:53.123270 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0221 23:51:53.123572 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0221 23:51:53.125825 3153 v0_volume_manager.cpp:628] NODE_SERVICE loaded: {} I0221 23:51:53.126520 3153 v0_volume_manager.cpp:628] CONTROLLER_SERVICE loaded: {} I0221 23:51:53.128597 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ControllerGetCapabilities call I0221 23:51:53.132222 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetCapabilities call I0221 23:51:53.135562 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetId call I0221 23:51:53.135761 3157 hierarchical.cpp:1853] Performed allocation for 1 agents in 195801ns I0221 23:51:53.138001 3158 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0221 23:51:53.138139 3163 status_update_manager_process.hpp:379] Pausing operation status update manager I0221 23:51:53.138566 3152 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:37949/slave(1250)/api/v1/resource_provider I0221 23:51:53.141943 3155 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:37949/slave(1250)/api/v1/resource_provider I0221 23:51:53.142563 3153 provider.cpp:476] Connected to resource provider manager I0221 23:51:53.143258 3163 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:37949/slave(1250)/api/v1/resource_provider I0221 23:51:53.144598 3156 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider' I0221 23:51:53.146466 3148 http.cpp:1405] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:60266 I0221 23:51:53.147171 3148 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_SykrWv","--available_capacity=0B","--volumes=","--forward=unix:///tmp/5984rp/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"} I0221 23:51:53.183713 3156 slave.cpp:8565] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"cec2d6bb-bccb-40a9-9d45-96f77007dc9d"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_SykrWv","--available_capacity=0B","--volumes=","--forward=unix:///tmp/5984rp/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}' I0221 23:51:53.185295 3157 provider.cpp:498] Received SUBSCRIBED event I0221 23:51:53.185339 3157 provider.cpp:1309] Subscribed with ID cec2d6bb-bccb-40a9-9d45-96f77007dc9d I0221 23:51:53.186111 3163 status_update_manager_process.hpp:314] Recovering operation status update manager I0221 23:51:53.187307 3158 hierarchical.cpp:1853] Performed allocation for 1 agents in 159080ns I0221 23:51:53.236481 3153 provider.cpp:790] Reconciling storage pools and volumes I0221 23:51:53.237829 3161 hierarchical.cpp:1853] Performed allocation for 1 agents in 113858ns I0221 23:51:53.238606 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0221 23:51:53.241288 3149 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 I0221 23:51:53.241583 3153 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:37949/slave(1250)/api/v1/resource_provider I0221 23:51:53.241695 3149 provider.cpp:748] Resource provider cec2d6bb-bccb-40a9-9d45-96f77007dc9d is in READY state I0221 23:51:53.241792 3156 status_update_manager_process.hpp:385] Resuming operation status update manager I0221 23:51:53.242547 3150 provider.cpp:1235] Updating profiles { test } for resource provider cec2d6bb-bccb-40a9-9d45-96f77007dc9d I0221 23:51:53.242813 3158 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider' I0221 23:51:53.243793 3153 provider.cpp:790] Reconciling storage pools and volumes I0221 23:51:53.244557 3155 http.cpp:1405] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:60264 I0221 23:51:53.245086 3154 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider cec2d6bb-bccb-40a9-9d45-96f77007dc9d I0221 23:51:53.245308 3158 slave.cpp:8565] Handling resource provider message 'UPDATE_STATE: cec2d6bb-bccb-40a9-9d45-96f77007dc9d {}' I0221 23:51:53.245383 3158 slave.cpp:8685] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0221 23:51:53.245836 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0221 23:51:53.246163 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0221 23:51:53.246913 3153 hierarchical.cpp:1110] Grew agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 by {} (total), { } (used) I0221 23:51:53.247277 3153 hierarchical.cpp:1067] Agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 (34e3cb60962b) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0221 23:51:53.255745 3148 hierarchical.cpp:1853] Performed allocation for 1 agents in 153845ns I0221 23:51:53.256423 3158 provider.cpp:790] Reconciling storage pools and volumes I0221 23:51:53.258603 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0221 23:51:53.259061 14716 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0221 23:51:53.269412 3161 slave.cpp:995] Agent terminating I0221 23:51:53.270277 3161 manager.cpp:127] Terminating resource provider cec2d6bb-bccb-40a9-9d45-96f77007dc9d I0221 23:51:53.270730 3150 master.cpp:1300] Agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 at slave(1250)@172.17.0.2:37949 (34e3cb60962b) disconnected I0221 23:51:53.270768 3150 master.cpp:3365] Disconnecting agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 at slave(1250)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:53.270850 3150 master.cpp:3384] Deactivating agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 at slave(1250)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:53.270974 3159 hierarchical.cpp:1156] Agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 deactivated E0221 23:51:53.271544 3156 http_connection.hpp:449] End-Of-File received I0221 23:51:53.272132 3156 http_connection.hpp:217] Re-detecting endpoint I0221 23:51:53.272593 3156 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0221 23:51:53.272678 3156 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0221 23:51:53.272709 3161 provider.cpp:488] Disconnected from resource provider manager I0221 23:51:53.272778 3156 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:37949/slave(1250)/api/v1/resource_provider I0221 23:51:53.272915 3151 status_update_manager_process.hpp:379] Pausing operation status update manager I0221 23:51:53.274214 3160 containerizer.cpp:2619] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0221 23:51:53.274277 3160 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.500868864secs I0221 23:51:53.274693 3160 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:53.276002 3153 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:37949/slave(1250)/api/v1/resource_provider I0221 23:51:53.276662 3163 provider.cpp:476] Connected to resource provider manager I0221 23:51:53.277472 3154 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:37949/slave(1250)/api/v1/resource_provider I0221 23:51:53.278479 3164 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1/resource_provider' E0221 23:51:53.279932 3152 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0221 23:51:53.299501 3149 hierarchical.cpp:1853] Performed allocation for 1 agents in 176499ns I0221 23:51:53.348482 3153 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0221 23:51:53.350039 3153 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 I0221 23:51:53.351137 3160 hierarchical.cpp:1853] Performed allocation for 1 agents in 126846ns I0221 23:51:53.352741 3155 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' I0221 23:51:53.352983 3155 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-LJVU9f/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:53.353231 3155 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:53.355952 3164 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1' I0221 23:51:53.368629 3147 master.cpp:1140] Master terminating I0221 23:51:53.368983 3162 hierarchical.cpp:1132] Removed all filters for agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 I0221 23:51:53.369007 3162 hierarchical.cpp:1008] Removed agent 994aab90-ae26-41a2-9582-f5c4cfbcaf16-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (745 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 I0221 23:51:53.383213 3147 cluster.cpp:186] Creating default 'local' authorizer I0221 23:51:53.387663 3158 master.cpp:443] Master c9e4bbdf-5fcc-45ba-838a-a88216bc96c3 (34e3cb60962b) started on 172.17.0.2:37949 I0221 23:51:53.387696 3158 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/p35oCX/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.10.0/_inst/share/mesos/webui" --work_dir="/tmp/p35oCX/master" --zk_session_timeout="10secs" I0221 23:51:53.388196 3158 master.cpp:495] Master only allowing authenticated frameworks to register I0221 23:51:53.388212 3158 master.cpp:501] Master only allowing authenticated agents to register I0221 23:51:53.388223 3158 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0221 23:51:53.388236 3158 credentials.hpp:37] Loading credentials for authentication from '/tmp/p35oCX/credentials' I0221 23:51:53.388533 3158 master.cpp:551] Using default 'crammd5' authenticator I0221 23:51:53.388770 3158 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0221 23:51:53.388996 3158 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0221 23:51:53.389199 3158 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0221 23:51:53.389403 3158 master.cpp:632] Authorization enabled I0221 23:51:53.389768 3159 hierarchical.cpp:567] Initialized hierarchical allocator process I0221 23:51:53.389844 3152 whitelist_watcher.cpp:77] No whitelist given I0221 23:51:53.394012 3154 master.cpp:2173] Elected as the leading master! I0221 23:51:53.394042 3154 master.cpp:1669] Recovering from registrar I0221 23:51:53.394245 3151 registrar.cpp:339] Recovering registrar I0221 23:51:53.394922 3151 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0221 23:51:53.395040 3151 registrar.cpp:487] Applied 1 operations in 35442ns; attempting to update the registry I0221 23:51:53.395658 3151 registrar.cpp:544] Successfully updated the registry in 0ns I0221 23:51:53.395794 3151 registrar.cpp:416] Successfully recovered registrar I0221 23:51:53.396211 3153 master.cpp:1822] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0221 23:51:53.396275 3160 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover W0221 23:51:53.401687 3147 process.cpp:2877] Attempted to spawn already running process [email protected]:37949 I0221 23:51:53.403064 3147 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0221 23:51:53.403615 3147 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0221 23:51:53.403643 3147 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0221 23:51:53.403659 3147 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0221 23:51:53.403703 3147 provisioner.cpp:294] Using default backend 'copy' I0221 23:51:53.406774 3147 cluster.cpp:533] Creating default 'local' authorizer I0221 23:51:53.409082 3156 slave.cpp:274] Mesos agent started on (1251)@172.17.0.2:37949 I0221 23:51:53.409109 3156 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/p35oCX/DimTyv/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/p35oCX/DimTyv/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/p35oCX/DimTyv/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/p35oCX/DimTyv/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/p35oCX/DimTyv/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/p35oCX/DimTyv/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posi x" --launcher_dir="/tmp/SRC/build/mesos-1.10.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/p35oCX/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_UwRX3m" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLoca lResourceProviderTest_Update_v1_rFY2ye" --zk_session_timeout="10secs" I0221 23:51:53.409505 3156 credentials.hpp:86] Loading credential for authentication from '/tmp/p35oCX/DimTyv/credential' I0221 23:51:53.409655 3156 slave.cpp:307] Agent using credential for: test-principal I0221 23:51:53.409680 3156 credentials.hpp:37] Loading credentials for authentication from '/tmp/p35oCX/DimTyv/http_credentials' I0221 23:51:53.409907 3156 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0221 23:51:53.410364 3156 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0221 23:51:53.412411 3163 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0221 23:51:53.412214 3156 slave.cpp:622] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] I0221 23:51:53.412489 3156 slave.cpp:630] Agent attributes: [ ] I0221 23:51:53.412508 3156 slave.cpp:639] Agent hostname: 34e3cb60962b I0221 23:51:53.412704 3155 task_status_update_manager.cpp:181] Pausing sending task status updates I0221 23:51:53.412740 3162 status_update_manager_process.hpp:379] Pausing operation status update manager I0221 23:51:53.414876 3161 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rFY2ye/meta' I0221 23:51:53.415124 3148 slave.cpp:7574] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rFY2ye/meta', beginning agent recovery I0221 23:51:53.415693 3159 task_status_update_manager.cpp:207] Recovering task status update manager I0221 23:51:53.416193 3151 containerizer.cpp:820] Recovering Mesos containers I0221 23:51:53.416595 3151 containerizer.cpp:1160] Recovering isolators I0221 23:51:53.417771 3152 containerizer.cpp:1199] Recovering provisioner I0221 23:51:53.418718 3153 provisioner.cpp:518] Provisioner recovery complete I0221 23:51:53.419704 3163 composing.cpp:339] Finished recovering all containerizers I0221 23:51:53.420023 3154 slave.cpp:8056] Recovering executors I0221 23:51:53.420172 3154 slave.cpp:8209] Finished recovery I0221 23:51:53.420444 3155 hierarchical.cpp:1853] Performed allocation for 0 agents in 102203ns I0221 23:51:53.420990 3150 task_status_update_manager.cpp:181] Pausing sending task status updates I0221 23:51:53.421011 3152 slave.cpp:1422] New master detected at [email protected]:37949 I0221 23:51:53.421038 3158 status_update_manager_process.hpp:379] Pausing operation status update manager I0221 23:51:53.421141 3152 slave.cpp:1487] Detecting new master I0221 23:51:53.422427 3156 slave.cpp:1514] Authenticating with master [email protected]:37949 I0221 23:51:53.422528 3156 slave.cpp:1523] Using default CRAM-MD5 authenticatee I0221 23:51:53.422828 3157 authenticatee.cpp:121] Creating new client SASL connection I0221 23:51:53.423175 3149 master.cpp:10156] Authenticating slave(1251)@172.17.0.2:37949 I0221 23:51:53.423307 3161 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2111)@172.17.0.2:37949 I0221 23:51:53.423568 3151 authenticator.cpp:98] Creating new server SASL connection I0221 23:51:53.423858 3163 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0221 23:51:53.423907 3163 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0221 23:51:53.424063 3163 authenticator.cpp:204] Received SASL authentication start I0221 23:51:53.424140 3163 authenticator.cpp:326] Authentication requires more steps I0221 23:51:53.424297 3163 authenticatee.cpp:259] Received SASL authentication step I0221 23:51:53.424449 3163 authenticator.cpp:232] Received SASL authentication step I0221 23:51:53.424494 3163 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '34e3cb60962b' server FQDN: '34e3cb60962b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0221 23:51:53.424510 3163 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0221 23:51:53.424578 3163 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0221 23:51:53.424638 3163 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '34e3cb60962b' server FQDN: '34e3cb60962b' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0221 23:51:53.424660 3163 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0221 23:51:53.424686 3163 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0221 23:51:53.424717 3163 authenticator.cpp:318] Authentication success I0221 23:51:53.424850 3155 authenticatee.cpp:299] Authentication success I0221 23:51:53.424973 3153 master.cpp:10188] Successfully authenticated principal 'test-principal' at slave(1251)@172.17.0.2:37949 I0221 23:51:53.425071 3158 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2111)@172.17.0.2:37949 I0221 23:51:53.425350 3150 slave.cpp:1614] Successfully authenticated with master [email protected]:37949 I0221 23:51:53.425773 3150 slave.cpp:2064] Will retry registration in 9.775062ms if necessary I0221 23:51:53.425951 3157 master.cpp:6626] Received register agent message from slave(1251)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:53.426343 3157 master.cpp:3709] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0221 23:51:53.426954 3159 master.cpp:6693] Authorized registration of agent at slave(1251)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:53.427088 3159 master.cpp:6805] Registering agent at slave(1251)@172.17.0.2:37949 (34e3cb60962b) with id c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 I0221 23:51:53.427930 3148 registrar.cpp:487] Applied 1 operations in 292232ns; attempting to update the registry I0221 23:51:53.428711 3148 registrar.cpp:544] Successfully updated the registry in 705792ns I0221 23:51:53.428910 3156 master.cpp:6853] Admitted agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 at slave(1251)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:53.429811 3156 master.cpp:6898] Registered agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 at slave(1251)@172.17.0.2:37949 (34e3cb60962b) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0221 23:51:53.429842 3155 slave.cpp:1647] Registered with master [email protected]:37949; given agent ID c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 I0221 23:51:53.430016 3161 task_status_update_manager.cpp:188] Resuming sending task status updates I0221 23:51:53.430044 3158 hierarchical.cpp:959] Added agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 (34e3cb60962b) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0221 23:51:53.430346 3155 slave.cpp:1682] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rFY2ye/meta/slaves/c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0/slave.info' I0221 23:51:53.430372 3158 hierarchical.cpp:1853] Performed allocation for 1 agents in 128017ns I0221 23:51:53.430474 3157 status_update_manager_process.hpp:385] Resuming operation status update manager I0221 23:51:53.431553 3155 slave.cpp:1734] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"HeVDrO5aS6CevKixNn3ZDw=="},"slave_id":{"value":"c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0"},"update_oversubscribed_resources":false} I0221 23:51:53.432387 3155 master.cpp:8036] Ignoring update on agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 at slave(1251)@172.17.0.2:37949 (34e3cb60962b) as it reports no changes I0221 23:51:53.436376 3151 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1' I0221 23:51:53.437726 3148 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.2:60274 I0221 23:51:53.438239 3148 http.cpp:2146] Processing GET_CONTAINERS call I0221 23:51:53.444036 3156 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:53.446475 3162 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1' I0221 23:51:53.447547 3160 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.2:60276 I0221 23:51:53.448189 3160 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' I0221 23:51:53.449192 3163 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rFY2ye/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:53.471866 3148 hierarchical.cpp:1853] Performed allocation for 1 agents in 194604ns I0221 23:51:53.477032 3150 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:53.477782 3150 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 285952ns I0221 23:51:53.478716 3150 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_UwRX3m/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0221 23:51:53.478782 3150 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.003008ms I0221 23:51:53.482236 3159 containerizer.cpp:2099] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Sk2835","--available_capacity=0B","--volumes=","--forward=unix:///tmp/p35oCX/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rFY2ye/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-dOMDV3/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rFY2ye/containers/o rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="108" --pipe_write="109" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_UwRX3m/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0221 23:51:53.492736 3159 launcher.cpp:145] Forked child with pid '14727' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:53.493820 3159 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 15.024128ms I0221 23:51:53.495555 3159 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 1.724928ms I0221 23:51:53.495945 3157 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_rFY2ye/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:53.517195 3153 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 21.6448ms I0221 23:51:53.519291 3148 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' I0221 23:51:53.519457 3148 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-dOMDV3/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:53.523166 3150 hierarchical.cpp:1853] Performed allocation for 1 agents in 208888ns I0221 23:51:53.574563 3160 hierarchical.cpp:1853] Performed allocation for 1 agents in 131950ns I0221 23:51:53.626070 3158 hierarchical.cpp:1853] Performed allocation for 1 agents in 349733ns I0221 23:51:53.677023 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 138804ns I0221 23:51:53.728909 3163 hierarchical.cpp:1853] Performed allocation for 1 agents in 244391ns I0221 23:51:53.780203 3153 hierarchical.cpp:1853] Performed allocation for 1 agents in 210528ns I0221 23:51:53.828933 3156 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-dOMDV3/endpoint.sock' with CSI v1 I0221 23:51:53.830858 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call I0221 23:51:53.831259 3163 hierarchical.cpp:1853] Performed allocation for 1 agents in 139817ns I0221 23:51:53.834101 3148 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:53.836905 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call I0221 23:51:53.837402 3162 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1' I0221 23:51:53.838819 3150 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.2:60278 I0221 23:51:53.839303 3150 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' I0221 23:51:53.841683 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0221 23:51:53.842031 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0221 23:51:53.843820 3149 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {} I0221 23:51:53.844360 3149 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {} I0221 23:51:53.846393 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call I0221 23:51:53.850173 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call I0221 23:51:53.853708 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call I0221 23:51:53.856153 3148 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0221 23:51:53.856324 3151 status_update_manager_process.hpp:379] Pausing operation status update manager I0221 23:51:53.856684 3153 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:37949/slave(1251)/api/v1/resource_provider I0221 23:51:53.859999 3163 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:37949/slave(1251)/api/v1/resource_provider I0221 23:51:53.860759 3149 provider.cpp:476] Connected to resource provider manager I0221 23:51:53.861430 3150 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:37949/slave(1251)/api/v1/resource_provider I0221 23:51:53.862676 3151 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1/resource_provider' I0221 23:51:53.864519 3156 http.cpp:1405] HTTP POST for /slave(1251)/api/v1/resource_provider from 172.17.0.2:60282 I0221 23:51:53.865242 3154 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Sk2835","--available_capacity=0B","--volumes=","--forward=unix:///tmp/p35oCX/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"} I0221 23:51:53.882269 3148 hierarchical.cpp:1853] Performed allocation for 1 agents in 190045ns I0221 23:51:53.902449 3151 slave.cpp:8565] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"96909808-215d-43d2-9c30-f20227e326e3"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Sk2835","--available_capacity=0B","--volumes=","--forward=unix:///tmp/p35oCX/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}' I0221 23:51:53.903875 3158 provider.cpp:498] Received SUBSCRIBED event I0221 23:51:53.903923 3158 provider.cpp:1309] Subscribed with ID 96909808-215d-43d2-9c30-f20227e326e3 I0221 23:51:53.904681 3157 status_update_manager_process.hpp:314] Recovering operation status update manager I0221 23:51:53.933960 3149 hierarchical.cpp:1853] Performed allocation for 1 agents in 132384ns I0221 23:51:53.954851 3150 provider.cpp:790] Reconciling storage pools and volumes I0221 23:51:53.957031 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0221 23:51:53.960088 3152 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 I0221 23:51:53.960454 3153 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:37949/slave(1251)/api/v1/resource_provider I0221 23:51:53.960500 3152 provider.cpp:748] Resource provider 96909808-215d-43d2-9c30-f20227e326e3 is in READY state I0221 23:51:53.960667 3150 status_update_manager_process.hpp:385] Resuming operation status update manager I0221 23:51:53.961367 3162 provider.cpp:1235] Updating profiles { test } for resource provider 96909808-215d-43d2-9c30-f20227e326e3 I0221 23:51:53.961640 3160 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1/resource_provider' I0221 23:51:53.962572 3153 provider.cpp:790] Reconciling storage pools and volumes I0221 23:51:53.963213 3155 http.cpp:1405] HTTP POST for /slave(1251)/api/v1/resource_provider from 172.17.0.2:60280 I0221 23:51:53.963682 3149 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 96909808-215d-43d2-9c30-f20227e326e3 I0221 23:51:53.963893 3160 slave.cpp:8565] Handling resource provider message 'UPDATE_STATE: 96909808-215d-43d2-9c30-f20227e326e3 {}' I0221 23:51:53.963997 3160 slave.cpp:8685] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0221 23:51:53.964516 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0221 23:51:53.964887 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0221 23:51:53.965656 3158 hierarchical.cpp:1110] Grew agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 by {} (total), { } (used) I0221 23:51:53.968210 3158 hierarchical.cpp:1067] Agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 (34e3cb60962b) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0221 23:51:53.971573 3155 hierarchical.cpp:1853] Performed allocation for 1 agents in 275601ns I0221 23:51:53.971853 3152 provider.cpp:790] Reconciling storage pools and volumes I0221 23:51:53.974089 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0221 23:51:53.974598 14731 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0221 23:51:53.984880 3153 slave.cpp:995] Agent terminating I0221 23:51:53.985800 3153 manager.cpp:127] Terminating resource provider 96909808-215d-43d2-9c30-f20227e326e3 I0221 23:51:53.986363 3156 master.cpp:1300] Agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 at slave(1251)@172.17.0.2:37949 (34e3cb60962b) disconnected I0221 23:51:53.986413 3156 master.cpp:3365] Disconnecting agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 at slave(1251)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:53.986503 3156 master.cpp:3384] Deactivating agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 at slave(1251)@172.17.0.2:37949 (34e3cb60962b) I0221 23:51:53.986654 3162 hierarchical.cpp:1156] Agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 deactivated E0221 23:51:53.986855 3149 http_connection.hpp:449] End-Of-File received I0221 23:51:53.987421 3149 http_connection.hpp:217] Re-detecting endpoint I0221 23:51:53.987934 3149 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0221 23:51:53.987998 3159 provider.cpp:488] Disconnected from resource provider manager I0221 23:51:53.988035 3149 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0221 23:51:53.988122 3159 status_update_manager_process.hpp:379] Pausing operation status update manager I0221 23:51:53.988116 3149 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:37949/slave(1251)/api/v1/resource_provider I0221 23:51:53.989917 3157 containerizer.cpp:2619] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0221 23:51:53.990001 3157 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.472818176secs I0221 23:51:53.990478 3157 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:53.991768 3159 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:37949/slave(1251)/api/v1/resource_provider I0221 23:51:53.992547 3162 provider.cpp:476] Connected to resource provider manager I0221 23:51:53.993330 3161 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:37949/slave(1251)/api/v1/resource_provider I0221 23:51:53.994125 3164 process.cpp:2781] Returning '404 Not Found' for '/slave(1251)/api/v1/resource_provider' E0221 23:51:53.995477 3160 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0221 23:51:54.017520 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 140624ns I0221 23:51:54.067605 3148 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0221 23:51:54.069159 3155 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 I0221 23:51:54.069237 3148 hierarchical.cpp:1853] Performed allocation for 1 agents in 109341ns I0221 23:51:54.071617 3163 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' I0221 23:51:54.071987 3157 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-dOMDV3/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0221 23:51:54.072311 3157 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0221 23:51:54.075150 3164 process.cpp:2781] Returning '404 Not Found' for '/slave(1251)/api/v1' I0221 23:51:54.086592 3147 master.cpp:1140] Master terminating I0221 23:51:54.086961 3158 hierarchical.cpp:1132] Removed all filters for agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 I0221 23:51:54.086984 3158 hierarchical.cpp:1008] Removed agent c9e4bbdf-5fcc-45ba-838a-a88216bc96c3-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (716 ms) [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (96769 ms total) [----------] Global test environment tear-down [==========] 2321 tests from 222 test cases ran. (1139488 ms total) [ PASSED ] 2320 tests. [ FAILED ] 1 test, listed below: [ FAILED ] OversubscriptionTest.FixedResourceEstimator 1 FAILED TEST YOU HAVE 34 DISABLED TESTS I0221 23:51:54.175143 3164 process.cpp:935] Stopped the socket accept loop Makefile:15957: recipe for target 'check-local' failed make[4]: *** [check-local] Error 1 make[4]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src' Makefile:15073: recipe for target 'check-am' failed make[3]: *** [check-am] Error 2 make[3]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src' Makefile:15077: recipe for target 'check' failed make[2]: *** [check] Error 2 make[2]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src' Makefile:791: recipe for target 'check-recursive' failed make[1]: *** [check-recursive] Error 1 make[1]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub' Makefile:997: recipe for target 'distcheck' failed make: *** [distcheck] Error 1 Untagged: mesos/mesos-build:ubuntu-16.04 Untagged: mesos/mesos-build@sha256:fa967cbcfb44f55708a3cbc87f245c6d29dd891464db558af56a03ee321526bb Deleted: sha256:e895c0531b9a9a288fabe479a49f7059aed83645351ac99ec2ea2616822c9f97 Deleted: sha256:09119b0b314a69ba6ec6251f2e89f4199fe1e874c84f9abf07dcbd23dbc3f1c1 Deleted: sha256:562fe6af5a3883058be9c784a839392215ed4185a21d21f1d99df0d17f3ae6e7 Deleted: sha256:0dcdfbe322a4f332f73ac70905d557300ec6dae3bd19586758772c750c7b4a19 Deleted: sha256:c66652d605f01094e2db53d62505dbd524e076d5aa69b89d5e620003803eb149 Deleted: sha256:a2cf79bfb9593c05fd7142ddb49afef77ea4ad5d2464e841f09fe62ffee396e0 Deleted: sha256:f7a904214b390f39d98573882f631dc908df8b2b540cf04e1062f8182c1efffd Deleted: sha256:ce1f6fcaa83dfce189d76e08f184085732eab4eeb2562d2399953958405c5bec Deleted: sha256:cce92fda689ab9033f0b8db214bc63edd1ae3e05831a0f3a9418976d7dc7ccdd Deleted: sha256:d22094bbd65447c59a42c580eaa3a44cee9cd855f00905f59409be21bcefc745 Deleted: sha256:b8976847450013f3eb5e9a81a5778f73ed7bef67e6393049712ef17102b4b7b7 Deleted: sha256:b8c891f0ffec910a12757d733b178e3f62d81dbbde2b31d3b754071c416108ed Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/7399/console - Mesos Reviewbot On Feb. 21, 2020, 12:30 p.m., Andrei Budnik wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/72158/ > ----------------------------------------------------------- > > (Updated Feb. 21, 2020, 12:30 p.m.) > > > Review request for mesos, Andrei Sekretenko, Greg Mann, and Qian Zhang. > > > Repository: mesos > > > Description > ------- > > This patch fixes the bug when `listenFdsWithName` function returns > an empty set of file descriptors on pre-227 systemd versions when > `domain_socket_location` value is not equals to the "systemd:unknown". > This happens when a user expects a newer version of systemd and > specifies a "systemd/<value taken from FileDescriptorName>", but > the actual systemd version does not support `FileDescriptorName`. > In this case, `LISTEN_FDNAMES` env variable is not specified, > so all socket FDs, which are specified by the `LISTEN_FDS`, > must be used to locate the path to the domain socket. > > > Diffs > ----- > > src/linux/systemd.cpp 9897473115ac0f9809734c109ba412eefd32e59e > > > Diff: https://reviews.apache.org/r/72158/diff/1/ > > > Testing > ------- > > internal CI (including CoreOS) > > > Thanks, > > Andrei Budnik > >
