----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/72190/#review219925 -----------------------------------------------------------
Bad patch! Reviews applied: [72121, 72122, 71965, 71966, 72189, 72190] 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_72190"] Error: ...<truncated>... e_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 24ee1ed8-568b-42e9-935d-62319a45d1ec) for operation UUID 2500967f-b94e-45e0-8394-ca0b87c00886 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:43.718674 3106 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:35181/slave(1237)/api/v1/resource_provider I0312 15:30:43.719671 3112 process.cpp:3671] Handling HTTP event for process 'slave(1237)' with path: '/slave(1237)/api/v1/resource_provider' I0312 15:30:43.722822 3102 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.149137ms I0312 15:30:43.723472 3110 master.cpp:9485] Sending offers [ 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O3 ] to framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 I0312 15:30:43.724125 3110 sched.cpp:934] Scheduler::resourceOffers took 83602ns I0312 15:30:43.727680 3105 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0312 15:30:43.733299 3106 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:57454 I0312 15:30:43.733705 3106 http.cpp:277] Processing call CREATE_VOLUMES I0312 15:30:43.734825 3106 master.cpp:3705] Authorizing principal 'test-principal' to perform action CREATE_VOLUME on object {"value":"storage/default-role","resource":{"provider_id":{"value":"c02fab3f-71bc-466f-8c45-d1b0f4b1cfee"},"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":"1453291a-08ac-4289-a7bc-f8a3bebc6f87","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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945","profile":"test"}}}} I0312 15:30:43.737004 3108 sched.cpp:960] Rescinded offer 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O3 I0312 15:30:43.737107 3108 sched.cpp:971] Scheduler::offerRescinded took 36985ns I0312 15:30:43.737731 3101 master.cpp:11784] Removing offer 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O3 I0312 15:30:43.737730 3110 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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945,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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945,test)]:2048, offered or allocated: {}) on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 from framework 4bb2a 1df-7aad-4ad9-83a7-35b437e64572-0000 I0312 15:30:43.739643 3110 hierarchical.cpp:1625] Framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 filtered agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 for 5secs I0312 15:30:43.743119 3100 master.cpp:11649] Sending operation '' (uuid: de10685e-a41f-4fd5-ac37-7919e7571473) to agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 at slave(1237)@172.17.0.2:35181 (5083c546e440) I0312 15:30:43.743981 3097 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0312 15:30:43.745810 3112 master.cpp:5533] Processing REVIVE call for framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 I0312 15:30:43.746536 3101 hierarchical.cpp:1721] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 I0312 15:30:43.747983 3107 provider.cpp:498] Received APPLY_OPERATION event I0312 15:30:43.748037 3107 provider.cpp:1351] Received CREATE operation '' (uuid: de10685e-a41f-4fd5-ac37-7919e7571473) I0312 15:30:43.748266 3101 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.375725ms I0312 15:30:43.749162 3103 master.cpp:9485] Sending offers [ 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O4 ] to framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 I0312 15:30:43.749933 3103 sched.cpp:934] Scheduler::resourceOffers took 99927ns I0312 15:30:43.761827 3098 http.cpp:1405] HTTP POST for /slave(1237)/api/v1/resource_provider from 172.17.0.2:57446 I0312 15:30:43.763037 3111 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 2500967f-b94e-45e0-8394-ca0b87c00886) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0312 15:30:43.763265 3111 slave.cpp:9050] Updating the state of operation with no ID (uuid: 2500967f-b94e-45e0-8394-ca0b87c00886) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0312 15:30:43.763335 3111 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: 2500967f-b94e-45e0-8394-ca0b87c00886) for an operator API call I0312 15:30:43.763756 3099 master.cpp:11301] Updating the state of operation '' (uuid: 2500967f-b94e-45e0-8394-ca0b87c00886) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0312 15:30:43.764485 3100 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0312 15:30:43.852033 3108 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 58b55deb-5688-49e9-bc98-729b653f6380) for operation UUID de10685e-a41f-4fd5-ac37-7919e7571473 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:43.852098 3108 status_update_manager_process.hpp:414] Creating operation status update stream de10685e-a41f-4fd5-ac37-7919e7571473 checkpoint=true I0312 15:30:43.852114 3107 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0312 15:30:43.852425 3108 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 58b55deb-5688-49e9-bc98-729b653f6380) for operation UUID de10685e-a41f-4fd5-ac37-7919e7571473 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:43.910455 3108 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 58b55deb-5688-49e9-bc98-729b653f6380) for operation UUID de10685e-a41f-4fd5-ac37-7919e7571473 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:43.910773 3108 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 24ee1ed8-568b-42e9-935d-62319a45d1ec) for stream 2500967f-b94e-45e0-8394-ca0b87c00886 I0312 15:30:43.910842 3108 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 24ee1ed8-568b-42e9-935d-62319a45d1ec) for operation UUID 2500967f-b94e-45e0-8394-ca0b87c00886 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:43.911538 3110 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:35181/slave(1237)/api/v1/resource_provider I0312 15:30:43.912897 3105 process.cpp:3671] Handling HTTP event for process 'slave(1237)' with path: '/slave(1237)/api/v1/resource_provider' I0312 15:30:43.957654 3106 http.cpp:1405] HTTP POST for /slave(1237)/api/v1/resource_provider from 172.17.0.2:57446 I0312 15:30:43.958606 3112 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: de10685e-a41f-4fd5-ac37-7919e7571473) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0312 15:30:43.958858 3112 slave.cpp:9050] Updating the state of operation with no ID (uuid: de10685e-a41f-4fd5-ac37-7919e7571473) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0312 15:30:43.958907 3112 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: de10685e-a41f-4fd5-ac37-7919e7571473) for an operator API call I0312 15:30:43.959270 3107 master.cpp:11301] Updating the state of operation '' (uuid: de10685e-a41f-4fd5-ac37-7919e7571473) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0312 15:30:43.960094 3110 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0312 15:30:43.960625 3108 status_update_manager_process.hpp:490] Cleaning up operation status update stream 2500967f-b94e-45e0-8394-ca0b87c00886 I0312 15:30:44.018764 3103 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0312 15:30:44.018966 3103 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 58b55deb-5688-49e9-bc98-729b653f6380) for stream de10685e-a41f-4fd5-ac37-7919e7571473 I0312 15:30:44.019052 3103 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 58b55deb-5688-49e9-bc98-729b653f6380) for operation UUID de10685e-a41f-4fd5-ac37-7919e7571473 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.087262 3103 status_update_manager_process.hpp:490] Cleaning up operation status update stream de10685e-a41f-4fd5-ac37-7919e7571473 I0312 15:30:44.141638 3099 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0312 15:30:44.144048 3102 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:57456 I0312 15:30:44.144326 3102 http.cpp:277] Processing call DESTROY_VOLUMES I0312 15:30:44.145352 3102 master.cpp:3705] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"c02fab3f-71bc-466f-8c45-d1b0f4b1cfee"},"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":"1453291a-08ac-4289-a7bc-f8a3bebc6f87","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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945","profile":"test"}}}} I0312 15:30:44.146950 3111 sched.cpp:960] Rescinded offer 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O4 I0312 15:30:44.147075 3111 sched.cpp:971] Scheduler::offerRescinded took 56013ns I0312 15:30:44.147617 3103 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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945,test),1453291a-08ac-4289-a7bc-f8a3bebc6f87: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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945,test),1453291a-08ac-4289-a7bc-f8a3bebc6f87:volume]:2048, offered or allocated: {}) on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 from framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 I0312 15:30:44.147720 3097 master.cpp:11784] Removing offer 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O4 I0312 15:30:44.149780 3103 hierarchical.cpp:1625] Framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 filtered agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 for 5secs I0312 15:30:44.153127 3098 master.cpp:11649] Sending operation '' (uuid: d32b9d11-64bc-4358-bf12-1d25fe9bb4f4) to agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 at slave(1237)@172.17.0.2:35181 (5083c546e440) I0312 15:30:44.153736 3101 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0312 15:30:44.157407 3110 provider.cpp:498] Received APPLY_OPERATION event I0312 15:30:44.157456 3110 provider.cpp:1351] Received DESTROY operation '' (uuid: d32b9d11-64bc-4358-bf12-1d25fe9bb4f4) I0312 15:30:44.162317 3104 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.47963ms I0312 15:30:44.163358 3098 master.cpp:9485] Sending offers [ 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O5 ] to framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 I0312 15:30:44.164177 3108 sched.cpp:934] Scheduler::resourceOffers took 103120ns I0312 15:30:44.253561 3105 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 31498db8-b718-45db-81fe-08bda2beee2c) for operation UUID d32b9d11-64bc-4358-bf12-1d25fe9bb4f4 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.253648 3105 status_update_manager_process.hpp:414] Creating operation status update stream d32b9d11-64bc-4358-bf12-1d25fe9bb4f4 checkpoint=true I0312 15:30:44.254006 3105 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 31498db8-b718-45db-81fe-08bda2beee2c) for operation UUID d32b9d11-64bc-4358-bf12-1d25fe9bb4f4 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.312212 3105 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 31498db8-b718-45db-81fe-08bda2beee2c) for operation UUID d32b9d11-64bc-4358-bf12-1d25fe9bb4f4 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.313262 3101 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:35181/slave(1237)/api/v1/resource_provider I0312 15:30:44.314599 3109 process.cpp:3671] Handling HTTP event for process 'slave(1237)' with path: '/slave(1237)/api/v1/resource_provider' I0312 15:30:44.318254 3097 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0312 15:30:44.320065 3110 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:57458 I0312 15:30:44.320358 3110 http.cpp:277] Processing call UNRESERVE_RESOURCES I0312 15:30:44.321259 3110 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"c02fab3f-71bc-466f-8c45-d1b0f4b1cfee"},"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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945","profile":"test"}}}} I0312 15:30:44.323004 3106 sched.cpp:960] Rescinded offer 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O5 I0312 15:30:44.323125 3106 sched.cpp:971] Scheduler::offerRescinded took 51747ns I0312 15:30:44.323616 3109 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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945,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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945,test)]:2048, offered or allocated: {}) on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 from framework 4bb2a 1df-7aad-4ad9-83a7-35b437e64572-0000 I0312 15:30:44.323714 3101 master.cpp:11784] Removing offer 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O5 I0312 15:30:44.325356 3109 hierarchical.cpp:1625] Framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 filtered agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 for 5secs I0312 15:30:44.328200 3103 master.cpp:11649] Sending operation '' (uuid: d2792d28-bf6b-46ae-b4b7-129b345e129b) to agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 at slave(1237)@172.17.0.2:35181 (5083c546e440) I0312 15:30:44.328953 3099 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0312 15:30:44.332355 3112 provider.cpp:498] Received APPLY_OPERATION event I0312 15:30:44.332407 3112 provider.cpp:1351] Received UNRESERVE operation '' (uuid: d2792d28-bf6b-46ae-b4b7-129b345e129b) I0312 15:30:44.338850 3097 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.265489ms I0312 15:30:44.339550 3104 master.cpp:9485] Sending offers [ 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O6 ] to framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 I0312 15:30:44.340358 3103 sched.cpp:934] Scheduler::resourceOffers took 109836ns I0312 15:30:44.357730 3099 http.cpp:1405] HTTP POST for /slave(1237)/api/v1/resource_provider from 172.17.0.2:57446 I0312 15:30:44.358703 3106 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: d32b9d11-64bc-4358-bf12-1d25fe9bb4f4) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0312 15:30:44.358917 3106 slave.cpp:9050] Updating the state of operation with no ID (uuid: d32b9d11-64bc-4358-bf12-1d25fe9bb4f4) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0312 15:30:44.358975 3106 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: d32b9d11-64bc-4358-bf12-1d25fe9bb4f4) for an operator API call I0312 15:30:44.359369 3102 master.cpp:11301] Updating the state of operation '' (uuid: d32b9d11-64bc-4358-bf12-1d25fe9bb4f4) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0312 15:30:44.360072 3111 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0312 15:30:44.421914 3106 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 882ee57d-947c-43a7-9007-b6cd6c1ce9b4) for operation UUID d2792d28-bf6b-46ae-b4b7-129b345e129b on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.421984 3106 status_update_manager_process.hpp:414] Creating operation status update stream d2792d28-bf6b-46ae-b4b7-129b345e129b checkpoint=true I0312 15:30:44.422020 3112 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0312 15:30:44.422293 3106 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 882ee57d-947c-43a7-9007-b6cd6c1ce9b4) for operation UUID d2792d28-bf6b-46ae-b4b7-129b345e129b on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.489182 3106 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 882ee57d-947c-43a7-9007-b6cd6c1ce9b4) for operation UUID d2792d28-bf6b-46ae-b4b7-129b345e129b on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.489578 3106 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 31498db8-b718-45db-81fe-08bda2beee2c) for stream d32b9d11-64bc-4358-bf12-1d25fe9bb4f4 I0312 15:30:44.489662 3106 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 31498db8-b718-45db-81fe-08bda2beee2c) for operation UUID d32b9d11-64bc-4358-bf12-1d25fe9bb4f4 on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.490168 3097 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:35181/slave(1237)/api/v1/resource_provider I0312 15:30:44.491297 3109 process.cpp:3671] Handling HTTP event for process 'slave(1237)' with path: '/slave(1237)/api/v1/resource_provider' I0312 15:30:44.533687 3107 http.cpp:1405] HTTP POST for /slave(1237)/api/v1/resource_provider from 172.17.0.2:57446 I0312 15:30:44.534870 3101 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: d2792d28-bf6b-46ae-b4b7-129b345e129b) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0312 15:30:44.535133 3101 slave.cpp:9050] Updating the state of operation with no ID (uuid: d2792d28-bf6b-46ae-b4b7-129b345e129b) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0312 15:30:44.535197 3101 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: d2792d28-bf6b-46ae-b4b7-129b345e129b) for an operator API call I0312 15:30:44.535570 3112 master.cpp:11301] Updating the state of operation '' (uuid: d2792d28-bf6b-46ae-b4b7-129b345e129b) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0312 15:30:44.536321 3097 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0312 15:30:44.537854 3100 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0312 15:30:44.564548 3106 status_update_manager_process.hpp:490] Cleaning up operation status update stream d32b9d11-64bc-4358-bf12-1d25fe9bb4f4 I0312 15:30:44.564761 3106 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 882ee57d-947c-43a7-9007-b6cd6c1ce9b4) for stream d2792d28-bf6b-46ae-b4b7-129b345e129b I0312 15:30:44.564838 3106 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 882ee57d-947c-43a7-9007-b6cd6c1ce9b4) for operation UUID d2792d28-bf6b-46ae-b4b7-129b345e129b on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.649179 3106 status_update_manager_process.hpp:490] Cleaning up operation status update stream d2792d28-bf6b-46ae-b4b7-129b345e129b I0312 15:30:44.697890 3102 master.cpp:1407] Framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 disconnected I0312 15:30:44.697942 3102 master.cpp:3326] Deactivating framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 I0312 15:30:44.698413 3097 hierarchical.cpp:813] Deactivated framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 I0312 15:30:44.698889 3096 slave.cpp:995] Agent terminating I0312 15:30:44.699162 3097 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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945,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_iptpzV/2GB-cacaf8a8-e9dd-4688-a28e-09d620d7c945,test)]:2048, offered or allocated: {}) on agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 from framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 I0312 15:30:44.699445 3102 master.cpp:11784] Removing offer 4bb2a1df-7aad-4ad9-83a7-35b437e64572-O6 I0312 15:30:44.699579 3102 master.cpp:3310] Disconnecting framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 I0312 15:30:44.699834 3102 master.cpp:1422] Giving framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 0ns to failover I0312 15:30:44.700516 3096 manager.cpp:127] Terminating resource provider c02fab3f-71bc-466f-8c45-d1b0f4b1cfee I0312 15:30:44.700971 3105 master.cpp:1292] Agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 at slave(1237)@172.17.0.2:35181 (5083c546e440) disconnected I0312 15:30:44.701006 3105 master.cpp:3361] Disconnecting agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 at slave(1237)@172.17.0.2:35181 (5083c546e440) I0312 15:30:44.701143 3105 master.cpp:3380] Deactivating agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 at slave(1237)@172.17.0.2:35181 (5083c546e440) I0312 15:30:44.701377 3105 master.cpp:9269] Framework failover timeout, removing framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 I0312 15:30:44.701416 3105 master.cpp:10285] Removing framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 (default) at [email protected]:35181 I0312 15:30:44.701432 3097 hierarchical.cpp:1156] Agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 deactivated I0312 15:30:44.701925 3105 hierarchical.cpp:1777] Allocation paused E0312 15:30:44.701998 3108 http_connection.hpp:449] End-Of-File received I0312 15:30:44.702414 3108 http_connection.hpp:217] Re-detecting endpoint I0312 15:30:44.702416 3105 hierarchical.cpp:757] Removed framework 4bb2a1df-7aad-4ad9-83a7-35b437e64572-0000 I0312 15:30:44.702543 3105 hierarchical.cpp:1787] Allocation resumed I0312 15:30:44.702987 3108 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0312 15:30:44.703050 3108 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0312 15:30:44.703104 3097 provider.cpp:488] Disconnected from resource provider manager I0312 15:30:44.703133 3108 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35181/slave(1237)/api/v1/resource_provider I0312 15:30:44.703310 3097 status_update_manager_process.hpp:379] Pausing operation status update manager I0312 15:30:44.704677 3111 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 I0312 15:30:44.704774 3111 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.576205184secs I0312 15:30:44.705220 3111 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:44.706542 3097 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35181/slave(1237)/api/v1/resource_provider I0312 15:30:44.707231 3108 provider.cpp:476] Connected to resource provider manager I0312 15:30:44.707979 3101 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35181/slave(1237)/api/v1/resource_provider I0312 15:30:44.708250 3103 hierarchical.cpp:1853] Performed allocation for 1 agents in 192683ns E0312 15:30:44.708595 3101 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 I0312 15:30:44.709024 3113 process.cpp:2781] Returning '404 Not Found' for '/slave(1237)/api/v1/resource_provider' E0312 15:30:44.710283 3106 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0312 15:30:44.759331 3109 hierarchical.cpp:1853] Performed allocation for 1 agents in 189401ns I0312 15:30:44.809446 3110 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0312 15:30:44.811172 3102 hierarchical.cpp:1853] Performed allocation for 1 agents in 308211ns I0312 15:30:44.811224 3110 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 I0312 15:30:44.814138 3103 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' I0312 15:30:44.814375 3106 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-7iAPUu/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:44.814666 3106 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:44.817476 3113 process.cpp:2781] Returning '404 Not Found' for '/slave(1237)/api/v1' I0312 15:30:44.831476 3096 master.cpp:1140] Master terminating I0312 15:30:44.832486 3111 hierarchical.cpp:1132] Removed all filters for agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 I0312 15:30:44.832516 3111 hierarchical.cpp:1008] Removed agent 4bb2a1df-7aad-4ad9-83a7-35b437e64572-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2463 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 I0312 15:30:44.848964 3096 cluster.cpp:186] Creating default 'local' authorizer I0312 15:30:44.853910 3111 master.cpp:443] Master 765e56fd-033e-48dd-9319-420957c920d9 (5083c546e440) started on 172.17.0.2:35181 I0312 15:30:44.853941 3111 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/cjzDhW/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/cjzDhW/master" --zk_session_timeout="10secs" I0312 15:30:44.854249 3111 master.cpp:495] Master only allowing authenticated frameworks to register I0312 15:30:44.854270 3111 master.cpp:501] Master only allowing authenticated agents to register I0312 15:30:44.854279 3111 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0312 15:30:44.854288 3111 credentials.hpp:37] Loading credentials for authentication from '/tmp/cjzDhW/credentials' I0312 15:30:44.854539 3111 master.cpp:551] Using default 'crammd5' authenticator I0312 15:30:44.854727 3111 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0312 15:30:44.854955 3111 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0312 15:30:44.855136 3111 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0312 15:30:44.855315 3111 master.cpp:632] Authorization enabled I0312 15:30:44.855708 3108 hierarchical.cpp:567] Initialized hierarchical allocator process I0312 15:30:44.855739 3104 whitelist_watcher.cpp:77] No whitelist given I0312 15:30:44.858835 3102 master.cpp:2165] Elected as the leading master! I0312 15:30:44.858877 3102 master.cpp:1661] Recovering from registrar I0312 15:30:44.859122 3098 registrar.cpp:339] Recovering registrar I0312 15:30:44.859910 3098 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0312 15:30:44.860033 3098 registrar.cpp:487] Applied 1 operations in 35961ns; attempting to update the registry I0312 15:30:44.860759 3105 registrar.cpp:544] Successfully updated the registry in 0ns I0312 15:30:44.860913 3105 registrar.cpp:416] Successfully recovered registrar I0312 15:30:44.861394 3108 master.cpp:1814] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0312 15:30:44.861452 3111 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover W0312 15:30:44.866937 3096 process.cpp:2877] Attempted to spawn already running process [email protected]:35181 I0312 15:30:44.868444 3096 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0312 15:30:44.869035 3096 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0312 15:30:44.869065 3096 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0312 15:30:44.869079 3096 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0312 15:30:44.869109 3096 provisioner.cpp:294] Using default backend 'copy' I0312 15:30:44.871647 3096 cluster.cpp:533] Creating default 'local' authorizer I0312 15:30:44.874177 3098 slave.cpp:274] Mesos agent started on (1238)@172.17.0.2:35181 I0312 15:30:44.874205 3098 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/cjzDhW/c8Axcx/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/cjzDhW/c8Axcx/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/cjzDhW/c8Axcx/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/cjzDhW/c8Axcx/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/cjzDhW/c8Axcx/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/cjzDhW/c8Axcx/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/cjzDhW/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_g91usD" --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_ss4sIJ" --zk_session_timeout="10secs" I0312 15:30:44.874663 3098 credentials.hpp:86] Loading credential for authentication from '/tmp/cjzDhW/c8Axcx/credential' I0312 15:30:44.874853 3098 slave.cpp:307] Agent using credential for: test-principal I0312 15:30:44.874883 3098 credentials.hpp:37] Loading credentials for authentication from '/tmp/cjzDhW/c8Axcx/http_credentials' I0312 15:30:44.875123 3098 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0312 15:30:44.875596 3098 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0312 15:30:44.877317 3098 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"}] I0312 15:30:44.877609 3098 slave.cpp:630] Agent attributes: [ ] I0312 15:30:44.877632 3098 slave.cpp:639] Agent hostname: 5083c546e440 I0312 15:30:44.877712 3107 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0312 15:30:44.877858 3103 status_update_manager_process.hpp:379] Pausing operation status update manager I0312 15:30:44.877898 3110 task_status_update_manager.cpp:181] Pausing sending task status updates I0312 15:30:44.879559 3106 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_ss4sIJ/meta' I0312 15:30:44.879748 3112 slave.cpp:7606] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_ss4sIJ/meta', beginning agent recovery I0312 15:30:44.880466 3109 task_status_update_manager.cpp:207] Recovering task status update manager I0312 15:30:44.881111 3108 containerizer.cpp:820] Recovering Mesos containers I0312 15:30:44.881595 3108 containerizer.cpp:1160] Recovering isolators I0312 15:30:44.882767 3100 containerizer.cpp:1199] Recovering provisioner I0312 15:30:44.883607 3105 provisioner.cpp:518] Provisioner recovery complete I0312 15:30:44.884505 3104 composing.cpp:339] Finished recovering all containerizers I0312 15:30:44.884894 3108 slave.cpp:8088] Recovering executors I0312 15:30:44.885010 3108 slave.cpp:8241] Finished recovery I0312 15:30:44.885457 3097 hierarchical.cpp:1853] Performed allocation for 0 agents in 92438ns I0312 15:30:44.885846 3105 task_status_update_manager.cpp:181] Pausing sending task status updates I0312 15:30:44.885888 3097 slave.cpp:1454] New master detected at [email protected]:35181 I0312 15:30:44.885888 3110 status_update_manager_process.hpp:379] Pausing operation status update manager I0312 15:30:44.886030 3097 slave.cpp:1519] Detecting new master I0312 15:30:44.891402 3101 slave.cpp:1546] Authenticating with master [email protected]:35181 I0312 15:30:44.891517 3101 slave.cpp:1555] Using default CRAM-MD5 authenticatee I0312 15:30:44.891896 3111 authenticatee.cpp:121] Creating new client SASL connection I0312 15:30:44.892269 3111 master.cpp:9676] Authenticating slave(1238)@172.17.0.2:35181 I0312 15:30:44.892525 3107 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2095)@172.17.0.2:35181 I0312 15:30:44.892943 3104 authenticator.cpp:98] Creating new server SASL connection I0312 15:30:44.893292 3103 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0312 15:30:44.893344 3103 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0312 15:30:44.893484 3103 authenticator.cpp:204] Received SASL authentication start I0312 15:30:44.893554 3103 authenticator.cpp:326] Authentication requires more steps I0312 15:30:44.893690 3108 authenticatee.cpp:259] Received SASL authentication step I0312 15:30:44.893887 3102 authenticator.cpp:232] Received SASL authentication step I0312 15:30:44.893945 3102 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5083c546e440' server FQDN: '5083c546e440' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0312 15:30:44.893978 3102 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0312 15:30:44.894059 3102 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0312 15:30:44.894166 3102 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5083c546e440' server FQDN: '5083c546e440' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0312 15:30:44.894203 3102 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0312 15:30:44.894220 3102 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0312 15:30:44.894245 3102 authenticator.cpp:318] Authentication success I0312 15:30:44.894381 3100 authenticatee.cpp:299] Authentication success I0312 15:30:44.894520 3112 master.cpp:9708] Successfully authenticated principal 'test-principal' at slave(1238)@172.17.0.2:35181 I0312 15:30:44.894520 3105 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2095)@172.17.0.2:35181 I0312 15:30:44.894871 3110 slave.cpp:1646] Successfully authenticated with master [email protected]:35181 I0312 15:30:44.895401 3110 slave.cpp:2096] Will retry registration in 5.325646ms if necessary I0312 15:30:44.895622 3099 master.cpp:6174] Received register agent message from slave(1238)@172.17.0.2:35181 (5083c546e440) I0312 15:30:44.896031 3099 master.cpp:3705] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0312 15:30:44.896675 3106 master.cpp:6241] Authorized registration of agent at slave(1238)@172.17.0.2:35181 (5083c546e440) I0312 15:30:44.896795 3106 master.cpp:6353] Registering agent at slave(1238)@172.17.0.2:35181 (5083c546e440) with id 765e56fd-033e-48dd-9319-420957c920d9-S0 I0312 15:30:44.897478 3108 registrar.cpp:487] Applied 1 operations in 234432ns; attempting to update the registry I0312 15:30:44.898211 3108 registrar.cpp:544] Successfully updated the registry in 660992ns I0312 15:30:44.898447 3097 master.cpp:6401] Admitted agent 765e56fd-033e-48dd-9319-420957c920d9-S0 at slave(1238)@172.17.0.2:35181 (5083c546e440) I0312 15:30:44.899232 3097 master.cpp:6446] Registered agent 765e56fd-033e-48dd-9319-420957c920d9-S0 at slave(1238)@172.17.0.2:35181 (5083c546e440) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0312 15:30:44.899351 3110 slave.cpp:1679] Registered with master [email protected]:35181; given agent ID 765e56fd-033e-48dd-9319-420957c920d9-S0 I0312 15:30:44.899458 3105 hierarchical.cpp:959] Added agent 765e56fd-033e-48dd-9319-420957c920d9-S0 (5083c546e440) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0312 15:30:44.899503 3099 task_status_update_manager.cpp:188] Resuming sending task status updates I0312 15:30:44.899935 3104 status_update_manager_process.hpp:385] Resuming operation status update manager I0312 15:30:44.899937 3110 slave.cpp:1714] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_ss4sIJ/meta/slaves/765e56fd-033e-48dd-9319-420957c920d9-S0/slave.info' I0312 15:30:44.900032 3105 hierarchical.cpp:1853] Performed allocation for 1 agents in 324386ns I0312 15:30:44.901407 3110 slave.cpp:1766] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"XHat3ECJSyGJSbXa81ProQ=="},"slave_id":{"value":"765e56fd-033e-48dd-9319-420957c920d9-S0"},"update_oversubscribed_resources":false} I0312 15:30:44.902535 3108 master.cpp:7584] Ignoring update on agent 765e56fd-033e-48dd-9319-420957c920d9-S0 at slave(1238)@172.17.0.2:35181 (5083c546e440) as it reports no changes I0312 15:30:44.906597 3109 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1' I0312 15:30:44.908156 3103 http.cpp:1405] HTTP POST for /slave(1238)/api/v1 from 172.17.0.2:57466 I0312 15:30:44.908646 3103 http.cpp:2828] Processing GET_CONTAINERS call I0312 15:30:44.914515 3103 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:44.917232 3105 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1' I0312 15:30:44.918383 3098 http.cpp:1405] HTTP POST for /slave(1238)/api/v1 from 172.17.0.2:57468 I0312 15:30:44.919044 3098 http.cpp:3288] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:44.920228 3097 http.cpp:3392] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_ss4sIJ/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:44.921085 3112 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:44.921782 3112 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 276992ns I0312 15:30:44.922614 3112 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_g91usD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0312 15:30:44.922672 3112 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 892928ns I0312 15:30:44.925496 3111 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_8K7rYP","--available_capacity=0B","--volumes=","--forward=unix:///tmp/cjzDhW/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_ss4sIJ/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-Sas5z8/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_ss4sIJ/containers/o rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="105" --pipe_write="106" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_g91usD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0312 15:30:44.934448 3111 launcher.cpp:145] Forked child with pid '14671' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:44.937077 3109 hierarchical.cpp:1853] Performed allocation for 1 agents in 227851ns I0312 15:30:44.957811 3111 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 35.139072ms I0312 15:30:44.958756 3111 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 935168ns I0312 15:30:44.958945 3111 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_ss4sIJ/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:44.959791 3100 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.012992ms I0312 15:30:44.962038 3101 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' I0312 15:30:44.962286 3097 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-Sas5z8/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:44.988773 3107 hierarchical.cpp:1853] Performed allocation for 1 agents in 210822ns I0312 15:30:45.040096 3109 hierarchical.cpp:1853] Performed allocation for 1 agents in 206747ns I0312 15:30:45.091270 3107 hierarchical.cpp:1853] Performed allocation for 1 agents in 203877ns I0312 15:30:45.143020 3110 hierarchical.cpp:1853] Performed allocation for 1 agents in 209248ns I0312 15:30:45.195098 3099 hierarchical.cpp:1853] Performed allocation for 1 agents in 212632ns I0312 15:30:45.246522 3100 hierarchical.cpp:1853] Performed allocation for 1 agents in 183113ns I0312 15:30:45.273126 3109 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-Sas5z8/endpoint.sock' with CSI v1 I0312 15:30:45.276108 3106 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-Sas5z8/endpoint.sock' with CSI v0 I0312 15:30:45.277683 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/Probe call I0312 15:30:45.280557 3112 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:45.283428 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginCapabilities call I0312 15:30:45.283717 3109 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1' I0312 15:30:45.285248 3111 http.cpp:1405] HTTP POST for /slave(1238)/api/v1 from 172.17.0.2:57470 I0312 15:30:45.285763 3111 http.cpp:3506] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:45.287688 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0312 15:30:45.288051 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0312 15:30:45.290036 3108 v0_volume_manager.cpp:628] NODE_SERVICE loaded: {} I0312 15:30:45.290565 3108 v0_volume_manager.cpp:628] CONTROLLER_SERVICE loaded: {} I0312 15:30:45.292752 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ControllerGetCapabilities call I0312 15:30:45.296484 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetCapabilities call I0312 15:30:45.298056 3109 hierarchical.cpp:1853] Performed allocation for 1 agents in 182049ns I0312 15:30:45.300009 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetId call I0312 15:30:45.302273 3107 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0312 15:30:45.302400 3111 status_update_manager_process.hpp:379] Pausing operation status update manager I0312 15:30:45.302841 3101 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35181/slave(1238)/api/v1/resource_provider I0312 15:30:45.305887 3109 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35181/slave(1238)/api/v1/resource_provider I0312 15:30:45.306627 3112 provider.cpp:476] Connected to resource provider manager I0312 15:30:45.307250 3111 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35181/slave(1238)/api/v1/resource_provider I0312 15:30:45.308445 3110 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1/resource_provider' I0312 15:30:45.310191 3108 http.cpp:1405] HTTP POST for /slave(1238)/api/v1/resource_provider from 172.17.0.2:57474 I0312 15:30:45.310920 3102 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_8K7rYP","--available_capacity=0B","--volumes=","--forward=unix:///tmp/cjzDhW/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"} I0312 15:30:45.335345 3110 slave.cpp:8597] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"b7fa933d-033f-4a00-9d37-519ae20e8b2c"},"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_8K7rYP","--available_capacity=0B","--volumes=","--forward=unix:///tmp/cjzDhW/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"}' I0312 15:30:45.337270 3106 provider.cpp:498] Received SUBSCRIBED event I0312 15:30:45.337322 3106 provider.cpp:1309] Subscribed with ID b7fa933d-033f-4a00-9d37-519ae20e8b2c I0312 15:30:45.338193 3099 status_update_manager_process.hpp:314] Recovering operation status update manager I0312 15:30:45.349308 3109 hierarchical.cpp:1853] Performed allocation for 1 agents in 191806ns I0312 15:30:45.391610 3103 provider.cpp:790] Reconciling storage pools and volumes I0312 15:30:45.393996 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0312 15:30:45.396978 3107 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 765e56fd-033e-48dd-9319-420957c920d9-S0 I0312 15:30:45.397305 3103 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:35181/slave(1238)/api/v1/resource_provider I0312 15:30:45.397361 3107 provider.cpp:748] Resource provider b7fa933d-033f-4a00-9d37-519ae20e8b2c is in READY state I0312 15:30:45.397424 3104 status_update_manager_process.hpp:385] Resuming operation status update manager I0312 15:30:45.398161 3098 provider.cpp:1235] Updating profiles { test } for resource provider b7fa933d-033f-4a00-9d37-519ae20e8b2c I0312 15:30:45.398828 3112 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1/resource_provider' I0312 15:30:45.399451 3105 provider.cpp:790] Reconciling storage pools and volumes I0312 15:30:45.400627 3099 http.cpp:1405] HTTP POST for /slave(1238)/api/v1/resource_provider from 172.17.0.2:57472 I0312 15:30:45.401047 3097 hierarchical.cpp:1853] Performed allocation for 1 agents in 207641ns I0312 15:30:45.401304 3109 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider b7fa933d-033f-4a00-9d37-519ae20e8b2c I0312 15:30:45.401568 3098 slave.cpp:8597] Handling resource provider message 'UPDATE_STATE: b7fa933d-033f-4a00-9d37-519ae20e8b2c {}' I0312 15:30:45.401607 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0312 15:30:45.401679 3098 slave.cpp:8717] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0312 15:30:45.401935 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0312 15:30:45.403048 3104 hierarchical.cpp:1110] Grew agent 765e56fd-033e-48dd-9319-420957c920d9-S0 by {} (total), { } (used) I0312 15:30:45.403481 3104 hierarchical.cpp:1067] Agent 765e56fd-033e-48dd-9319-420957c920d9-S0 (5083c546e440) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0312 15:30:45.408483 3101 hierarchical.cpp:1853] Performed allocation for 1 agents in 156111ns I0312 15:30:45.408954 3097 provider.cpp:790] Reconciling storage pools and volumes I0312 15:30:45.411031 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0312 15:30:45.411432 14675 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0312 15:30:45.422286 3096 slave.cpp:995] Agent terminating I0312 15:30:45.423103 3096 manager.cpp:127] Terminating resource provider b7fa933d-033f-4a00-9d37-519ae20e8b2c I0312 15:30:45.423511 3097 master.cpp:1292] Agent 765e56fd-033e-48dd-9319-420957c920d9-S0 at slave(1238)@172.17.0.2:35181 (5083c546e440) disconnected I0312 15:30:45.423552 3097 master.cpp:3361] Disconnecting agent 765e56fd-033e-48dd-9319-420957c920d9-S0 at slave(1238)@172.17.0.2:35181 (5083c546e440) I0312 15:30:45.423646 3097 master.cpp:3380] Deactivating agent 765e56fd-033e-48dd-9319-420957c920d9-S0 at slave(1238)@172.17.0.2:35181 (5083c546e440) I0312 15:30:45.423919 3104 hierarchical.cpp:1156] Agent 765e56fd-033e-48dd-9319-420957c920d9-S0 deactivated E0312 15:30:45.424170 3103 http_connection.hpp:449] End-Of-File received I0312 15:30:45.424649 3103 http_connection.hpp:217] Re-detecting endpoint I0312 15:30:45.425153 3103 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0312 15:30:45.425236 3100 provider.cpp:488] Disconnected from resource provider manager I0312 15:30:45.425282 3103 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0312 15:30:45.425362 3103 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35181/slave(1238)/api/v1/resource_provider I0312 15:30:45.425372 3111 status_update_manager_process.hpp:379] Pausing operation status update manager I0312 15:30:45.426785 3109 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 I0312 15:30:45.426856 3109 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.467090688secs I0312 15:30:45.427278 3109 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:45.428155 3100 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35181/slave(1238)/api/v1/resource_provider I0312 15:30:45.428870 3097 provider.cpp:476] Connected to resource provider manager I0312 15:30:45.429541 3103 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35181/slave(1238)/api/v1/resource_provider I0312 15:30:45.430397 3113 process.cpp:2781] Returning '404 Not Found' for '/slave(1238)/api/v1/resource_provider' E0312 15:30:45.431921 3108 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0312 15:30:45.455096 3099 hierarchical.cpp:1853] Performed allocation for 1 agents in 191933ns I0312 15:30:45.505151 3105 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0312 15:30:45.506604 3108 hierarchical.cpp:1853] Performed allocation for 1 agents in 218597ns I0312 15:30:45.506752 3109 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 I0312 15:30:45.509718 3097 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' I0312 15:30:45.509943 3097 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-Sas5z8/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:45.510165 3108 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:45.512887 3113 process.cpp:2781] Returning '404 Not Found' for '/slave(1238)/api/v1' I0312 15:30:45.524792 3096 master.cpp:1140] Master terminating I0312 15:30:45.525210 3106 hierarchical.cpp:1132] Removed all filters for agent 765e56fd-033e-48dd-9319-420957c920d9-S0 I0312 15:30:45.525241 3106 hierarchical.cpp:1008] Removed agent 765e56fd-033e-48dd-9319-420957c920d9-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (691 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 I0312 15:30:45.541194 3096 cluster.cpp:186] Creating default 'local' authorizer I0312 15:30:45.545821 3106 master.cpp:443] Master a1bd6366-5938-4fb3-b854-e044364efd3f (5083c546e440) started on 172.17.0.2:35181 I0312 15:30:45.545863 3106 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/oAiGGA/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/oAiGGA/master" --zk_session_timeout="10secs" I0312 15:30:45.546259 3106 master.cpp:495] Master only allowing authenticated frameworks to register I0312 15:30:45.546274 3106 master.cpp:501] Master only allowing authenticated agents to register I0312 15:30:45.546283 3106 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0312 15:30:45.546291 3106 credentials.hpp:37] Loading credentials for authentication from '/tmp/oAiGGA/credentials' I0312 15:30:45.546587 3106 master.cpp:551] Using default 'crammd5' authenticator I0312 15:30:45.546855 3106 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0312 15:30:45.547101 3106 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0312 15:30:45.547277 3106 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0312 15:30:45.547464 3106 master.cpp:632] Authorization enabled I0312 15:30:45.547854 3110 hierarchical.cpp:567] Initialized hierarchical allocator process I0312 15:30:45.547891 3111 whitelist_watcher.cpp:77] No whitelist given I0312 15:30:45.550671 3100 master.cpp:2165] Elected as the leading master! I0312 15:30:45.550707 3100 master.cpp:1661] Recovering from registrar I0312 15:30:45.550912 3103 registrar.cpp:339] Recovering registrar I0312 15:30:45.551667 3103 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0312 15:30:45.551841 3103 registrar.cpp:487] Applied 1 operations in 76971ns; attempting to update the registry I0312 15:30:45.552507 3103 registrar.cpp:544] Successfully updated the registry in 0ns I0312 15:30:45.552657 3103 registrar.cpp:416] Successfully recovered registrar I0312 15:30:45.553108 3110 master.cpp:1814] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0312 15:30:45.553130 3101 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover W0312 15:30:45.558732 3096 process.cpp:2877] Attempted to spawn already running process [email protected]:35181 I0312 15:30:45.560115 3096 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0312 15:30:45.560695 3096 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0312 15:30:45.560722 3096 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0312 15:30:45.560737 3096 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0312 15:30:45.560773 3096 provisioner.cpp:294] Using default backend 'copy' I0312 15:30:45.563438 3096 cluster.cpp:533] Creating default 'local' authorizer I0312 15:30:45.565804 3099 slave.cpp:274] Mesos agent started on (1239)@172.17.0.2:35181 I0312 15:30:45.565830 3099 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/oAiGGA/K9l5Qi/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/oAiGGA/K9l5Qi/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/oAiGGA/K9l5Qi/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/oAiGGA/K9l5Qi/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/oAiGGA/K9l5Qi/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/oAiGGA/K9l5Qi/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/oAiGGA/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_qpGHin" --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_qvBkKr" --zk_session_timeout="10secs" I0312 15:30:45.566275 3099 credentials.hpp:86] Loading credential for authentication from '/tmp/oAiGGA/K9l5Qi/credential' I0312 15:30:45.566437 3099 slave.cpp:307] Agent using credential for: test-principal I0312 15:30:45.566462 3099 credentials.hpp:37] Loading credentials for authentication from '/tmp/oAiGGA/K9l5Qi/http_credentials' I0312 15:30:45.566671 3099 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0312 15:30:45.567028 3099 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0312 15:30:45.568537 3099 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"}] I0312 15:30:45.568761 3099 slave.cpp:630] Agent attributes: [ ] I0312 15:30:45.568776 3099 slave.cpp:639] Agent hostname: 5083c546e440 I0312 15:30:45.568781 3104 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0312 15:30:45.568969 3105 status_update_manager_process.hpp:379] Pausing operation status update manager I0312 15:30:45.568998 3104 task_status_update_manager.cpp:181] Pausing sending task status updates I0312 15:30:45.570926 3097 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qvBkKr/meta' I0312 15:30:45.571221 3108 slave.cpp:7606] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qvBkKr/meta', beginning agent recovery I0312 15:30:45.571913 3111 task_status_update_manager.cpp:207] Recovering task status update manager I0312 15:30:45.572425 3110 containerizer.cpp:820] Recovering Mesos containers I0312 15:30:45.572868 3110 containerizer.cpp:1160] Recovering isolators I0312 15:30:45.573971 3107 containerizer.cpp:1199] Recovering provisioner I0312 15:30:45.574800 3101 provisioner.cpp:518] Provisioner recovery complete I0312 15:30:45.575738 3100 composing.cpp:339] Finished recovering all containerizers I0312 15:30:45.576128 3110 slave.cpp:8088] Recovering executors I0312 15:30:45.576265 3110 slave.cpp:8241] Finished recovery I0312 15:30:45.577270 3101 task_status_update_manager.cpp:181] Pausing sending task status updates I0312 15:30:45.577292 3103 slave.cpp:1454] New master detected at [email protected]:35181 I0312 15:30:45.577311 3112 status_update_manager_process.hpp:379] Pausing operation status update manager I0312 15:30:45.577378 3103 slave.cpp:1519] Detecting new master I0312 15:30:45.578027 3111 hierarchical.cpp:1853] Performed allocation for 0 agents in 127293ns I0312 15:30:45.581094 3109 slave.cpp:1546] Authenticating with master [email protected]:35181 I0312 15:30:45.581219 3109 slave.cpp:1555] Using default CRAM-MD5 authenticatee I0312 15:30:45.581580 3105 authenticatee.cpp:121] Creating new client SASL connection I0312 15:30:45.581923 3099 master.cpp:9676] Authenticating slave(1239)@172.17.0.2:35181 I0312 15:30:45.582079 3097 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2096)@172.17.0.2:35181 I0312 15:30:45.582408 3100 authenticator.cpp:98] Creating new server SASL connection I0312 15:30:45.582721 3102 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0312 15:30:45.582753 3102 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0312 15:30:45.582861 3102 authenticator.cpp:204] Received SASL authentication start I0312 15:30:45.582923 3102 authenticator.cpp:326] Authentication requires more steps I0312 15:30:45.583070 3107 authenticatee.cpp:259] Received SASL authentication step I0312 15:30:45.583238 3110 authenticator.cpp:232] Received SASL authentication step I0312 15:30:45.583281 3110 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5083c546e440' server FQDN: '5083c546e440' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0312 15:30:45.583299 3110 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0312 15:30:45.583350 3110 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0312 15:30:45.583385 3110 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5083c546e440' server FQDN: '5083c546e440' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0312 15:30:45.583403 3110 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0312 15:30:45.583415 3110 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0312 15:30:45.583434 3110 authenticator.cpp:318] Authentication success I0312 15:30:45.583566 3098 authenticatee.cpp:299] Authentication success I0312 15:30:45.583637 3101 master.cpp:9708] Successfully authenticated principal 'test-principal' at slave(1239)@172.17.0.2:35181 I0312 15:30:45.583662 3112 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2096)@172.17.0.2:35181 I0312 15:30:45.584152 3106 slave.cpp:1646] Successfully authenticated with master [email protected]:35181 I0312 15:30:45.584558 3106 slave.cpp:2096] Will retry registration in 18.719279ms if necessary I0312 15:30:45.584758 3105 master.cpp:6174] Received register agent message from slave(1239)@172.17.0.2:35181 (5083c546e440) I0312 15:30:45.585108 3105 master.cpp:3705] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0312 15:30:45.585811 3108 master.cpp:6241] Authorized registration of agent at slave(1239)@172.17.0.2:35181 (5083c546e440) I0312 15:30:45.585917 3108 master.cpp:6353] Registering agent at slave(1239)@172.17.0.2:35181 (5083c546e440) with id a1bd6366-5938-4fb3-b854-e044364efd3f-S0 I0312 15:30:45.586704 3107 registrar.cpp:487] Applied 1 operations in 265717ns; attempting to update the registry I0312 15:30:45.587517 3107 registrar.cpp:544] Successfully updated the registry in 730112ns I0312 15:30:45.587744 3101 master.cpp:6401] Admitted agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 at slave(1239)@172.17.0.2:35181 (5083c546e440) I0312 15:30:45.588631 3101 master.cpp:6446] Registered agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 at slave(1239)@172.17.0.2:35181 (5083c546e440) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0312 15:30:45.588713 3112 slave.cpp:1679] Registered with master [email protected]:35181; given agent ID a1bd6366-5938-4fb3-b854-e044364efd3f-S0 I0312 15:30:45.588866 3097 task_status_update_manager.cpp:188] Resuming sending task status updates I0312 15:30:45.588869 3098 hierarchical.cpp:959] Added agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 (5083c546e440) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0312 15:30:45.589205 3112 slave.cpp:1714] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qvBkKr/meta/slaves/a1bd6366-5938-4fb3-b854-e044364efd3f-S0/slave.info' I0312 15:30:45.589251 3098 hierarchical.cpp:1853] Performed allocation for 1 agents in 159251ns I0312 15:30:45.589284 3105 status_update_manager_process.hpp:385] Resuming operation status update manager I0312 15:30:45.590579 3112 slave.cpp:1766] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"NRYnc8luRyOyGOQudGuaBQ=="},"slave_id":{"value":"a1bd6366-5938-4fb3-b854-e044364efd3f-S0"},"update_oversubscribed_resources":false} I0312 15:30:45.591384 3103 master.cpp:7584] Ignoring update on agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 at slave(1239)@172.17.0.2:35181 (5083c546e440) as it reports no changes I0312 15:30:45.595139 3105 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1' I0312 15:30:45.596587 3103 http.cpp:1405] HTTP POST for /slave(1239)/api/v1 from 172.17.0.2:57482 I0312 15:30:45.597147 3103 http.cpp:2828] Processing GET_CONTAINERS call I0312 15:30:45.603065 3103 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:45.605607 3110 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1' I0312 15:30:45.606742 3111 http.cpp:1405] HTTP POST for /slave(1239)/api/v1 from 172.17.0.2:57484 I0312 15:30:45.607473 3111 http.cpp:3288] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:45.608551 3107 http.cpp:3392] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qvBkKr/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:45.629680 3106 hierarchical.cpp:1853] Performed allocation for 1 agents in 185664ns I0312 15:30:45.643741 3103 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:45.644476 3103 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 279040ns I0312 15:30:45.645354 3103 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qpGHin/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0312 15:30:45.645417 3103 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 942080ns I0312 15:30:45.648823 3108 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_MErYbw","--available_capacity=0B","--volumes=","--forward=unix:///tmp/oAiGGA/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_qvBkKr/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-Etszs1/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qvBkKr/containers/o rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="105" --pipe_write="106" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qpGHin/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0312 15:30:45.660965 3108 launcher.cpp:145] Forked child with pid '14687' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:45.661981 3108 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 16.552192ms I0312 15:30:45.663638 3108 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.656576ms I0312 15:30:45.664036 3103 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_qvBkKr/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:45.680912 3109 hierarchical.cpp:1853] Performed allocation for 1 agents in 156239ns I0312 15:30:45.684415 3101 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 20.671232ms I0312 15:30:45.686553 3106 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' I0312 15:30:45.686717 3106 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-Etszs1/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:45.731855 3098 hierarchical.cpp:1853] Performed allocation for 1 agents in 239107ns I0312 15:30:45.783879 3105 hierarchical.cpp:1853] Performed allocation for 1 agents in 233814ns I0312 15:30:45.835790 3112 hierarchical.cpp:1853] Performed allocation for 1 agents in 247080ns I0312 15:30:45.887135 3102 hierarchical.cpp:1853] Performed allocation for 1 agents in 189087ns I0312 15:30:45.938856 3109 hierarchical.cpp:1853] Performed allocation for 1 agents in 233101ns I0312 15:30:45.990574 3111 hierarchical.cpp:1853] Performed allocation for 1 agents in 207369ns I0312 15:30:45.997678 3097 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-Etszs1/endpoint.sock' with CSI v1 I0312 15:30:45.999671 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call I0312 15:30:46.002800 3106 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:46.005897 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call I0312 15:30:46.006506 3104 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1' I0312 15:30:46.008083 3109 http.cpp:1405] HTTP POST for /slave(1239)/api/v1 from 172.17.0.2:57486 I0312 15:30:46.008622 3109 http.cpp:3506] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:46.010320 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0312 15:30:46.010628 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0312 15:30:46.012563 3097 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {} I0312 15:30:46.013299 3097 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {} I0312 15:30:46.015591 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call I0312 15:30:46.019562 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call I0312 15:30:46.023308 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call I0312 15:30:46.025749 3099 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0312 15:30:46.025966 3103 status_update_manager_process.hpp:379] Pausing operation status update manager I0312 15:30:46.026312 3106 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35181/slave(1239)/api/v1/resource_provider I0312 15:30:46.029709 3104 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35181/slave(1239)/api/v1/resource_provider I0312 15:30:46.030452 3110 provider.cpp:476] Connected to resource provider manager I0312 15:30:46.031157 3099 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35181/slave(1239)/api/v1/resource_provider I0312 15:30:46.032469 3106 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1/resource_provider' I0312 15:30:46.034525 3100 http.cpp:1405] HTTP POST for /slave(1239)/api/v1/resource_provider from 172.17.0.2:57490 I0312 15:30:46.035292 3100 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_MErYbw","--available_capacity=0B","--volumes=","--forward=unix:///tmp/oAiGGA/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"} I0312 15:30:46.042273 3099 hierarchical.cpp:1853] Performed allocation for 1 agents in 188131ns I0312 15:30:46.069449 3106 slave.cpp:8597] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"31f8017c-489d-4fe5-ba06-31c51363ee2c"},"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_MErYbw","--available_capacity=0B","--volumes=","--forward=unix:///tmp/oAiGGA/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"}' I0312 15:30:46.071195 3097 provider.cpp:498] Received SUBSCRIBED event I0312 15:30:46.071249 3097 provider.cpp:1309] Subscribed with ID 31f8017c-489d-4fe5-ba06-31c51363ee2c I0312 15:30:46.072094 3110 status_update_manager_process.hpp:314] Recovering operation status update manager I0312 15:30:46.093269 3099 hierarchical.cpp:1853] Performed allocation for 1 agents in 140399ns I0312 15:30:46.127724 3108 provider.cpp:790] Reconciling storage pools and volumes I0312 15:30:46.130095 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0312 15:30:46.133030 3106 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 I0312 15:30:46.133349 3108 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:35181/slave(1239)/api/v1/resource_provider I0312 15:30:46.133399 3106 provider.cpp:748] Resource provider 31f8017c-489d-4fe5-ba06-31c51363ee2c is in READY state I0312 15:30:46.133455 3105 status_update_manager_process.hpp:385] Resuming operation status update manager I0312 15:30:46.134289 3112 provider.cpp:1235] Updating profiles { test } for resource provider 31f8017c-489d-4fe5-ba06-31c51363ee2c I0312 15:30:46.134585 3100 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1/resource_provider' I0312 15:30:46.135510 3109 provider.cpp:790] Reconciling storage pools and volumes I0312 15:30:46.136539 3111 http.cpp:1405] HTTP POST for /slave(1239)/api/v1/resource_provider from 172.17.0.2:57488 I0312 15:30:46.137030 3111 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 31f8017c-489d-4fe5-ba06-31c51363ee2c I0312 15:30:46.137202 3097 slave.cpp:8597] Handling resource provider message 'UPDATE_STATE: 31f8017c-489d-4fe5-ba06-31c51363ee2c {}' I0312 15:30:46.137295 3097 slave.cpp:8717] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0312 15:30:46.137913 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0312 15:30:46.138687 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0312 15:30:46.138957 3098 hierarchical.cpp:1110] Grew agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 by {} (total), { } (used) I0312 15:30:46.139485 3098 hierarchical.cpp:1067] Agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 (5083c546e440) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0312 15:30:46.144563 3109 hierarchical.cpp:1853] Performed allocation for 1 agents in 243854ns I0312 15:30:46.144968 3106 provider.cpp:790] Reconciling storage pools and volumes I0312 15:30:46.147001 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0312 15:30:46.147496 14691 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0312 15:30:46.158295 3096 slave.cpp:995] Agent terminating I0312 15:30:46.159142 3096 manager.cpp:127] Terminating resource provider 31f8017c-489d-4fe5-ba06-31c51363ee2c I0312 15:30:46.159637 3108 master.cpp:1292] Agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 at slave(1239)@172.17.0.2:35181 (5083c546e440) disconnected I0312 15:30:46.159680 3108 master.cpp:3361] Disconnecting agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 at slave(1239)@172.17.0.2:35181 (5083c546e440) I0312 15:30:46.159766 3108 master.cpp:3380] Deactivating agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 at slave(1239)@172.17.0.2:35181 (5083c546e440) I0312 15:30:46.159931 3103 hierarchical.cpp:1156] Agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 deactivated E0312 15:30:46.160177 3100 http_connection.hpp:449] End-Of-File received I0312 15:30:46.160821 3100 http_connection.hpp:217] Re-detecting endpoint I0312 15:30:46.161334 3100 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0312 15:30:46.161420 3100 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0312 15:30:46.161475 3105 provider.cpp:488] Disconnected from resource provider manager I0312 15:30:46.161530 3100 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:35181/slave(1239)/api/v1/resource_provider I0312 15:30:46.161644 3102 status_update_manager_process.hpp:379] Pausing operation status update manager I0312 15:30:46.163147 3109 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 I0312 15:30:46.163208 3109 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.478912secs I0312 15:30:46.163663 3109 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:46.165108 3105 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:35181/slave(1239)/api/v1/resource_provider I0312 15:30:46.165797 3108 provider.cpp:476] Connected to resource provider manager I0312 15:30:46.166462 3099 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:35181/slave(1239)/api/v1/resource_provider I0312 15:30:46.167403 3113 process.cpp:2781] Returning '404 Not Found' for '/slave(1239)/api/v1/resource_provider' E0312 15:30:46.168999 3107 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0312 15:30:46.191097 3106 hierarchical.cpp:1853] Performed allocation for 1 agents in 192589ns I0312 15:30:46.241246 3103 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0312 15:30:46.242671 3101 hierarchical.cpp:1853] Performed allocation for 1 agents in 123279ns I0312 15:30:46.243240 3109 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 I0312 15:30:46.246315 3107 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' I0312 15:30:46.246595 3104 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-Etszs1/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0312 15:30:46.246888 3111 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0312 15:30:46.250000 3113 process.cpp:2781] Returning '404 Not Found' for '/slave(1239)/api/v1' I0312 15:30:46.261664 3096 master.cpp:1140] Master terminating I0312 15:30:46.262034 3105 hierarchical.cpp:1132] Removed all filters for agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 I0312 15:30:46.262063 3105 hierarchical.cpp:1008] Removed agent a1bd6366-5938-4fb3-b854-e044364efd3f-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (735 ms) [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (98972 ms total) [----------] Global test environment tear-down [==========] 2312 tests from 223 test cases ran. (1139066 ms total) [ PASSED ] 2311 tests. [ FAILED ] 1 test, listed below: [ FAILED ] OversubscriptionTest.FixedResourceEstimator 1 FAILED TEST YOU HAVE 34 DISABLED TESTS I0312 15:30:46.351524 3113 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:785: 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:991: 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/7963/console - Mesos Reviewbot On March 4, 2020, 10:56 a.m., Andrei Budnik wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/72190/ > ----------------------------------------------------------- > > (Updated March 4, 2020, 10:56 a.m.) > > > Review request for mesos, Greg Mann and Qian Zhang. > > > Repository: mesos > > > Description > ------- > > Added a test `LaunchNestedShareCgroups`. > > > Diffs > ----- > > src/tests/containerizer/nested_mesos_containerizer_tests.cpp > c6f96e6b1bc0d9989ca87d23e112604820ac1d51 > > > Diff: https://reviews.apache.org/r/72190/diff/2/ > > > Testing > ------- > > > Thanks, > > Andrei Budnik > >
