----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/72068/#review219443 -----------------------------------------------------------
Bad patch! Reviews applied: [72056, 72064, 72065, 72066, 72067, 72068] 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_72068"] Error: ...<truncated>... nt 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:14.904318 3141 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:40819/slave(1249)/api/v1/resource_provider I0130 23:47:14.905791 3150 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I0130 23:47:14.909590 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.711672ms I0130 23:47:14.910320 3145 master.cpp:9974] Sending offers [ 971bbe49-9d06-44b0-bede-888f75d3b35d-O3 ] to framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 I0130 23:47:14.911221 3142 sched.cpp:934] Scheduler::resourceOffers took 102673ns I0130 23:47:14.914903 3143 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0130 23:47:14.916847 3149 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:51758 I0130 23:47:14.917249 3149 http.cpp:277] Processing call CREATE_VOLUMES I0130 23:47:14.918244 3149 master.cpp:3712] Authorizing principal 'test-principal' to perform action CREATE_VOLUME on object {"value":"storage/default-role","resource":{"provider_id":{"value":"b2227d66-f5e1-4683-8e28-849b149e1446"},"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":"79b8b41d-9a30-4260-8026-840de47897a1","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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283","profile":"test"}}}} I0130 23:47:14.919992 3142 sched.cpp:960] Rescinded offer 971bbe49-9d06-44b0-bede-888f75d3b35d-O3 I0130 23:47:14.920091 3142 sched.cpp:971] Scheduler::offerRescinded took 28965ns I0130 23:47:14.920533 3144 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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283,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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283,test)]:2048, offered or allocated: {}) on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 from framework 971bb e49-9d06-44b0-bede-888f75d3b35d-0000 I0130 23:47:14.920750 3151 master.cpp:12273] Removing offer 971bbe49-9d06-44b0-bede-888f75d3b35d-O3 I0130 23:47:14.921928 3144 hierarchical.cpp:1625] Framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 filtered agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 for 5secs I0130 23:47:14.924556 3148 master.cpp:12138] Sending operation '' (uuid: f182bc6f-30d0-4ffb-9056-488b9c0a9824) to agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 at slave(1249)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:14.925266 3148 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version I0130 23:47:14.928223 3143 provider.cpp:498] Received APPLY_OPERATION event I0130 23:47:14.928273 3143 provider.cpp:1351] Received CREATE operation '' (uuid: f182bc6f-30d0-4ffb-9056-488b9c0a9824) I0130 23:47:14.932937 3154 master.cpp:5958] Processing REVIVE call for framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 I0130 23:47:14.933447 3141 hierarchical.cpp:1721] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 I0130 23:47:14.935186 3141 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.533902ms I0130 23:47:14.935585 3141 hierarchical.cpp:1853] Performed allocation for 1 agents in 164824ns I0130 23:47:14.935981 3156 master.cpp:9974] Sending offers [ 971bbe49-9d06-44b0-bede-888f75d3b35d-O4 ] to framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 I0130 23:47:14.936688 3150 sched.cpp:934] Scheduler::resourceOffers took 84041ns I0130 23:47:14.948565 3151 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:51752 I0130 23:47:14.949878 3142 slave.cpp:8559] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: e36798d1-6306-4ff4-b757-047a55362505) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0130 23:47:14.950294 3142 slave.cpp:9012] Updating the state of operation with no ID (uuid: e36798d1-6306-4ff4-b757-047a55362505) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0130 23:47:14.950373 3142 slave.cpp:8766] Forwarding status update of operation with no ID (operation_uuid: e36798d1-6306-4ff4-b757-047a55362505) for an operator API call I0130 23:47:14.950943 3144 master.cpp:11790] Updating the state of operation '' (uuid: e36798d1-6306-4ff4-b757-047a55362505) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0130 23:47:14.951611 3154 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version I0130 23:47:15.045740 3142 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 24e991f9-ca3c-498a-b168-2118eb8e2a81) for operation UUID f182bc6f-30d0-4ffb-9056-488b9c0a9824 on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:15.045958 3143 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0130 23:47:15.046025 3142 status_update_manager_process.hpp:414] Creating operation status update stream f182bc6f-30d0-4ffb-9056-488b9c0a9824 checkpoint=true I0130 23:47:15.046520 3142 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 24e991f9-ca3c-498a-b168-2118eb8e2a81) for operation UUID f182bc6f-30d0-4ffb-9056-488b9c0a9824 on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:15.371263 3142 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 24e991f9-ca3c-498a-b168-2118eb8e2a81) for operation UUID f182bc6f-30d0-4ffb-9056-488b9c0a9824 on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:15.371832 3142 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: c9958d5a-f8ed-46ba-9521-38f43a38e213) for stream e36798d1-6306-4ff4-b757-047a55362505 I0130 23:47:15.371912 3142 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: c9958d5a-f8ed-46ba-9521-38f43a38e213) for operation UUID e36798d1-6306-4ff4-b757-047a55362505 on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:15.372704 3144 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:40819/slave(1249)/api/v1/resource_provider I0130 23:47:15.374135 3146 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I0130 23:47:15.416574 3145 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:51752 I0130 23:47:15.418298 3151 slave.cpp:8559] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: f182bc6f-30d0-4ffb-9056-488b9c0a9824) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0130 23:47:15.418602 3151 slave.cpp:9012] Updating the state of operation with no ID (uuid: f182bc6f-30d0-4ffb-9056-488b9c0a9824) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0130 23:47:15.418668 3151 slave.cpp:8766] Forwarding status update of operation with no ID (operation_uuid: f182bc6f-30d0-4ffb-9056-488b9c0a9824) for an operator API call I0130 23:47:15.419136 3143 master.cpp:11790] Updating the state of operation '' (uuid: f182bc6f-30d0-4ffb-9056-488b9c0a9824) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0130 23:47:15.419781 3144 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version I0130 23:47:15.421588 3149 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0130 23:47:15.442332 3142 status_update_manager_process.hpp:490] Cleaning up operation status update stream e36798d1-6306-4ff4-b757-047a55362505 I0130 23:47:15.442713 3142 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 24e991f9-ca3c-498a-b168-2118eb8e2a81) for stream f182bc6f-30d0-4ffb-9056-488b9c0a9824 I0130 23:47:15.442854 3142 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 24e991f9-ca3c-498a-b168-2118eb8e2a81) for operation UUID f182bc6f-30d0-4ffb-9056-488b9c0a9824 on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:15.521559 3142 status_update_manager_process.hpp:490] Cleaning up operation status update stream f182bc6f-30d0-4ffb-9056-488b9c0a9824 I0130 23:47:15.575922 3156 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0130 23:47:15.577975 3155 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:51760 I0130 23:47:15.578310 3155 http.cpp:277] Processing call DESTROY_VOLUMES I0130 23:47:15.579442 3155 master.cpp:3712] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"b2227d66-f5e1-4683-8e28-849b149e1446"},"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":"79b8b41d-9a30-4260-8026-840de47897a1","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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283","profile":"test"}}}} I0130 23:47:15.581552 3153 sched.cpp:960] Rescinded offer 971bbe49-9d06-44b0-bede-888f75d3b35d-O4 I0130 23:47:15.581692 3153 sched.cpp:971] Scheduler::offerRescinded took 64542ns I0130 23:47:15.582356 3149 master.cpp:12273] Removing offer 971bbe49-9d06-44b0-bede-888f75d3b35d-O4 I0130 23:47:15.582309 3146 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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283,test),79b8b41d-9a30-4260-8026-840de47897a1: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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283,test),79b8b41d-9a30-4260-8026-840de47897a1:volume]:2048, offered or allocated: {}) on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 from framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 I0130 23:47:15.584532 3146 hierarchical.cpp:1625] Framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 filtered agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 for 5secs I0130 23:47:15.587913 3156 master.cpp:12138] Sending operation '' (uuid: 00832d1d-9575-4bb3-8523-c742a72f10ee) to agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 at slave(1249)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:15.588665 3150 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version I0130 23:47:15.592330 3154 provider.cpp:498] Received APPLY_OPERATION event I0130 23:47:15.592381 3154 provider.cpp:1351] Received DESTROY operation '' (uuid: 00832d1d-9575-4bb3-8523-c742a72f10ee) I0130 23:47:15.596572 3141 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.211995ms I0130 23:47:15.597295 3156 master.cpp:9974] Sending offers [ 971bbe49-9d06-44b0-bede-888f75d3b35d-O5 ] to framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 I0130 23:47:15.597995 3148 sched.cpp:934] Scheduler::resourceOffers took 82658ns I0130 23:47:15.706378 3144 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: e085651d-faaf-43f2-b448-8b48152662c5) for operation UUID 00832d1d-9575-4bb3-8523-c742a72f10ee on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:15.706509 3144 status_update_manager_process.hpp:414] Creating operation status update stream 00832d1d-9575-4bb3-8523-c742a72f10ee checkpoint=true I0130 23:47:15.706773 3144 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: e085651d-faaf-43f2-b448-8b48152662c5) for operation UUID 00832d1d-9575-4bb3-8523-c742a72f10ee on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:15.798543 3144 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: e085651d-faaf-43f2-b448-8b48152662c5) for operation UUID 00832d1d-9575-4bb3-8523-c742a72f10ee on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:15.799554 3150 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:40819/slave(1249)/api/v1/resource_provider I0130 23:47:15.800887 3155 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I0130 23:47:15.804203 3143 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0130 23:47:15.805927 3154 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:51762 I0130 23:47:15.806196 3154 http.cpp:277] Processing call UNRESERVE_RESOURCES I0130 23:47:15.806995 3154 master.cpp:3712] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"b2227d66-f5e1-4683-8e28-849b149e1446"},"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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283","profile":"test"}}}} I0130 23:47:15.808471 3155 sched.cpp:960] Rescinded offer 971bbe49-9d06-44b0-bede-888f75d3b35d-O5 I0130 23:47:15.808568 3155 sched.cpp:971] Scheduler::offerRescinded took 28043ns I0130 23:47:15.809052 3149 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283,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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283,test)]:2048, offered or allocated: {}) on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 from framework 971bb e49-9d06-44b0-bede-888f75d3b35d-0000 I0130 23:47:15.809242 3151 master.cpp:12273] Removing offer 971bbe49-9d06-44b0-bede-888f75d3b35d-O5 I0130 23:47:15.810789 3149 hierarchical.cpp:1625] Framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 filtered agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 for 5secs I0130 23:47:15.813308 3143 master.cpp:12138] Sending operation '' (uuid: bcade8a1-b2b1-477a-854a-677f0ee92a46) to agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 at slave(1249)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:15.813947 3156 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version I0130 23:47:15.816751 3153 provider.cpp:498] Received APPLY_OPERATION event I0130 23:47:15.816812 3153 provider.cpp:1351] Received UNRESERVE operation '' (uuid: bcade8a1-b2b1-477a-854a-677f0ee92a46) I0130 23:47:15.825402 3141 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.269843ms I0130 23:47:15.826293 3143 master.cpp:9974] Sending offers [ 971bbe49-9d06-44b0-bede-888f75d3b35d-O6 ] to framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 I0130 23:47:15.827131 3148 sched.cpp:934] Scheduler::resourceOffers took 85672ns I0130 23:47:15.848522 3144 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:51752 I0130 23:47:15.850076 3155 slave.cpp:8559] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 00832d1d-9575-4bb3-8523-c742a72f10ee) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0130 23:47:15.850317 3155 slave.cpp:9012] Updating the state of operation with no ID (uuid: 00832d1d-9575-4bb3-8523-c742a72f10ee) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0130 23:47:15.850374 3155 slave.cpp:8766] Forwarding status update of operation with no ID (operation_uuid: 00832d1d-9575-4bb3-8523-c742a72f10ee) for an operator API call I0130 23:47:15.850760 3150 master.cpp:11790] Updating the state of operation '' (uuid: 00832d1d-9575-4bb3-8523-c742a72f10ee) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0130 23:47:15.851419 3149 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version I0130 23:47:15.917531 3155 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: a0217595-ebaa-4acd-9f9a-36bb454915a8) for operation UUID bcade8a1-b2b1-477a-854a-677f0ee92a46 on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:15.917642 3155 status_update_manager_process.hpp:414] Creating operation status update stream bcade8a1-b2b1-477a-854a-677f0ee92a46 checkpoint=true I0130 23:47:15.917716 3153 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0130 23:47:15.917997 3155 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: a0217595-ebaa-4acd-9f9a-36bb454915a8) for operation UUID bcade8a1-b2b1-477a-854a-677f0ee92a46 on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:16.000409 3155 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: a0217595-ebaa-4acd-9f9a-36bb454915a8) for operation UUID bcade8a1-b2b1-477a-854a-677f0ee92a46 on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:16.001333 3155 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: e085651d-faaf-43f2-b448-8b48152662c5) for stream 00832d1d-9575-4bb3-8523-c742a72f10ee I0130 23:47:16.001482 3155 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: e085651d-faaf-43f2-b448-8b48152662c5) for operation UUID 00832d1d-9575-4bb3-8523-c742a72f10ee on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:16.002260 3150 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:40819/slave(1249)/api/v1/resource_provider I0130 23:47:16.004256 3143 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I0130 23:47:16.052898 3154 http.cpp:1405] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:51752 I0130 23:47:16.054697 3144 slave.cpp:8559] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: bcade8a1-b2b1-477a-854a-677f0ee92a46) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0130 23:47:16.054983 3144 slave.cpp:9012] Updating the state of operation with no ID (uuid: bcade8a1-b2b1-477a-854a-677f0ee92a46) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0130 23:47:16.055047 3144 slave.cpp:8766] Forwarding status update of operation with no ID (operation_uuid: bcade8a1-b2b1-477a-854a-677f0ee92a46) for an operator API call I0130 23:47:16.055625 3153 master.cpp:11790] Updating the state of operation '' (uuid: bcade8a1-b2b1-477a-854a-677f0ee92a46) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0130 23:47:16.056347 3150 slave.cpp:4428] Ignoring new checkpointed resources and operations identical to the current version I0130 23:47:16.058122 3146 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0130 23:47:16.058883 3155 status_update_manager_process.hpp:490] Cleaning up operation status update stream 00832d1d-9575-4bb3-8523-c742a72f10ee I0130 23:47:16.059183 3155 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: a0217595-ebaa-4acd-9f9a-36bb454915a8) for stream bcade8a1-b2b1-477a-854a-677f0ee92a46 I0130 23:47:16.059293 3155 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: a0217595-ebaa-4acd-9f9a-36bb454915a8) for operation UUID bcade8a1-b2b1-477a-854a-677f0ee92a46 on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:16.101584 3155 status_update_manager_process.hpp:490] Cleaning up operation status update stream bcade8a1-b2b1-477a-854a-677f0ee92a46 I0130 23:47:16.153246 3141 master.cpp:1414] Framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 disconnected I0130 23:47:16.153331 3141 master.cpp:3333] Deactivating framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 I0130 23:47:16.153856 3143 hierarchical.cpp:813] Deactivated framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 I0130 23:47:16.154584 3155 slave.cpp:989] Agent terminating I0130 23:47:16.154742 3156 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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283,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_bKXUj5/2GB-bf0b488b-d3f9-4c91-9ca1-017d27a4b283,test)]:2048, offered or allocated: {}) on agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 from framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 I0130 23:47:16.155016 3141 master.cpp:12273] Removing offer 971bbe49-9d06-44b0-bede-888f75d3b35d-O6 I0130 23:47:16.155223 3141 master.cpp:3310] Disconnecting framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 I0130 23:47:16.155314 3141 master.cpp:1429] Giving framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 0ns to failover I0130 23:47:16.155452 3155 manager.cpp:127] Terminating resource provider b2227d66-f5e1-4683-8e28-849b149e1446 I0130 23:47:16.156117 3152 master.cpp:1299] Agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 at slave(1249)@172.17.0.2:40819 (11de8f60f6d8) disconnected I0130 23:47:16.156221 3152 master.cpp:3368] Disconnecting agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 at slave(1249)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:16.156324 3152 master.cpp:3387] Deactivating agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 at slave(1249)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:16.156841 3156 hierarchical.cpp:1156] Agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 deactivated I0130 23:47:16.157073 3156 master.cpp:9760] Framework failover timeout, removing framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 I0130 23:47:16.157112 3156 master.cpp:10762] Removing framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 (default) at [email protected]:40819 I0130 23:47:16.157641 3150 hierarchical.cpp:1777] Allocation paused E0130 23:47:16.157712 3148 http_connection.hpp:449] End-Of-File received I0130 23:47:16.158210 3150 hierarchical.cpp:757] Removed framework 971bbe49-9d06-44b0-bede-888f75d3b35d-0000 I0130 23:47:16.158360 3148 http_connection.hpp:217] Re-detecting endpoint I0130 23:47:16.158361 3152 hierarchical.cpp:1787] Allocation resumed I0130 23:47:16.159373 3148 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0130 23:47:16.159440 3148 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0130 23:47:16.159520 3148 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:40819/slave(1249)/api/v1/resource_provider I0130 23:47:16.160009 3154 provider.cpp:488] Disconnected from resource provider manager I0130 23:47:16.160192 3143 status_update_manager_process.hpp:379] Pausing operation status update manager I0130 23:47:16.161180 3150 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 I0130 23:47:16.161267 3150 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 2.87108288secs I0130 23:47:16.161782 3150 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:16.163270 3142 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:40819/slave(1249)/api/v1/resource_provider I0130 23:47:16.167093 3148 provider.cpp:476] Connected to resource provider manager I0130 23:47:16.167855 3155 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:40819/slave(1249)/api/v1/resource_provider I0130 23:47:16.168512 3152 hierarchical.cpp:1853] Performed allocation for 1 agents in 225682ns E0130 23:47:16.168792 3154 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Cannot process 'SUBSCRIBE' call as the driver is in state SUBSCRIBING I0130 23:47:16.169668 3157 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1/resource_provider' E0130 23:47:16.171078 3142 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0130 23:47:16.220460 3156 hierarchical.cpp:1853] Performed allocation for 1 agents in 252339ns I0130 23:47:16.269562 3148 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0130 23:47:16.271466 3145 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 I0130 23:47:16.271986 3143 hierarchical.cpp:1853] Performed allocation for 1 agents in 168726ns I0130 23:47:16.274866 3150 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' I0130 23:47:16.275095 3141 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-D2vKgb/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:16.275316 3145 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:16.277801 3157 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1' I0130 23:47:16.289194 3140 master.cpp:1140] Master terminating I0130 23:47:16.290220 3150 hierarchical.cpp:1132] Removed all filters for agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 I0130 23:47:16.290246 3150 hierarchical.cpp:1008] Removed agent 971bbe49-9d06-44b0-bede-888f75d3b35d-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2763 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 I0130 23:47:16.312127 3140 cluster.cpp:180] Creating default 'local' authorizer I0130 23:47:16.316972 3150 master.cpp:443] Master 749899c3-ec6c-4ae7-92ac-066d0562af9c (11de8f60f6d8) started on 172.17.0.2:40819 I0130 23:47:16.316999 3150 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/HZeib3/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/HZeib3/master" --zk_session_timeout="10secs" I0130 23:47:16.317338 3150 master.cpp:495] Master only allowing authenticated frameworks to register I0130 23:47:16.317355 3150 master.cpp:501] Master only allowing authenticated agents to register I0130 23:47:16.317363 3150 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0130 23:47:16.317373 3150 credentials.hpp:37] Loading credentials for authentication from '/tmp/HZeib3/credentials' I0130 23:47:16.317656 3150 master.cpp:551] Using default 'crammd5' authenticator I0130 23:47:16.317890 3150 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0130 23:47:16.318131 3150 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0130 23:47:16.318323 3150 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0130 23:47:16.318531 3150 master.cpp:632] Authorization enabled I0130 23:47:16.318922 3144 whitelist_watcher.cpp:77] No whitelist given I0130 23:47:16.318930 3153 hierarchical.cpp:567] Initialized hierarchical allocator process I0130 23:47:16.321987 3149 master.cpp:2172] Elected as the leading master! I0130 23:47:16.322021 3149 master.cpp:1668] Recovering from registrar I0130 23:47:16.322219 3145 registrar.cpp:339] Recovering registrar I0130 23:47:16.323056 3145 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0130 23:47:16.323186 3145 registrar.cpp:487] Applied 1 operations in 42561ns; attempting to update the registry I0130 23:47:16.323848 3145 registrar.cpp:544] Successfully updated the registry in 0ns I0130 23:47:16.323979 3145 registrar.cpp:416] Successfully recovered registrar I0130 23:47:16.324432 3153 master.cpp:1821] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0130 23:47:16.324486 3154 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover W0130 23:47:16.330263 3140 process.cpp:2877] Attempted to spawn already running process [email protected]:40819 I0130 23:47:16.331697 3140 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0130 23:47:16.332306 3140 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0130 23:47:16.332335 3140 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0130 23:47:16.332351 3140 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0130 23:47:16.332383 3140 provisioner.cpp:294] Using default backend 'copy' I0130 23:47:16.335098 3140 cluster.cpp:527] Creating default 'local' authorizer I0130 23:47:16.337507 3152 slave.cpp:270] Mesos agent started on (1250)@172.17.0.2:40819 I0130 23:47:16.337538 3152 slave.cpp:271] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/HZeib3/tWblB8/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/HZeib3/tWblB8/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/HZeib3/tWblB8/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/HZeib3/tWblB8/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/HZeib3/tWblB8/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/HZeib3/tWblB8/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/HZeib3/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_hpcvJR" --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_VKPFRA" --zk_session_timeout="10secs" I0130 23:47:16.338232 3152 credentials.hpp:86] Loading credential for authentication from '/tmp/HZeib3/tWblB8/credential' I0130 23:47:16.338459 3152 slave.cpp:303] Agent using credential for: test-principal I0130 23:47:16.338492 3152 credentials.hpp:37] Loading credentials for authentication from '/tmp/HZeib3/tWblB8/http_credentials' I0130 23:47:16.338788 3152 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0130 23:47:16.339318 3152 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0130 23:47:16.340968 3150 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0130 23:47:16.341293 3152 slave.cpp:618] 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"}] I0130 23:47:16.341560 3152 slave.cpp:626] Agent attributes: [ ] I0130 23:47:16.341579 3152 slave.cpp:635] Agent hostname: 11de8f60f6d8 I0130 23:47:16.341790 3141 status_update_manager_process.hpp:379] Pausing operation status update manager I0130 23:47:16.341833 3149 task_status_update_manager.cpp:181] Pausing sending task status updates I0130 23:47:16.343605 3147 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_VKPFRA/meta' I0130 23:47:16.343921 3155 slave.cpp:7568] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_VKPFRA/meta', beginning agent recovery I0130 23:47:16.344609 3144 task_status_update_manager.cpp:207] Recovering task status update manager I0130 23:47:16.345105 3154 containerizer.cpp:820] Recovering Mesos containers I0130 23:47:16.345510 3154 containerizer.cpp:1160] Recovering isolators I0130 23:47:16.346693 3142 containerizer.cpp:1199] Recovering provisioner I0130 23:47:16.347579 3145 provisioner.cpp:518] Provisioner recovery complete I0130 23:47:16.348137 3151 hierarchical.cpp:1853] Performed allocation for 0 agents in 119664ns I0130 23:47:16.348476 3143 composing.cpp:339] Finished recovering all containerizers I0130 23:47:16.348830 3141 slave.cpp:8050] Recovering executors I0130 23:47:16.348945 3141 slave.cpp:8203] Finished recovery I0130 23:47:16.349799 3147 task_status_update_manager.cpp:181] Pausing sending task status updates I0130 23:47:16.349831 3145 status_update_manager_process.hpp:379] Pausing operation status update manager I0130 23:47:16.349860 3142 slave.cpp:1416] New master detected at [email protected]:40819 I0130 23:47:16.350018 3142 slave.cpp:1481] Detecting new master I0130 23:47:16.353407 3146 slave.cpp:1508] Authenticating with master [email protected]:40819 I0130 23:47:16.353525 3146 slave.cpp:1517] Using default CRAM-MD5 authenticatee I0130 23:47:16.353880 3156 authenticatee.cpp:121] Creating new client SASL connection I0130 23:47:16.354249 3148 master.cpp:10159] Authenticating slave(1250)@172.17.0.2:40819 I0130 23:47:16.354416 3144 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2109)@172.17.0.2:40819 I0130 23:47:16.354751 3151 authenticator.cpp:98] Creating new server SASL connection I0130 23:47:16.355048 3143 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0130 23:47:16.355090 3143 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0130 23:47:16.355226 3154 authenticator.cpp:204] Received SASL authentication start I0130 23:47:16.355307 3154 authenticator.cpp:326] Authentication requires more steps I0130 23:47:16.355463 3153 authenticatee.cpp:259] Received SASL authentication step I0130 23:47:16.355624 3155 authenticator.cpp:232] Received SASL authentication step I0130 23:47:16.355679 3155 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '11de8f60f6d8' server FQDN: '11de8f60f6d8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0130 23:47:16.355708 3155 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0130 23:47:16.355764 3155 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0130 23:47:16.355801 3155 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '11de8f60f6d8' server FQDN: '11de8f60f6d8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0130 23:47:16.355819 3155 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0130 23:47:16.355834 3155 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0130 23:47:16.355855 3155 authenticator.cpp:318] Authentication success I0130 23:47:16.355975 3141 authenticatee.cpp:299] Authentication success I0130 23:47:16.356077 3149 master.cpp:10191] Successfully authenticated principal 'test-principal' at slave(1250)@172.17.0.2:40819 I0130 23:47:16.356123 3147 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2109)@172.17.0.2:40819 I0130 23:47:16.356402 3145 slave.cpp:1608] Successfully authenticated with master [email protected]:40819 I0130 23:47:16.356837 3145 slave.cpp:2058] Will retry registration in 9.73146ms if necessary I0130 23:47:16.357028 3156 master.cpp:6629] Received register agent message from slave(1250)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:16.357476 3156 master.cpp:3712] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0130 23:47:16.358220 3143 master.cpp:6696] Authorized registration of agent at slave(1250)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:16.358328 3143 master.cpp:6808] Registering agent at slave(1250)@172.17.0.2:40819 (11de8f60f6d8) with id 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 I0130 23:47:16.359094 3153 registrar.cpp:487] Applied 1 operations in 262339ns; attempting to update the registry I0130 23:47:16.359987 3153 registrar.cpp:544] Successfully updated the registry in 819968ns I0130 23:47:16.360194 3152 master.cpp:6856] Admitted agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 at slave(1250)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:16.361057 3152 master.cpp:6901] Registered agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 at slave(1250)@172.17.0.2:40819 (11de8f60f6d8) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0130 23:47:16.361124 3147 slave.cpp:1641] Registered with master [email protected]:40819; given agent ID 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 I0130 23:47:16.361240 3156 task_status_update_manager.cpp:188] Resuming sending task status updates I0130 23:47:16.361263 3145 hierarchical.cpp:959] Added agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 (11de8f60f6d8) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0130 23:47:16.361589 3147 slave.cpp:1676] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_VKPFRA/meta/slaves/749899c3-ec6c-4ae7-92ac-066d0562af9c-S0/slave.info' I0130 23:47:16.361616 3145 hierarchical.cpp:1853] Performed allocation for 1 agents in 163196ns I0130 23:47:16.361657 3151 status_update_manager_process.hpp:385] Resuming operation status update manager I0130 23:47:16.362824 3147 slave.cpp:1728] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"Q85FgcOgSDiQSc7qILfqfw=="},"slave_id":{"value":"749899c3-ec6c-4ae7-92ac-066d0562af9c-S0"},"update_oversubscribed_resources":false} I0130 23:47:16.363667 3141 master.cpp:8039] Ignoring update on agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 at slave(1250)@172.17.0.2:40819 (11de8f60f6d8) as it reports no changes I0130 23:47:16.367827 3151 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1' I0130 23:47:16.369293 3150 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:51770 I0130 23:47:16.369969 3150 http.cpp:2928] Processing GET_CONTAINERS call I0130 23:47:16.376168 3150 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:16.379014 3155 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1' I0130 23:47:16.380115 3149 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:51772 I0130 23:47:16.380939 3149 http.cpp:3388] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:16.381959 3143 http.cpp:3492] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_VKPFRA/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:16.399353 3142 hierarchical.cpp:1853] Performed allocation for 1 agents in 182024ns I0130 23:47:16.403215 3150 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:16.404088 3150 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 381184ns I0130 23:47:16.404891 3150 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hpcvJR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0130 23:47:16.404940 3150 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 854784ns I0130 23:47:16.408476 3145 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_jeCRZj","--available_capacity=0B","--volumes=","--forward=unix:///tmp/HZeib3/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_VKPFRA/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-MEwnte/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_VKPFRA/containers/o rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="107" --pipe_write="108" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hpcvJR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0130 23:47:16.419045 3145 launcher.cpp:145] Forked child with pid '14624' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:16.420047 3145 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 15.087104ms I0130 23:47:16.421653 3145 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.614848ms I0130 23:47:16.422183 3153 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_VKPFRA/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:16.442112 3152 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.43904ms I0130 23:47:16.444243 3141 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' I0130 23:47:16.444391 3142 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-MEwnte/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:16.451082 3145 hierarchical.cpp:1853] Performed allocation for 1 agents in 186245ns I0130 23:47:16.502279 3154 hierarchical.cpp:1853] Performed allocation for 1 agents in 219297ns I0130 23:47:16.553711 3146 hierarchical.cpp:1853] Performed allocation for 1 agents in 214010ns I0130 23:47:16.605564 3154 hierarchical.cpp:1853] Performed allocation for 1 agents in 168429ns I0130 23:47:16.656627 3144 hierarchical.cpp:1853] Performed allocation for 1 agents in 201321ns I0130 23:47:16.707831 3147 hierarchical.cpp:1853] Performed allocation for 1 agents in 200335ns I0130 23:47:16.759220 3141 hierarchical.cpp:1853] Performed allocation for 1 agents in 191519ns I0130 23:47:16.775305 3146 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-MEwnte/endpoint.sock' with CSI v1 I0130 23:47:16.777940 3150 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-MEwnte/endpoint.sock' with CSI v0 I0130 23:47:16.779201 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/Probe call I0130 23:47:16.782130 3155 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:16.785033 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginCapabilities call I0130 23:47:16.785630 3146 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1' I0130 23:47:16.786909 3156 http.cpp:1405] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:51774 I0130 23:47:16.787523 3156 http.cpp:3606] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:16.789492 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0130 23:47:16.789902 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0130 23:47:16.791622 3150 v0_volume_manager.cpp:628] NODE_SERVICE loaded: {} I0130 23:47:16.792151 3150 v0_volume_manager.cpp:628] CONTROLLER_SERVICE loaded: {} I0130 23:47:16.794260 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ControllerGetCapabilities call I0130 23:47:16.797688 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetCapabilities call I0130 23:47:16.801334 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetId call I0130 23:47:16.803791 3154 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0130 23:47:16.803946 3156 status_update_manager_process.hpp:379] Pausing operation status update manager I0130 23:47:16.804365 3146 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:40819/slave(1250)/api/v1/resource_provider I0130 23:47:16.807755 3142 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:40819/slave(1250)/api/v1/resource_provider I0130 23:47:16.808473 3141 provider.cpp:476] Connected to resource provider manager I0130 23:47:16.809177 3156 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:40819/slave(1250)/api/v1/resource_provider I0130 23:47:16.810299 3154 hierarchical.cpp:1853] Performed allocation for 1 agents in 192453ns I0130 23:47:16.810649 3144 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider' I0130 23:47:16.812417 3152 http.cpp:1405] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:51778 I0130 23:47:16.813020 3145 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_jeCRZj","--available_capacity=0B","--volumes=","--forward=unix:///tmp/HZeib3/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"} I0130 23:47:16.846760 3144 slave.cpp:8559] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"fe179dc8-52ec-40b5-a614-bba975149132"},"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_jeCRZj","--available_capacity=0B","--volumes=","--forward=unix:///tmp/HZeib3/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"}' I0130 23:47:16.848407 3150 provider.cpp:498] Received SUBSCRIBED event I0130 23:47:16.848455 3150 provider.cpp:1309] Subscribed with ID fe179dc8-52ec-40b5-a614-bba975149132 I0130 23:47:16.849146 3156 status_update_manager_process.hpp:314] Recovering operation status update manager I0130 23:47:16.862579 3155 hierarchical.cpp:1853] Performed allocation for 1 agents in 215607ns I0130 23:47:16.914412 3151 hierarchical.cpp:1853] Performed allocation for 1 agents in 177534ns I0130 23:47:16.920744 3148 provider.cpp:790] Reconciling storage pools and volumes I0130 23:47:16.923714 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0130 23:47:16.926937 3149 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 I0130 23:47:16.927268 3148 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:40819/slave(1250)/api/v1/resource_provider I0130 23:47:16.927389 3149 provider.cpp:748] Resource provider fe179dc8-52ec-40b5-a614-bba975149132 is in READY state I0130 23:47:16.927469 3152 status_update_manager_process.hpp:385] Resuming operation status update manager I0130 23:47:16.928171 3143 provider.cpp:1235] Updating profiles { test } for resource provider fe179dc8-52ec-40b5-a614-bba975149132 I0130 23:47:16.928634 3154 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider' I0130 23:47:16.929157 3144 provider.cpp:790] Reconciling storage pools and volumes I0130 23:47:16.930095 3156 http.cpp:1405] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:51776 I0130 23:47:16.930629 3154 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider fe179dc8-52ec-40b5-a614-bba975149132 I0130 23:47:16.930825 3147 slave.cpp:8559] Handling resource provider message 'UPDATE_STATE: fe179dc8-52ec-40b5-a614-bba975149132 {}' I0130 23:47:16.930932 3147 slave.cpp:8679] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0130 23:47:16.931227 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0130 23:47:16.931568 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0130 23:47:16.932962 3153 hierarchical.cpp:1110] Grew agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 by {} (total), { } (used) I0130 23:47:16.933480 3153 hierarchical.cpp:1067] Agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 (11de8f60f6d8) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0130 23:47:16.938177 3149 hierarchical.cpp:1853] Performed allocation for 1 agents in 186223ns I0130 23:47:16.938743 3147 provider.cpp:790] Reconciling storage pools and volumes I0130 23:47:16.941298 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0130 23:47:16.941648 14628 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0130 23:47:16.952062 3150 slave.cpp:989] Agent terminating I0130 23:47:16.952762 3150 manager.cpp:127] Terminating resource provider fe179dc8-52ec-40b5-a614-bba975149132 I0130 23:47:16.953263 3144 master.cpp:1299] Agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 at slave(1250)@172.17.0.2:40819 (11de8f60f6d8) disconnected I0130 23:47:16.953303 3144 master.cpp:3368] Disconnecting agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 at slave(1250)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:16.953389 3144 master.cpp:3387] Deactivating agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 at slave(1250)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:16.953531 3156 hierarchical.cpp:1156] Agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 deactivated E0130 23:47:16.953886 3146 http_connection.hpp:449] End-Of-File received I0130 23:47:16.954447 3146 http_connection.hpp:217] Re-detecting endpoint I0130 23:47:16.954931 3146 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0130 23:47:16.955003 3145 provider.cpp:488] Disconnected from resource provider manager I0130 23:47:16.955132 3146 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0130 23:47:16.955157 3145 status_update_manager_process.hpp:379] Pausing operation status update manager I0130 23:47:16.955209 3146 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:40819/slave(1250)/api/v1/resource_provider I0130 23:47:16.956710 3154 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 I0130 23:47:16.956773 3154 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.514688secs I0130 23:47:16.957237 3154 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:16.958127 3145 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:40819/slave(1250)/api/v1/resource_provider I0130 23:47:16.958709 3141 provider.cpp:476] Connected to resource provider manager I0130 23:47:16.959302 3149 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:40819/slave(1250)/api/v1/resource_provider I0130 23:47:16.960191 3157 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1/resource_provider' E0130 23:47:16.961447 3152 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0130 23:47:16.984872 3150 hierarchical.cpp:1853] Performed allocation for 1 agents in 171159ns I0130 23:47:17.034195 3145 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0130 23:47:17.035600 3149 hierarchical.cpp:1853] Performed allocation for 1 agents in 176098ns I0130 23:47:17.035948 3153 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:17.038334 3155 container_daemon.cpp:189] Invoking post-stop hook for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:17.038584 3155 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-MEwnte/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:17.038770 3145 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:17.041443 3157 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1' I0130 23:47:17.053208 3140 master.cpp:1140] Master terminating I0130 23:47:17.053596 3146 hierarchical.cpp:1132] Removed all filters for agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 I0130 23:47:17.053629 3146 hierarchical.cpp:1008] Removed agent 749899c3-ec6c-4ae7-92ac-066d0562af9c-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (758 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 I0130 23:47:17.075561 3140 cluster.cpp:180] Creating default 'local' authorizer I0130 23:47:17.083453 3155 master.cpp:443] Master 26e1930c-a8b2-45b9-8530-a055d173c4dd (11de8f60f6d8) started on 172.17.0.2:40819 I0130 23:47:17.083483 3155 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/oFItQV/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/oFItQV/master" --zk_session_timeout="10secs" I0130 23:47:17.083864 3155 master.cpp:495] Master only allowing authenticated frameworks to register I0130 23:47:17.083880 3155 master.cpp:501] Master only allowing authenticated agents to register I0130 23:47:17.083889 3155 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0130 23:47:17.083906 3155 credentials.hpp:37] Loading credentials for authentication from '/tmp/oFItQV/credentials' I0130 23:47:17.084206 3155 master.cpp:551] Using default 'crammd5' authenticator I0130 23:47:17.084450 3155 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0130 23:47:17.084702 3155 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0130 23:47:17.084930 3155 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0130 23:47:17.085156 3155 master.cpp:632] Authorization enabled I0130 23:47:17.085522 3151 hierarchical.cpp:567] Initialized hierarchical allocator process I0130 23:47:17.085553 3144 whitelist_watcher.cpp:77] No whitelist given I0130 23:47:17.089408 3149 master.cpp:2172] Elected as the leading master! I0130 23:47:17.089457 3149 master.cpp:1668] Recovering from registrar I0130 23:47:17.089668 3153 registrar.cpp:339] Recovering registrar I0130 23:47:17.090517 3153 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0130 23:47:17.090675 3153 registrar.cpp:487] Applied 1 operations in 54550ns; attempting to update the registry I0130 23:47:17.091405 3153 registrar.cpp:544] Successfully updated the registry in 0ns I0130 23:47:17.091555 3153 registrar.cpp:416] Successfully recovered registrar I0130 23:47:17.092017 3151 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover I0130 23:47:17.092011 3144 master.cpp:1821] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister W0130 23:47:17.098122 3140 process.cpp:2877] Attempted to spawn already running process [email protected]:40819 I0130 23:47:17.099608 3140 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0130 23:47:17.100242 3140 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0130 23:47:17.100270 3140 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0130 23:47:17.100284 3140 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0130 23:47:17.100317 3140 provisioner.cpp:294] Using default backend 'copy' I0130 23:47:17.102944 3140 cluster.cpp:527] Creating default 'local' authorizer I0130 23:47:17.105571 3150 slave.cpp:270] Mesos agent started on (1251)@172.17.0.2:40819 I0130 23:47:17.105604 3150 slave.cpp:271] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/oFItQV/AFOmi9/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/oFItQV/AFOmi9/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/oFItQV/AFOmi9/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/oFItQV/AFOmi9/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/oFItQV/AFOmi9/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/oFItQV/AFOmi9/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/oFItQV/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_gBrOpQ" --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_ETFgxx" --zk_session_timeout="10secs" I0130 23:47:17.106158 3150 credentials.hpp:86] Loading credential for authentication from '/tmp/oFItQV/AFOmi9/credential' I0130 23:47:17.106341 3150 slave.cpp:303] Agent using credential for: test-principal I0130 23:47:17.106377 3150 credentials.hpp:37] Loading credentials for authentication from '/tmp/oFItQV/AFOmi9/http_credentials' I0130 23:47:17.106647 3150 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0130 23:47:17.107043 3150 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0130 23:47:17.108543 3147 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0130 23:47:17.108556 3150 slave.cpp:618] 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"}] I0130 23:47:17.108824 3150 slave.cpp:626] Agent attributes: [ ] I0130 23:47:17.108844 3150 slave.cpp:635] Agent hostname: 11de8f60f6d8 I0130 23:47:17.109022 3155 status_update_manager_process.hpp:379] Pausing operation status update manager I0130 23:47:17.109035 3146 task_status_update_manager.cpp:181] Pausing sending task status updates I0130 23:47:17.110038 3141 hierarchical.cpp:1853] Performed allocation for 0 agents in 103078ns I0130 23:47:17.110827 3148 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ETFgxx/meta' I0130 23:47:17.111042 3156 slave.cpp:7568] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ETFgxx/meta', beginning agent recovery I0130 23:47:17.111646 3142 task_status_update_manager.cpp:207] Recovering task status update manager I0130 23:47:17.112066 3142 containerizer.cpp:820] Recovering Mesos containers I0130 23:47:17.112498 3142 containerizer.cpp:1160] Recovering isolators I0130 23:47:17.113415 3145 containerizer.cpp:1199] Recovering provisioner I0130 23:47:17.114110 3144 provisioner.cpp:518] Provisioner recovery complete I0130 23:47:17.114779 3154 composing.cpp:339] Finished recovering all containerizers I0130 23:47:17.115069 3146 slave.cpp:8050] Recovering executors I0130 23:47:17.115185 3146 slave.cpp:8203] Finished recovery I0130 23:47:17.116056 3142 task_status_update_manager.cpp:181] Pausing sending task status updates I0130 23:47:17.116084 3156 slave.cpp:1416] New master detected at [email protected]:40819 I0130 23:47:17.116108 3149 status_update_manager_process.hpp:379] Pausing operation status update manager I0130 23:47:17.116247 3156 slave.cpp:1481] Detecting new master I0130 23:47:17.119673 3147 slave.cpp:1508] Authenticating with master [email protected]:40819 I0130 23:47:17.119823 3147 slave.cpp:1517] Using default CRAM-MD5 authenticatee I0130 23:47:17.120205 3153 authenticatee.cpp:121] Creating new client SASL connection I0130 23:47:17.120539 3143 master.cpp:10159] Authenticating slave(1251)@172.17.0.2:40819 I0130 23:47:17.120694 3155 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2110)@172.17.0.2:40819 I0130 23:47:17.121001 3152 authenticator.cpp:98] Creating new server SASL connection I0130 23:47:17.121210 3154 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0130 23:47:17.121243 3154 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0130 23:47:17.121374 3150 authenticator.cpp:204] Received SASL authentication start I0130 23:47:17.121448 3150 authenticator.cpp:326] Authentication requires more steps I0130 23:47:17.121603 3145 authenticatee.cpp:259] Received SASL authentication step I0130 23:47:17.121743 3146 authenticator.cpp:232] Received SASL authentication step I0130 23:47:17.121783 3146 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '11de8f60f6d8' server FQDN: '11de8f60f6d8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0130 23:47:17.121809 3146 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0130 23:47:17.121871 3146 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0130 23:47:17.121920 3146 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '11de8f60f6d8' server FQDN: '11de8f60f6d8' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0130 23:47:17.121944 3146 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0130 23:47:17.121966 3146 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0130 23:47:17.121997 3146 authenticator.cpp:318] Authentication success I0130 23:47:17.122149 3151 authenticatee.cpp:299] Authentication success I0130 23:47:17.122241 3148 master.cpp:10191] Successfully authenticated principal 'test-principal' at slave(1251)@172.17.0.2:40819 I0130 23:47:17.122252 3142 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2110)@172.17.0.2:40819 I0130 23:47:17.122859 3149 slave.cpp:1608] Successfully authenticated with master [email protected]:40819 I0130 23:47:17.123297 3149 slave.cpp:2058] Will retry registration in 16.18112ms if necessary I0130 23:47:17.123492 3143 master.cpp:6629] Received register agent message from slave(1251)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:17.123935 3143 master.cpp:3712] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0130 23:47:17.124539 3150 master.cpp:6696] Authorized registration of agent at slave(1251)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:17.124651 3150 master.cpp:6808] Registering agent at slave(1251)@172.17.0.2:40819 (11de8f60f6d8) with id 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 I0130 23:47:17.125327 3146 registrar.cpp:487] Applied 1 operations in 217507ns; attempting to update the registry I0130 23:47:17.126070 3146 registrar.cpp:544] Successfully updated the registry in 657152ns I0130 23:47:17.126335 3146 master.cpp:6856] Admitted agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 at slave(1251)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:17.127326 3153 slave.cpp:1641] Registered with master [email protected]:40819; given agent ID 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 I0130 23:47:17.127321 3146 master.cpp:6901] Registered agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 at slave(1251)@172.17.0.2:40819 (11de8f60f6d8) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0130 23:47:17.127485 3143 task_status_update_manager.cpp:188] Resuming sending task status updates I0130 23:47:17.127513 3149 hierarchical.cpp:959] Added agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 (11de8f60f6d8) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0130 23:47:17.127883 3149 hierarchical.cpp:1853] Performed allocation for 1 agents in 149689ns I0130 23:47:17.127902 3153 slave.cpp:1676] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ETFgxx/meta/slaves/26e1930c-a8b2-45b9-8530-a055d173c4dd-S0/slave.info' I0130 23:47:17.127985 3155 status_update_manager_process.hpp:385] Resuming operation status update manager I0130 23:47:17.129153 3153 slave.cpp:1728] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"I5ZX3dvSTDiCYPfVGQ4Svg=="},"slave_id":{"value":"26e1930c-a8b2-45b9-8530-a055d173c4dd-S0"},"update_oversubscribed_resources":false} I0130 23:47:17.129860 3144 master.cpp:8039] Ignoring update on agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 at slave(1251)@172.17.0.2:40819 (11de8f60f6d8) as it reports no changes I0130 23:47:17.134362 3154 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1' I0130 23:47:17.135578 3147 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.2:51786 I0130 23:47:17.136049 3147 http.cpp:2928] Processing GET_CONTAINERS call I0130 23:47:17.141783 3147 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:17.144472 3146 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1' I0130 23:47:17.145494 3154 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.2:51788 I0130 23:47:17.146194 3154 http.cpp:3388] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:17.147229 3148 http.cpp:3492] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ETFgxx/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:17.161768 3152 hierarchical.cpp:1853] Performed allocation for 1 agents in 184040ns I0130 23:47:17.164098 3143 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:17.164769 3143 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 281344ns I0130 23:47:17.165522 3143 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_gBrOpQ/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0130 23:47:17.165571 3143 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 804864ns I0130 23:47:17.168689 3149 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_c39JEe","--available_capacity=0B","--volumes=","--forward=unix:///tmp/oFItQV/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_ETFgxx/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-41D3bn/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ETFgxx/containers/o rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="107" --pipe_write="108" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_gBrOpQ/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0130 23:47:17.179474 3149 launcher.cpp:145] Forked child with pid '14638' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:17.180543 3149 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 14.956032ms I0130 23:47:17.182157 3149 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.607936ms I0130 23:47:17.182556 3151 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_ETFgxx/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:17.197726 3141 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 15552us I0130 23:47:17.199867 3147 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' I0130 23:47:17.200027 3156 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-41D3bn/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:17.213655 3149 hierarchical.cpp:1853] Performed allocation for 1 agents in 187454ns I0130 23:47:17.265365 3144 hierarchical.cpp:1853] Performed allocation for 1 agents in 174492ns I0130 23:47:17.316689 3143 hierarchical.cpp:1853] Performed allocation for 1 agents in 188625ns I0130 23:47:17.368758 3154 hierarchical.cpp:1853] Performed allocation for 1 agents in 196201ns I0130 23:47:17.420334 3145 hierarchical.cpp:1853] Performed allocation for 1 agents in 196355ns I0130 23:47:17.472121 3141 hierarchical.cpp:1853] Performed allocation for 1 agents in 218574ns I0130 23:47:17.509150 3147 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-41D3bn/endpoint.sock' with CSI v1 I0130 23:47:17.511334 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call I0130 23:47:17.514309 3146 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:17.516919 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call I0130 23:47:17.517252 3144 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1' I0130 23:47:17.518414 3156 http.cpp:1405] HTTP POST for /slave(1251)/api/v1 from 172.17.0.2:51790 I0130 23:47:17.518940 3156 http.cpp:3606] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:17.520649 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0130 23:47:17.520998 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0130 23:47:17.522457 3147 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {} I0130 23:47:17.522889 3147 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {} I0130 23:47:17.523366 3144 hierarchical.cpp:1853] Performed allocation for 1 agents in 171078ns I0130 23:47:17.524780 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call I0130 23:47:17.527842 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call I0130 23:47:17.531137 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call I0130 23:47:17.533324 3150 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0130 23:47:17.533447 3151 status_update_manager_process.hpp:379] Pausing operation status update manager I0130 23:47:17.533887 3142 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:40819/slave(1251)/api/v1/resource_provider I0130 23:47:17.537004 3152 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:40819/slave(1251)/api/v1/resource_provider I0130 23:47:17.537690 3144 provider.cpp:476] Connected to resource provider manager I0130 23:47:17.538291 3146 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:40819/slave(1251)/api/v1/resource_provider I0130 23:47:17.539381 3154 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1/resource_provider' I0130 23:47:17.540904 3153 http.cpp:1405] HTTP POST for /slave(1251)/api/v1/resource_provider from 172.17.0.2:51794 I0130 23:47:17.541496 3147 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_c39JEe","--available_capacity=0B","--volumes=","--forward=unix:///tmp/oFItQV/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"} I0130 23:47:17.575080 3150 hierarchical.cpp:1853] Performed allocation for 1 agents in 177601ns I0130 23:47:17.582764 3155 slave.cpp:8559] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"25c7d5ad-39da-42d5-8ff1-5e127bad8df0"},"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_c39JEe","--available_capacity=0B","--volumes=","--forward=unix:///tmp/oFItQV/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"}' I0130 23:47:17.584666 3146 provider.cpp:498] Received SUBSCRIBED event I0130 23:47:17.584705 3146 provider.cpp:1309] Subscribed with ID 25c7d5ad-39da-42d5-8ff1-5e127bad8df0 I0130 23:47:17.585494 3144 status_update_manager_process.hpp:314] Recovering operation status update manager I0130 23:47:17.627032 3152 hierarchical.cpp:1853] Performed allocation for 1 agents in 245548ns I0130 23:47:17.639740 3150 provider.cpp:790] Reconciling storage pools and volumes I0130 23:47:17.642240 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0130 23:47:17.644937 3145 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 I0130 23:47:17.645251 3150 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:40819/slave(1251)/api/v1/resource_provider I0130 23:47:17.645313 3145 provider.cpp:748] Resource provider 25c7d5ad-39da-42d5-8ff1-5e127bad8df0 is in READY state I0130 23:47:17.645355 3149 status_update_manager_process.hpp:385] Resuming operation status update manager I0130 23:47:17.646036 3153 provider.cpp:1235] Updating profiles { test } for resource provider 25c7d5ad-39da-42d5-8ff1-5e127bad8df0 I0130 23:47:17.646641 3141 process.cpp:3671] Handling HTTP event for process 'slave(1251)' with path: '/slave(1251)/api/v1/resource_provider' I0130 23:47:17.647099 3152 provider.cpp:790] Reconciling storage pools and volumes I0130 23:47:17.648353 3144 http.cpp:1405] HTTP POST for /slave(1251)/api/v1/resource_provider from 172.17.0.2:51792 I0130 23:47:17.648918 3156 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 25c7d5ad-39da-42d5-8ff1-5e127bad8df0 I0130 23:47:17.649139 3155 slave.cpp:8559] Handling resource provider message 'UPDATE_STATE: 25c7d5ad-39da-42d5-8ff1-5e127bad8df0 {}' I0130 23:47:17.649178 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0130 23:47:17.649238 3155 slave.cpp:8679] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0130 23:47:17.649716 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0130 23:47:17.654925 3143 hierarchical.cpp:1110] Grew agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 by {} (total), { } (used) I0130 23:47:17.655287 3143 hierarchical.cpp:1067] Agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 (11de8f60f6d8) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0130 23:47:17.657346 3144 hierarchical.cpp:1853] Performed allocation for 1 agents in 248144ns I0130 23:47:17.657495 3146 provider.cpp:790] Reconciling storage pools and volumes I0130 23:47:17.659891 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0130 23:47:17.660276 14642 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0130 23:47:17.670658 3143 slave.cpp:989] Agent terminating I0130 23:47:17.671391 3143 manager.cpp:127] Terminating resource provider 25c7d5ad-39da-42d5-8ff1-5e127bad8df0 I0130 23:47:17.671905 3146 master.cpp:1299] Agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 at slave(1251)@172.17.0.2:40819 (11de8f60f6d8) disconnected I0130 23:47:17.671953 3146 master.cpp:3368] Disconnecting agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 at slave(1251)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:17.672106 3146 master.cpp:3387] Deactivating agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 at slave(1251)@172.17.0.2:40819 (11de8f60f6d8) I0130 23:47:17.672325 3148 hierarchical.cpp:1156] Agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 deactivated E0130 23:47:17.672557 3141 http_connection.hpp:449] End-Of-File received I0130 23:47:17.673133 3141 http_connection.hpp:217] Re-detecting endpoint I0130 23:47:17.673558 3141 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0130 23:47:17.673708 3141 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0130 23:47:17.673840 3141 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:40819/slave(1251)/api/v1/resource_provider I0130 23:47:17.673916 3150 provider.cpp:488] Disconnected from resource provider manager I0130 23:47:17.674027 3143 status_update_manager_process.hpp:379] Pausing operation status update manager I0130 23:47:17.675338 3153 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 I0130 23:47:17.675391 3153 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.477703936secs I0130 23:47:17.675830 3153 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:17.676962 3152 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:40819/slave(1251)/api/v1/resource_provider I0130 23:47:17.677476 3148 provider.cpp:476] Connected to resource provider manager I0130 23:47:17.678105 3154 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:40819/slave(1251)/api/v1/resource_provider I0130 23:47:17.678951 3157 process.cpp:2781] Returning '404 Not Found' for '/slave(1251)/api/v1/resource_provider' E0130 23:47:17.680100 3156 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0130 23:47:17.703222 3145 hierarchical.cpp:1853] Performed allocation for 1 agents in 164672ns I0130 23:47:17.752317 3146 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0130 23:47:17.754065 3149 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 I0130 23:47:17.754874 3147 hierarchical.cpp:1853] Performed allocation for 1 agents in 169156ns I0130 23:47:17.757092 3156 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' I0130 23:47:17.757380 3150 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-41D3bn/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0130 23:47:17.757602 3145 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0130 23:47:17.760342 3157 process.cpp:2781] Returning '404 Not Found' for '/slave(1251)/api/v1' I0130 23:47:17.771818 3140 master.cpp:1140] Master terminating I0130 23:47:17.772279 3151 hierarchical.cpp:1132] Removed all filters for agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 I0130 23:47:17.772315 3151 hierarchical.cpp:1008] Removed agent 26e1930c-a8b2-45b9-8530-a055d173c4dd-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (716 ms) [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (102894 ms total) [----------] Global test environment tear-down [==========] 2320 tests from 222 test cases ran. (1261282 ms total) [ PASSED ] 2319 tests. [ FAILED ] 1 test, listed below: [ FAILED ] OversubscriptionTest.FixedResourceEstimator 1 FAILED TEST YOU HAVE 34 DISABLED TESTS I0130 23:47:17.864928 3157 process.cpp:935] Stopped the socket accept loop Makefile:15957: recipe for target 'check-local' failed make[4]: *** [check-local] Error 1 make[4]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src' Makefile:15073: recipe for target 'check-am' failed make[3]: *** [check-am] Error 2 make[3]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src' Makefile:15077: recipe for target 'check' failed make[2]: *** [check] Error 2 make[2]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src' Makefile:791: recipe for target 'check-recursive' failed make[1]: *** [check-recursive] Error 1 make[1]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub' Makefile:997: recipe for target 'distcheck' failed make: *** [distcheck] Error 1 Untagged: mesos/mesos-build:ubuntu-16.04 Untagged: mesos/mesos-build@sha256:fa967cbcfb44f55708a3cbc87f245c6d29dd891464db558af56a03ee321526bb Deleted: sha256:e895c0531b9a9a288fabe479a49f7059aed83645351ac99ec2ea2616822c9f97 Deleted: sha256:09119b0b314a69ba6ec6251f2e89f4199fe1e874c84f9abf07dcbd23dbc3f1c1 Deleted: sha256:562fe6af5a3883058be9c784a839392215ed4185a21d21f1d99df0d17f3ae6e7 Deleted: sha256:0dcdfbe322a4f332f73ac70905d557300ec6dae3bd19586758772c750c7b4a19 Deleted: sha256:c66652d605f01094e2db53d62505dbd524e076d5aa69b89d5e620003803eb149 Deleted: sha256:a2cf79bfb9593c05fd7142ddb49afef77ea4ad5d2464e841f09fe62ffee396e0 Deleted: sha256:f7a904214b390f39d98573882f631dc908df8b2b540cf04e1062f8182c1efffd Deleted: sha256:ce1f6fcaa83dfce189d76e08f184085732eab4eeb2562d2399953958405c5bec Deleted: sha256:cce92fda689ab9033f0b8db214bc63edd1ae3e05831a0f3a9418976d7dc7ccdd Deleted: sha256:d22094bbd65447c59a42c580eaa3a44cee9cd855f00905f59409be21bcefc745 Deleted: sha256:b8976847450013f3eb5e9a81a5778f73ed7bef67e6393049712ef17102b4b7b7 Deleted: sha256:b8c891f0ffec910a12757d733b178e3f62d81dbbde2b31d3b754071c416108ed Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/6879/console - Mesos Reviewbot On Jan. 30, 2020, 2:22 p.m., Benjamin Mahler wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/72068/ > ----------------------------------------------------------- > > (Updated Jan. 30, 2020, 2:22 p.m.) > > > Review request for mesos, Andrei Sekretenko and Greg Mann. > > > Repository: mesos > > > Description > ------- > > Per MESOS-10026, we replaced the old protobuf object construction > code with a direct serialization approach to improve performance. > This patch removes the old object construction code (I originally > kept it in case we needed it to debug, but at this point I'm more > confident that we don't need it). > > > Diffs > ----- > > src/master/http.cpp eeaac88c893b43170e655f8bff1d57dd0f7bbfb2 > src/master/master.hpp c813e9fc855cfb1701ec32be7f690e06b6eb203f > src/slave/http.hpp 0afdad9479f0cc2c94452b6b1f2289dd6ea01494 > src/slave/http.cpp 04ad0d816618a1880913857a6f0ff38c4643c488 > > > Diff: https://reviews.apache.org/r/72068/diff/1/ > > > Testing > ------- > > make check > > > Thanks, > > Benjamin Mahler > >
