----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/72787/#review221639 -----------------------------------------------------------
Bad patch! Reviews applied: [72771, 72738, 72739, 72741, 72742, 72774, 72743, 72744, 72745, 72775, 72776, 72782, 72783, 72784, 72785, 72786, 72787] 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_72787"] Error: ...<truncated>... 41285 4279 hierarchical.cpp:1933] Performed allocation for 1 agents in 3.576667ms I0819 14:08:46.543298 4278 master.cpp:9529] Sending offers [ 95c9cfaa-5004-4967-9570-5812b2b7349f-O3 ] to framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 I0819 14:08:46.544713 4268 sched.cpp:934] Scheduler::resourceOffers took 116571ns I0819 14:08:46.548557 4284 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0819 14:08:46.550891 4275 http.cpp:1436] HTTP POST for /master/api/v1 from 172.17.0.2:59828 I0819 14:08:46.551234 4275 http.cpp:277] Processing call CREATE_VOLUMES I0819 14:08:46.552497 4275 master.cpp:3745] Authorizing principal 'test-principal' to perform action CREATE_VOLUME on object {"value":"storage/default-role","resource":{"provider_id":{"value":"94a32bde-a8f9-49dd-8bb0-6964d24748d6"},"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":"c79c01d5-351a-472e-803e-ca25ca4098aa","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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8","profile":"test"}}}} I0819 14:08:46.554817 4267 sched.cpp:960] Rescinded offer 95c9cfaa-5004-4967-9570-5812b2b7349f-O3 I0819 14:08:46.554944 4267 sched.cpp:971] Scheduler::offerRescinded took 36172ns I0819 14:08:46.555747 4280 master.cpp:11827] Removing offer 95c9cfaa-5004-4967-9570-5812b2b7349f-O3 I0819 14:08:46.555721 4274 hierarchical.cpp:1656] 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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8,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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8,test)]:2048, offered or allocated: {}) on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 from framework 95c9c faa-5004-4967-9570-5812b2b7349f-0000 I0819 14:08:46.559052 4274 hierarchical.cpp:1705] Framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 filtered agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 for 5secs I0819 14:08:46.563393 4277 master.cpp:11692] Sending operation '' (uuid: f3818d02-9ab1-4849-9cb2-a8f1549462c6) to agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 at slave(1246)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:46.564393 4277 slave.cpp:4557] Ignoring new checkpointed resources and operations identical to the current version I0819 14:08:46.566814 4265 master.cpp:5573] Processing REVIVE call for framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 I0819 14:08:46.567895 4269 hierarchical.cpp:1801] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 I0819 14:08:46.570042 4283 provider.cpp:498] Received APPLY_OPERATION event I0819 14:08:46.570111 4283 provider.cpp:1352] Received CREATE operation '' (uuid: f3818d02-9ab1-4849-9cb2-a8f1549462c6) I0819 14:08:46.570576 4269 hierarchical.cpp:1933] Performed allocation for 1 agents in 1.927072ms I0819 14:08:46.571660 4267 master.cpp:9529] Sending offers [ 95c9cfaa-5004-4967-9570-5812b2b7349f-O4 ] to framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 I0819 14:08:46.572633 4280 sched.cpp:934] Scheduler::resourceOffers took 122024ns I0819 14:08:46.580122 4278 http.cpp:1436] HTTP POST for /slave(1246)/api/v1/resource_provider from 172.17.0.2:59800 I0819 14:08:46.582171 4277 slave.cpp:8714] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 0808cd79-4d7e-4599-8d13-287ea152ef84) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0819 14:08:46.582408 4277 slave.cpp:9167] Updating the state of operation with no ID (uuid: 0808cd79-4d7e-4599-8d13-287ea152ef84) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0819 14:08:46.582466 4277 slave.cpp:8921] Forwarding status update of operation with no ID (operation_uuid: 0808cd79-4d7e-4599-8d13-287ea152ef84) for an operator API call I0819 14:08:46.582927 4264 master.cpp:11344] Updating the state of operation '' (uuid: 0808cd79-4d7e-4599-8d13-287ea152ef84) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0819 14:08:46.583549 4265 slave.cpp:4557] Ignoring new checkpointed resources and operations identical to the current version I0819 14:08:47.150028 4280 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 3fd71eae-444c-4263-b778-2dce02030e27) for operation UUID f3818d02-9ab1-4849-9cb2-a8f1549462c6 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:47.150126 4280 status_update_manager_process.hpp:414] Creating operation status update stream f3818d02-9ab1-4849-9cb2-a8f1549462c6 checkpoint=true I0819 14:08:47.150187 4283 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0819 14:08:47.151325 4280 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 3fd71eae-444c-4263-b778-2dce02030e27) for operation UUID f3818d02-9ab1-4849-9cb2-a8f1549462c6 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:47.301046 4280 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 3fd71eae-444c-4263-b778-2dce02030e27) for operation UUID f3818d02-9ab1-4849-9cb2-a8f1549462c6 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:47.301561 4280 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 5c382d31-56d5-4d7f-8ba5-604301ad67cd) for stream 0808cd79-4d7e-4599-8d13-287ea152ef84 I0819 14:08:47.301681 4280 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 5c382d31-56d5-4d7f-8ba5-604301ad67cd) for operation UUID 0808cd79-4d7e-4599-8d13-287ea152ef84 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:47.302695 4274 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:36585/slave(1246)/api/v1/resource_provider I0819 14:08:47.304953 4272 process.cpp:3671] Handling HTTP event for process 'slave(1246)' with path: '/slave(1246)/api/v1/resource_provider' I0819 14:08:47.348141 4263 http.cpp:1436] HTTP POST for /slave(1246)/api/v1/resource_provider from 172.17.0.2:59800 I0819 14:08:47.349635 4265 slave.cpp:8714] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: f3818d02-9ab1-4849-9cb2-a8f1549462c6) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0819 14:08:47.349938 4265 slave.cpp:9167] Updating the state of operation with no ID (uuid: f3818d02-9ab1-4849-9cb2-a8f1549462c6) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0819 14:08:47.349997 4265 slave.cpp:8921] Forwarding status update of operation with no ID (operation_uuid: f3818d02-9ab1-4849-9cb2-a8f1549462c6) for an operator API call I0819 14:08:47.350587 4270 master.cpp:11344] Updating the state of operation '' (uuid: f3818d02-9ab1-4849-9cb2-a8f1549462c6) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0819 14:08:47.351387 4275 slave.cpp:4557] Ignoring new checkpointed resources and operations identical to the current version I0819 14:08:47.354555 4273 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0819 14:08:47.393503 4280 status_update_manager_process.hpp:490] Cleaning up operation status update stream 0808cd79-4d7e-4599-8d13-287ea152ef84 I0819 14:08:47.393874 4280 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 3fd71eae-444c-4263-b778-2dce02030e27) for stream f3818d02-9ab1-4849-9cb2-a8f1549462c6 I0819 14:08:47.393966 4280 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 3fd71eae-444c-4263-b778-2dce02030e27) for operation UUID f3818d02-9ab1-4849-9cb2-a8f1549462c6 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:47.550114 4280 status_update_manager_process.hpp:490] Cleaning up operation status update stream f3818d02-9ab1-4849-9cb2-a8f1549462c6 I0819 14:08:47.689910 4264 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0819 14:08:47.692364 4275 http.cpp:1436] HTTP POST for /master/api/v1 from 172.17.0.2:59840 I0819 14:08:47.692628 4275 http.cpp:277] Processing call DESTROY_VOLUMES I0819 14:08:47.694059 4275 master.cpp:3745] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"94a32bde-a8f9-49dd-8bb0-6964d24748d6"},"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":"c79c01d5-351a-472e-803e-ca25ca4098aa","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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8","profile":"test"}}}} I0819 14:08:47.696056 4286 sched.cpp:960] Rescinded offer 95c9cfaa-5004-4967-9570-5812b2b7349f-O4 I0819 14:08:47.696255 4286 sched.cpp:971] Scheduler::offerRescinded took 48256ns I0819 14:08:47.696755 4267 master.cpp:11827] Removing offer 95c9cfaa-5004-4967-9570-5812b2b7349f-O4 I0819 14:08:47.696749 4285 hierarchical.cpp:1656] 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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8,test),c79c01d5-351a-472e-803e-ca25ca4098aa: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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8,test),c79c01d5-351a-472e-803e-ca25ca4098aa:volume]:2048, offered or allocated: {}) on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 from framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 I0819 14:08:47.699900 4285 hierarchical.cpp:1705] Framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 filtered agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 for 5secs I0819 14:08:47.704313 4283 master.cpp:11692] Sending operation '' (uuid: f63cbbc9-3eea-48b9-aaac-cd62f576d703) to agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 at slave(1246)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:47.705277 4278 slave.cpp:4557] Ignoring new checkpointed resources and operations identical to the current version I0819 14:08:47.709082 4277 hierarchical.cpp:1933] Performed allocation for 1 agents in 2.050803ms I0819 14:08:47.709789 4275 provider.cpp:498] Received APPLY_OPERATION event I0819 14:08:47.709836 4275 provider.cpp:1352] Received DESTROY operation '' (uuid: f63cbbc9-3eea-48b9-aaac-cd62f576d703) I0819 14:08:47.709882 4270 master.cpp:9529] Sending offers [ 95c9cfaa-5004-4967-9570-5812b2b7349f-O5 ] to framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 I0819 14:08:47.710638 4269 sched.cpp:934] Scheduler::resourceOffers took 91721ns I0819 14:08:47.964803 4286 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: ba93562e-367c-4e31-93a8-bf68120f3d46) for operation UUID f63cbbc9-3eea-48b9-aaac-cd62f576d703 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:47.964982 4286 status_update_manager_process.hpp:414] Creating operation status update stream f63cbbc9-3eea-48b9-aaac-cd62f576d703 checkpoint=true I0819 14:08:47.965648 4286 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: ba93562e-367c-4e31-93a8-bf68120f3d46) for operation UUID f63cbbc9-3eea-48b9-aaac-cd62f576d703 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:48.131875 4286 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: ba93562e-367c-4e31-93a8-bf68120f3d46) for operation UUID f63cbbc9-3eea-48b9-aaac-cd62f576d703 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:48.133283 4274 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:36585/slave(1246)/api/v1/resource_provider I0819 14:08:48.134742 4273 process.cpp:3671] Handling HTTP event for process 'slave(1246)' with path: '/slave(1246)/api/v1/resource_provider' I0819 14:08:48.139044 4272 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0819 14:08:48.142397 4284 http.cpp:1436] HTTP POST for /master/api/v1 from 172.17.0.2:59844 I0819 14:08:48.142719 4284 http.cpp:277] Processing call UNRESERVE_RESOURCES I0819 14:08:48.143796 4284 master.cpp:3745] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"94a32bde-a8f9-49dd-8bb0-6964d24748d6"},"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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8","profile":"test"}}}} I0819 14:08:48.145752 4271 sched.cpp:960] Rescinded offer 95c9cfaa-5004-4967-9570-5812b2b7349f-O5 I0819 14:08:48.145867 4271 sched.cpp:971] Scheduler::offerRescinded took 33143ns I0819 14:08:48.146476 4270 hierarchical.cpp:1656] 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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8,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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8,test)]:2048, offered or allocated: {}) on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 from framework 95c9c faa-5004-4967-9570-5812b2b7349f-0000 I0819 14:08:48.146780 4265 master.cpp:11827] Removing offer 95c9cfaa-5004-4967-9570-5812b2b7349f-O5 I0819 14:08:48.148990 4270 hierarchical.cpp:1705] Framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 filtered agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 for 5secs I0819 14:08:48.152762 4286 master.cpp:11692] Sending operation '' (uuid: 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9) to agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 at slave(1246)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:48.153638 4279 slave.cpp:4557] Ignoring new checkpointed resources and operations identical to the current version I0819 14:08:48.158696 4284 provider.cpp:498] Received APPLY_OPERATION event I0819 14:08:48.158799 4284 provider.cpp:1352] Received UNRESERVE operation '' (uuid: 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9) I0819 14:08:48.161067 4282 hierarchical.cpp:1933] Performed allocation for 1 agents in 2.851671ms I0819 14:08:48.162380 4263 master.cpp:9529] Sending offers [ 95c9cfaa-5004-4967-9570-5812b2b7349f-O6 ] to framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 I0819 14:08:48.163434 4271 sched.cpp:934] Scheduler::resourceOffers took 158414ns I0819 14:08:48.179174 4285 http.cpp:1436] HTTP POST for /slave(1246)/api/v1/resource_provider from 172.17.0.2:59800 I0819 14:08:48.180282 4274 slave.cpp:8714] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: f63cbbc9-3eea-48b9-aaac-cd62f576d703) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0819 14:08:48.180477 4274 slave.cpp:9167] Updating the state of operation with no ID (uuid: f63cbbc9-3eea-48b9-aaac-cd62f576d703) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0819 14:08:48.180527 4274 slave.cpp:8921] Forwarding status update of operation with no ID (operation_uuid: f63cbbc9-3eea-48b9-aaac-cd62f576d703) for an operator API call I0819 14:08:48.181089 4283 master.cpp:11344] Updating the state of operation '' (uuid: f63cbbc9-3eea-48b9-aaac-cd62f576d703) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0819 14:08:48.181893 4278 slave.cpp:4557] Ignoring new checkpointed resources and operations identical to the current version I0819 14:08:48.370065 4271 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 8b5d49ce-3e7d-4370-9c58-f6f9828eab13) for operation UUID 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:48.370182 4271 status_update_manager_process.hpp:414] Creating operation status update stream 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9 checkpoint=true I0819 14:08:48.370266 4284 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0819 14:08:48.370564 4271 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 8b5d49ce-3e7d-4370-9c58-f6f9828eab13) for operation UUID 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:48.442402 4271 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 8b5d49ce-3e7d-4370-9c58-f6f9828eab13) for operation UUID 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:48.443358 4271 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: ba93562e-367c-4e31-93a8-bf68120f3d46) for stream f63cbbc9-3eea-48b9-aaac-cd62f576d703 I0819 14:08:48.443460 4271 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: ba93562e-367c-4e31-93a8-bf68120f3d46) for operation UUID f63cbbc9-3eea-48b9-aaac-cd62f576d703 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:48.443943 4269 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:36585/slave(1246)/api/v1/resource_provider I0819 14:08:48.445258 4267 process.cpp:3671] Handling HTTP event for process 'slave(1246)' with path: '/slave(1246)/api/v1/resource_provider' I0819 14:08:48.488164 4283 http.cpp:1436] HTTP POST for /slave(1246)/api/v1/resource_provider from 172.17.0.2:59800 I0819 14:08:48.489684 4278 slave.cpp:8714] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0819 14:08:48.489928 4278 slave.cpp:9167] Updating the state of operation with no ID (uuid: 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0819 14:08:48.489981 4278 slave.cpp:8921] Forwarding status update of operation with no ID (operation_uuid: 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9) for an operator API call I0819 14:08:48.490408 4264 master.cpp:11344] Updating the state of operation '' (uuid: 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0819 14:08:48.491147 4268 slave.cpp:4557] Ignoring new checkpointed resources and operations identical to the current version I0819 14:08:48.493036 4275 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0819 14:08:48.509143 4271 status_update_manager_process.hpp:490] Cleaning up operation status update stream f63cbbc9-3eea-48b9-aaac-cd62f576d703 I0819 14:08:48.509433 4271 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 8b5d49ce-3e7d-4370-9c58-f6f9828eab13) for stream 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9 I0819 14:08:48.509552 4271 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 8b5d49ce-3e7d-4370-9c58-f6f9828eab13) for operation UUID 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9 on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:48.609664 4271 status_update_manager_process.hpp:490] Cleaning up operation status update stream 0f29284d-a9e1-4e10-8435-20dfd9fbf8b9 I0819 14:08:48.678182 4273 master.cpp:1409] Framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 disconnected I0819 14:08:48.678267 4273 master.cpp:3378] Deactivating framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 I0819 14:08:48.678871 4280 hierarchical.cpp:885] Deactivated framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 I0819 14:08:48.679352 4276 slave.cpp:1000] Agent terminating I0819 14:08:48.679566 4273 master.cpp:11827] Removing offer 95c9cfaa-5004-4967-9570-5812b2b7349f-O6 I0819 14:08:48.679658 4273 master.cpp:3362] Disconnecting framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 I0819 14:08:48.679831 4273 master.cpp:1424] Giving framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 0ns to failover I0819 14:08:48.679869 4280 hierarchical.cpp:1656] 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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8,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_WfmWS4/2GB-4f81b6e2-683e-4aba-bd03-c8987d3e65c8,test)]:2048, offered or allocated: {}) on agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 from framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 I0819 14:08:48.680642 4276 manager.cpp:127] Terminating resource provider 94a32bde-a8f9-49dd-8bb0-6964d24748d6 I0819 14:08:48.681259 4285 master.cpp:1294] Agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 at slave(1246)@172.17.0.2:36585 (455040d4d5e3) disconnected I0819 14:08:48.681294 4285 master.cpp:3413] Disconnecting agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 at slave(1246)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:48.681370 4285 master.cpp:3432] Deactivating agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 at slave(1246)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:48.681604 4285 master.cpp:9313] Framework failover timeout, removing framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 I0819 14:08:48.681644 4285 master.cpp:10328] Removing framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 (default) at [email protected]:36585 E0819 14:08:48.682022 4283 http_connection.hpp:449] End-Of-File received I0819 14:08:48.682586 4283 http_connection.hpp:217] Re-detecting endpoint I0819 14:08:48.683169 4283 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0819 14:08:48.683243 4283 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0819 14:08:48.683336 4283 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:36585/slave(1246)/api/v1/resource_provider I0819 14:08:48.683372 4265 provider.cpp:488] Disconnected from resource provider manager I0819 14:08:48.683439 4280 hierarchical.cpp:1236] Agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 deactivated I0819 14:08:48.683562 4284 status_update_manager_process.hpp:379] Pausing operation status update manager I0819 14:08:48.683588 4280 hierarchical.cpp:1857] Allocation paused I0819 14:08:48.684298 4280 hierarchical.cpp:829] Removed framework 95c9cfaa-5004-4967-9570-5812b2b7349f-0000 I0819 14:08:48.684378 4280 hierarchical.cpp:1867] Allocation resumed I0819 14:08:48.685001 4286 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0819 14:08:48.685075 4286 containerizer.cpp:3414] 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 4.714445952secs I0819 14:08:48.685619 4286 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:48.686780 4272 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:36585/slave(1246)/api/v1/resource_provider I0819 14:08:48.687414 4265 provider.cpp:476] Connected to resource provider manager I0819 14:08:48.687924 4273 hierarchical.cpp:1933] Performed allocation for 1 agents in 244425ns I0819 14:08:48.688205 4270 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:36585/slave(1246)/api/v1/resource_provider I0819 14:08:48.689100 4287 process.cpp:2781] Returning '404 Not Found' for '/slave(1246)/api/v1/resource_provider' E0819 14:08:48.690769 4283 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0819 14:08:48.740089 4279 hierarchical.cpp:1933] Performed allocation for 1 agents in 242089ns I0819 14:08:48.789889 4285 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0819 14:08:48.791605 4284 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 I0819 14:08:48.792022 4275 hierarchical.cpp:1933] Performed allocation for 1 agents in 207390ns I0819 14:08:48.794831 4282 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' I0819 14:08:48.795158 4266 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-XwhpyF/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:48.795424 4281 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:48.798709 4287 process.cpp:2781] Returning '404 Not Found' for '/slave(1246)/api/v1' I0819 14:08:48.809129 4262 master.cpp:1142] Master terminating I0819 14:08:48.810029 4284 hierarchical.cpp:1212] Removed all filters for agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 I0819 14:08:48.810058 4284 hierarchical.cpp:1088] Removed agent 95c9cfaa-5004-4967-9570-5812b2b7349f-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (4599 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 I0819 14:08:48.827253 4262 cluster.cpp:186] Creating default 'local' authorizer I0819 14:08:48.832798 4268 master.cpp:445] Master 20a82097-6704-4c12-85b8-44aecc0623f6 (455040d4d5e3) started on 172.17.0.2:36585 I0819 14:08:48.832830 4268 master.cpp:448] 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/ZIi2Tr/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.11.0/_inst/share/mesos/webui" --work_dir="/tmp/ZIi2Tr/master" --zk_session_timeout="10secs" I0819 14:08:48.833240 4268 master.cpp:497] Master only allowing authenticated frameworks to register I0819 14:08:48.833256 4268 master.cpp:503] Master only allowing authenticated agents to register I0819 14:08:48.833266 4268 master.cpp:509] Master only allowing authenticated HTTP frameworks to register I0819 14:08:48.833277 4268 credentials.hpp:37] Loading credentials for authentication from '/tmp/ZIi2Tr/credentials' I0819 14:08:48.833556 4268 master.cpp:553] Using default 'crammd5' authenticator I0819 14:08:48.833863 4268 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0819 14:08:48.834113 4268 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0819 14:08:48.834302 4268 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0819 14:08:48.834506 4268 master.cpp:634] Authorization enabled I0819 14:08:48.834930 4269 hierarchical.cpp:637] Initialized hierarchical allocator process I0819 14:08:48.834995 4286 whitelist_watcher.cpp:77] No whitelist given I0819 14:08:48.838503 4271 master.cpp:2167] Elected as the leading master! I0819 14:08:48.838541 4271 master.cpp:1663] Recovering from registrar I0819 14:08:48.838762 4276 registrar.cpp:339] Recovering registrar I0819 14:08:48.839887 4276 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0819 14:08:48.840075 4276 registrar.cpp:487] Applied 1 operations in 71607ns; attempting to update the registry I0819 14:08:48.841167 4276 registrar.cpp:544] Successfully updated the registry in 0ns I0819 14:08:48.841342 4276 registrar.cpp:416] Successfully recovered registrar I0819 14:08:48.842003 4285 master.cpp:1816] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0819 14:08:48.842054 4279 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover W0819 14:08:48.848707 4262 process.cpp:2877] Attempted to spawn already running process [email protected]:36585 I0819 14:08:48.850298 4262 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0819 14:08:48.850965 4262 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0819 14:08:48.850996 4262 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0819 14:08:48.851013 4262 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0819 14:08:48.851049 4262 provisioner.cpp:294] Using default backend 'copy' I0819 14:08:48.854034 4262 cluster.cpp:533] Creating default 'local' authorizer I0819 14:08:48.856861 4273 slave.cpp:279] Mesos agent started on (1247)@172.17.0.2:36585 I0819 14:08:48.856890 4273 slave.cpp:280] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/ZIi2Tr/74rlCs/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/ZIi2Tr/74rlCs/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/ZIi2Tr/74rlCs/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/ZIi2Tr/74rlCs/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/ZIi2Tr/74rlCs/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/ZIi2Tr/74rlCs/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.11.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/ZIi2Tr/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_Mu0qVc" --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_nA9weX" --zk_session_timeout="10secs" I0819 14:08:48.857456 4273 credentials.hpp:73] Loading credential for authentication from '/tmp/ZIi2Tr/74rlCs/credential' I0819 14:08:48.857643 4273 slave.cpp:312] Agent using credential for: test-principal I0819 14:08:48.857679 4273 credentials.hpp:37] Loading credentials for authentication from '/tmp/ZIi2Tr/74rlCs/http_credentials' I0819 14:08:48.857916 4273 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0819 14:08:48.858306 4273 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0819 14:08:48.859993 4283 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0819 14:08:48.860040 4273 slave.cpp:627] 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"}] I0819 14:08:48.860324 4273 slave.cpp:635] Agent attributes: [ ] I0819 14:08:48.860344 4273 slave.cpp:644] Agent hostname: 455040d4d5e3 I0819 14:08:48.860535 4271 status_update_manager_process.hpp:379] Pausing operation status update manager I0819 14:08:48.860574 4280 task_status_update_manager.cpp:181] Pausing sending task status updates I0819 14:08:48.862257 4266 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_nA9weX/meta' I0819 14:08:48.862540 4278 slave.cpp:7723] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_nA9weX/meta', beginning agent recovery I0819 14:08:48.863041 4274 hierarchical.cpp:1933] Performed allocation for 0 agents in 79650ns I0819 14:08:48.863337 4277 task_status_update_manager.cpp:207] Recovering task status update manager I0819 14:08:48.863816 4285 containerizer.cpp:830] Recovering Mesos containers I0819 14:08:48.864187 4285 containerizer.cpp:1170] Recovering isolators I0819 14:08:48.865077 4271 containerizer.cpp:1209] Recovering provisioner I0819 14:08:48.865803 4284 provisioner.cpp:518] Provisioner recovery complete I0819 14:08:48.866788 4277 composing.cpp:343] Finished recovering all containerizers I0819 14:08:48.867130 4275 slave.cpp:8205] Recovering executors I0819 14:08:48.867261 4275 slave.cpp:8358] Finished recovery I0819 14:08:48.868264 4269 task_status_update_manager.cpp:181] Pausing sending task status updates I0819 14:08:48.868288 4286 status_update_manager_process.hpp:379] Pausing operation status update manager I0819 14:08:48.868332 4264 slave.cpp:1471] New master detected at [email protected]:36585 I0819 14:08:48.868521 4264 slave.cpp:1536] Detecting new master I0819 14:08:48.877943 4285 slave.cpp:1563] Authenticating with master [email protected]:36585 I0819 14:08:48.878080 4285 slave.cpp:1572] Using default CRAM-MD5 authenticatee I0819 14:08:48.878666 4279 authenticatee.cpp:121] Creating new client SASL connection I0819 14:08:48.879089 4282 master.cpp:9720] Authenticating slave(1247)@172.17.0.2:36585 I0819 14:08:48.879361 4280 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2113)@172.17.0.2:36585 I0819 14:08:48.879849 4283 authenticator.cpp:98] Creating new server SASL connection I0819 14:08:48.880198 4265 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0819 14:08:48.880240 4265 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0819 14:08:48.880365 4266 authenticator.cpp:204] Received SASL authentication start I0819 14:08:48.880443 4266 authenticator.cpp:326] Authentication requires more steps I0819 14:08:48.880651 4278 authenticatee.cpp:259] Received SASL authentication step I0819 14:08:48.880839 4274 authenticator.cpp:232] Received SASL authentication step I0819 14:08:48.880882 4274 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '455040d4d5e3' server FQDN: '455040d4d5e3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0819 14:08:48.880899 4274 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0819 14:08:48.880949 4274 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0819 14:08:48.880986 4274 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '455040d4d5e3' server FQDN: '455040d4d5e3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0819 14:08:48.881002 4274 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0819 14:08:48.881016 4274 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0819 14:08:48.881034 4274 authenticator.cpp:318] Authentication success I0819 14:08:48.881148 4273 authenticatee.cpp:299] Authentication success I0819 14:08:48.881273 4274 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2113)@172.17.0.2:36585 I0819 14:08:48.881294 4263 master.cpp:9752] Successfully authenticated principal 'test-principal' at slave(1247)@172.17.0.2:36585 I0819 14:08:48.881913 4272 slave.cpp:1663] Successfully authenticated with master [email protected]:36585 I0819 14:08:48.882586 4272 slave.cpp:2113] Will retry registration in 13.312485ms if necessary I0819 14:08:48.882860 4267 master.cpp:6214] Received register agent message from slave(1247)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:48.883436 4267 master.cpp:3745] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0819 14:08:48.884295 4264 master.cpp:6281] Authorized registration of agent at slave(1247)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:48.884426 4264 master.cpp:6393] Registering agent at slave(1247)@172.17.0.2:36585 (455040d4d5e3) with id 20a82097-6704-4c12-85b8-44aecc0623f6-S0 I0819 14:08:48.885368 4271 registrar.cpp:487] Applied 1 operations in 375857ns; attempting to update the registry I0819 14:08:48.886373 4271 registrar.cpp:544] Successfully updated the registry in 901888ns I0819 14:08:48.886691 4283 master.cpp:6441] Admitted agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 at slave(1247)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:48.887830 4283 master.cpp:6486] Registered agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 at slave(1247)@172.17.0.2:36585 (455040d4d5e3) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0819 14:08:48.887953 4265 slave.cpp:1696] Registered with master [email protected]:36585; given agent ID 20a82097-6704-4c12-85b8-44aecc0623f6-S0 I0819 14:08:48.888049 4284 hierarchical.cpp:1039] Added agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 (455040d4d5e3) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0819 14:08:48.888108 4276 task_status_update_manager.cpp:188] Resuming sending task status updates I0819 14:08:48.888485 4284 hierarchical.cpp:1933] Performed allocation for 1 agents in 166524ns I0819 14:08:48.888497 4265 slave.cpp:1731] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_nA9weX/meta/slaves/20a82097-6704-4c12-85b8-44aecc0623f6-S0/slave.info' I0819 14:08:48.888586 4275 status_update_manager_process.hpp:385] Resuming operation status update manager I0819 14:08:48.890355 4265 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"4fvi3i0tTi2k32edyq0W+g=="},"slave_id":{"value":"20a82097-6704-4c12-85b8-44aecc0623f6-S0"},"update_oversubscribed_resources":false} I0819 14:08:48.891412 4269 master.cpp:7628] Ignoring update on agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 at slave(1247)@172.17.0.2:36585 (455040d4d5e3) as it reports no changes I0819 14:08:48.896960 4266 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1' I0819 14:08:48.898655 4281 http.cpp:1436] HTTP POST for /slave(1247)/api/v1 from 172.17.0.2:59898 I0819 14:08:48.899339 4281 http.cpp:2828] Processing GET_CONTAINERS call I0819 14:08:48.907804 4282 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:48.911478 4283 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1' I0819 14:08:48.912992 4281 http.cpp:1436] HTTP POST for /slave(1247)/api/v1 from 172.17.0.2:59900 I0819 14:08:48.914022 4274 hierarchical.cpp:1933] Performed allocation for 1 agents in 185057ns I0819 14:08:48.914149 4281 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:48.915704 4265 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_nA9weX/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:48.916887 4273 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:48.917975 4273 containerizer.cpp:3414] 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 444160ns I0819 14:08:48.919339 4273 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Mu0qVc/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0819 14:08:48.919450 4273 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.464832ms I0819 14:08:48.924126 4271 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_kdkExH","--available_capacity=0B","--volumes=","--forward=unix:///tmp/ZIi2Tr/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_nA9weX/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-o49FOt/endpoint.sock"},{"name":"MESOS_AGENT_ID","type":"VALUE","value":"20a82097-6704-4c12-85b8-44aecc0623f6-S0"}]},"task_environment":{},"working _directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_nA9weX/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="112" --pipe_write="113" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_Mu0qVc/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0819 14:08:48.938207 4271 launcher.cpp:145] Forked child with pid '18702' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:48.939177 4271 containerizer.cpp:3414] 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 19.731968ms I0819 14:08:48.940884 4271 containerizer.cpp:3414] 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.703936ms I0819 14:08:48.941439 4270 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_nA9weX/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:48.943353 4265 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 2.383104ms I0819 14:08:48.947271 4280 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' I0819 14:08:48.947485 4268 service_manager.cpp:795] Connecting to endpoint 'unix:///tmp/mesos-csi-o49FOt/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:48.965626 4283 hierarchical.cpp:1933] Performed allocation for 1 agents in 249718ns I0819 14:08:49.016636 4267 hierarchical.cpp:1933] Performed allocation for 1 agents in 193669ns I0819 14:08:49.068655 4269 hierarchical.cpp:1933] Performed allocation for 1 agents in 180211ns I0819 14:08:49.119560 4268 hierarchical.cpp:1933] Performed allocation for 1 agents in 185083ns I0819 14:08:49.170780 4284 hierarchical.cpp:1933] Performed allocation for 1 agents in 199138ns I0819 14:08:49.221879 4270 hierarchical.cpp:1933] Performed allocation for 1 agents in 188294ns I0819 14:08:49.272950 4279 hierarchical.cpp:1933] Performed allocation for 1 agents in 185488ns I0819 14:08:49.324518 4276 hierarchical.cpp:1933] Performed allocation for 1 agents in 191053ns I0819 14:08:49.375530 4267 hierarchical.cpp:1933] Performed allocation for 1 agents in 169540ns I0819 14:08:49.393486 4285 service_manager.cpp:622] Probing endpoint 'unix:///tmp/mesos-csi-o49FOt/endpoint.sock' with CSI v1 I0819 14:08:49.396113 4279 service_manager.cpp:609] Probing endpoint 'unix:///tmp/mesos-csi-o49FOt/endpoint.sock' with CSI v0 I0819 14:08:49.397483 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/Probe call I0819 14:08:49.400226 4278 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:49.402696 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginCapabilities call I0819 14:08:49.404124 4281 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1' I0819 14:08:49.405326 4265 http.cpp:1436] HTTP POST for /slave(1247)/api/v1 from 172.17.0.2:59932 I0819 14:08:49.405825 4265 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:49.407928 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0819 14:08:49.408237 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0819 14:08:49.410096 4283 v0_volume_manager.cpp:653] NODE_SERVICE loaded: {} I0819 14:08:49.410727 4283 v0_volume_manager.cpp:653] CONTROLLER_SERVICE loaded: {} I0819 14:08:49.412806 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ControllerGetCapabilities call I0819 14:08:49.416229 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetCapabilities call I0819 14:08:49.419447 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetId call I0819 14:08:49.421800 4274 provider.cpp:677] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0819 14:08:49.421972 4273 status_update_manager_process.hpp:379] Pausing operation status update manager I0819 14:08:49.422565 4272 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:36585/slave(1247)/api/v1/resource_provider I0819 14:08:49.426554 4281 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:36585/slave(1247)/api/v1/resource_provider I0819 14:08:49.427101 4271 hierarchical.cpp:1933] Performed allocation for 1 agents in 192885ns I0819 14:08:49.427191 4280 provider.cpp:476] Connected to resource provider manager I0819 14:08:49.427841 4265 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:36585/slave(1247)/api/v1/resource_provider I0819 14:08:49.429051 4266 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1/resource_provider' I0819 14:08:49.431038 4263 http.cpp:1436] HTTP POST for /slave(1247)/api/v1/resource_provider from 172.17.0.2:59936 I0819 14:08:49.431684 4272 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_kdkExH","--available_capacity=0B","--volumes=","--forward=unix:///tmp/ZIi2Tr/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.11.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"} I0819 14:08:49.478472 4264 hierarchical.cpp:1933] Performed allocation for 1 agents in 193602ns I0819 14:08:49.480367 4286 slave.cpp:8714] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"91351d36-89c3-4d94-9cc8-75d6ada9ded7"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_kdkExH","--available_capacity=0B","--volumes=","--forward=unix:///tmp/ZIi2Tr/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.11.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"}' I0819 14:08:49.482395 4268 provider.cpp:498] Received SUBSCRIBED event I0819 14:08:49.482435 4268 provider.cpp:1310] Subscribed with ID 91351d36-89c3-4d94-9cc8-75d6ada9ded7 I0819 14:08:49.483305 4274 status_update_manager_process.hpp:314] Recovering operation status update manager I0819 14:08:49.530356 4284 hierarchical.cpp:1933] Performed allocation for 1 agents in 192388ns I0819 14:08:49.546882 4263 provider.cpp:791] Reconciling storage pools and volumes I0819 14:08:49.549461 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0819 14:08:49.552662 4266 provider.cpp:2218] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 I0819 14:08:49.552970 4276 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:36585/slave(1247)/api/v1/resource_provider I0819 14:08:49.553022 4266 provider.cpp:749] Resource provider 91351d36-89c3-4d94-9cc8-75d6ada9ded7 is in READY state I0819 14:08:49.553105 4268 status_update_manager_process.hpp:385] Resuming operation status update manager I0819 14:08:49.553758 4284 provider.cpp:1236] Updating profiles { test } for resource provider 91351d36-89c3-4d94-9cc8-75d6ada9ded7 I0819 14:08:49.554646 4270 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1/resource_provider' I0819 14:08:49.554908 4281 provider.cpp:791] Reconciling storage pools and volumes I0819 14:08:49.556555 4284 http.cpp:1436] HTTP POST for /slave(1247)/api/v1/resource_provider from 172.17.0.2:59934 I0819 14:08:49.557080 4283 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 91351d36-89c3-4d94-9cc8-75d6ada9ded7 I0819 14:08:49.557266 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0819 14:08:49.557289 4267 slave.cpp:8714] Handling resource provider message 'UPDATE_STATE: 91351d36-89c3-4d94-9cc8-75d6ada9ded7 {}' I0819 14:08:49.557407 4267 slave.cpp:8834] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0819 14:08:49.557690 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0819 14:08:49.559482 4282 hierarchical.cpp:1190] Grew agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 by {} (total), { } (used) I0819 14:08:49.560040 4282 hierarchical.cpp:1147] Agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 (455040d4d5e3) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0819 14:08:49.564497 4283 hierarchical.cpp:1933] Performed allocation for 1 agents in 149872ns I0819 14:08:49.565021 4265 provider.cpp:791] Reconciling storage pools and volumes I0819 14:08:49.567365 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0819 14:08:49.568073 18706 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0819 14:08:49.577975 4278 slave.cpp:1000] Agent terminating I0819 14:08:49.578771 4278 manager.cpp:127] Terminating resource provider 91351d36-89c3-4d94-9cc8-75d6ada9ded7 I0819 14:08:49.579345 4276 master.cpp:1294] Agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 at slave(1247)@172.17.0.2:36585 (455040d4d5e3) disconnected I0819 14:08:49.579391 4276 master.cpp:3413] Disconnecting agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 at slave(1247)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:49.579478 4276 master.cpp:3432] Deactivating agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 at slave(1247)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:49.579622 4270 hierarchical.cpp:1236] Agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 deactivated E0819 14:08:49.580019 4264 http_connection.hpp:449] End-Of-File received I0819 14:08:49.580567 4264 http_connection.hpp:217] Re-detecting endpoint I0819 14:08:49.581007 4264 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0819 14:08:49.581079 4264 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0819 14:08:49.581106 4283 provider.cpp:488] Disconnected from resource provider manager I0819 14:08:49.581151 4264 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:36585/slave(1247)/api/v1/resource_provider I0819 14:08:49.581230 4268 status_update_manager_process.hpp:379] Pausing operation status update manager I0819 14:08:49.582736 4267 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0819 14:08:49.582809 4267 containerizer.cpp:3414] 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.639561984secs I0819 14:08:49.583228 4267 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:49.584153 4285 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:36585/slave(1247)/api/v1/resource_provider I0819 14:08:49.584848 4274 provider.cpp:476] Connected to resource provider manager I0819 14:08:49.585805 4283 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:36585/slave(1247)/api/v1/resource_provider I0819 14:08:49.586663 4287 process.cpp:2781] Returning '404 Not Found' for '/slave(1247)/api/v1/resource_provider' E0819 14:08:49.587911 4282 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0819 14:08:49.611008 4278 hierarchical.cpp:1933] Performed allocation for 1 agents in 169237ns I0819 14:08:49.661551 4276 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0819 14:08:49.661867 4263 hierarchical.cpp:1933] Performed allocation for 1 agents in 172022ns I0819 14:08:49.663331 4283 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 I0819 14:08:49.665913 4266 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' I0819 14:08:49.666095 4269 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-o49FOt/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:49.666291 4285 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:49.668901 4287 process.cpp:2781] Returning '404 Not Found' for '/slave(1247)/api/v1' I0819 14:08:49.679383 4277 master.cpp:1142] Master terminating I0819 14:08:49.679738 4270 hierarchical.cpp:1212] Removed all filters for agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 I0819 14:08:49.679781 4270 hierarchical.cpp:1088] Removed agent 20a82097-6704-4c12-85b8-44aecc0623f6-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (868 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 I0819 14:08:49.697249 4262 cluster.cpp:186] Creating default 'local' authorizer I0819 14:08:49.702822 4286 master.cpp:445] Master 39b6b829-d60f-4535-818f-4820615671a0 (455040d4d5e3) started on 172.17.0.2:36585 I0819 14:08:49.702853 4286 master.cpp:448] 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/Pt5v53/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.11.0/_inst/share/mesos/webui" --work_dir="/tmp/Pt5v53/master" --zk_session_timeout="10secs" I0819 14:08:49.703238 4286 master.cpp:497] Master only allowing authenticated frameworks to register I0819 14:08:49.703253 4286 master.cpp:503] Master only allowing authenticated agents to register I0819 14:08:49.703263 4286 master.cpp:509] Master only allowing authenticated HTTP frameworks to register I0819 14:08:49.703274 4286 credentials.hpp:37] Loading credentials for authentication from '/tmp/Pt5v53/credentials' I0819 14:08:49.703550 4286 master.cpp:553] Using default 'crammd5' authenticator I0819 14:08:49.703773 4286 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0819 14:08:49.704017 4286 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0819 14:08:49.704202 4286 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0819 14:08:49.704387 4286 master.cpp:634] Authorization enabled I0819 14:08:49.704902 4268 hierarchical.cpp:637] Initialized hierarchical allocator process I0819 14:08:49.704934 4274 whitelist_watcher.cpp:77] No whitelist given I0819 14:08:49.708508 4279 master.cpp:2167] Elected as the leading master! I0819 14:08:49.708554 4279 master.cpp:1663] Recovering from registrar I0819 14:08:49.708856 4281 registrar.cpp:339] Recovering registrar I0819 14:08:49.709730 4281 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0819 14:08:49.709877 4281 registrar.cpp:487] Applied 1 operations in 45297ns; attempting to update the registry I0819 14:08:49.710574 4281 registrar.cpp:544] Successfully updated the registry in 0ns I0819 14:08:49.710718 4281 registrar.cpp:416] Successfully recovered registrar I0819 14:08:49.711181 4278 master.cpp:1816] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0819 14:08:49.711208 4282 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover W0819 14:08:49.718403 4262 process.cpp:2877] Attempted to spawn already running process [email protected]:36585 I0819 14:08:49.719993 4262 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0819 14:08:49.720679 4262 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0819 14:08:49.720711 4262 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0819 14:08:49.720729 4262 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0819 14:08:49.720767 4262 provisioner.cpp:294] Using default backend 'copy' I0819 14:08:49.723804 4262 cluster.cpp:533] Creating default 'local' authorizer I0819 14:08:49.727368 4269 slave.cpp:279] Mesos agent started on (1248)@172.17.0.2:36585 I0819 14:08:49.727398 4269 slave.cpp:280] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/Pt5v53/5lzXKc/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/Pt5v53/5lzXKc/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/Pt5v53/5lzXKc/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/Pt5v53/5lzXKc/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/Pt5v53/5lzXKc/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/Pt5v53/5lzXKc/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.11.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/Pt5v53/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_PCGM4U" --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_LxpCoD" --zk_session_timeout="10secs" I0819 14:08:49.727938 4269 credentials.hpp:73] Loading credential for authentication from '/tmp/Pt5v53/5lzXKc/credential' I0819 14:08:49.728121 4269 slave.cpp:312] Agent using credential for: test-principal I0819 14:08:49.728147 4269 credentials.hpp:37] Loading credentials for authentication from '/tmp/Pt5v53/5lzXKc/http_credentials' I0819 14:08:49.728374 4269 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0819 14:08:49.728916 4269 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0819 14:08:49.730813 4286 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0819 14:08:49.730829 4269 slave.cpp:627] 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"}] I0819 14:08:49.731093 4269 slave.cpp:635] Agent attributes: [ ] I0819 14:08:49.731114 4269 slave.cpp:644] Agent hostname: 455040d4d5e3 I0819 14:08:49.731348 4279 status_update_manager_process.hpp:379] Pausing operation status update manager I0819 14:08:49.731381 4265 task_status_update_manager.cpp:181] Pausing sending task status updates I0819 14:08:49.732843 4285 hierarchical.cpp:1933] Performed allocation for 0 agents in 117371ns I0819 14:08:49.733394 4271 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_LxpCoD/meta' I0819 14:08:49.733737 4272 slave.cpp:7723] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_LxpCoD/meta', beginning agent recovery I0819 14:08:49.734468 4267 task_status_update_manager.cpp:207] Recovering task status update manager I0819 14:08:49.734899 4278 containerizer.cpp:830] Recovering Mesos containers I0819 14:08:49.735276 4278 containerizer.cpp:1170] Recovering isolators I0819 14:08:49.736428 4279 containerizer.cpp:1209] Recovering provisioner I0819 14:08:49.737365 4285 provisioner.cpp:518] Provisioner recovery complete I0819 14:08:49.738270 4267 composing.cpp:343] Finished recovering all containerizers I0819 14:08:49.738701 4263 slave.cpp:8205] Recovering executors I0819 14:08:49.738850 4263 slave.cpp:8358] Finished recovery I0819 14:08:49.739933 4283 task_status_update_manager.cpp:181] Pausing sending task status updates I0819 14:08:49.739964 4280 status_update_manager_process.hpp:379] Pausing operation status update manager I0819 14:08:49.739986 4275 slave.cpp:1471] New master detected at [email protected]:36585 I0819 14:08:49.740151 4275 slave.cpp:1536] Detecting new master I0819 14:08:49.747608 4278 slave.cpp:1563] Authenticating with master [email protected]:36585 I0819 14:08:49.747756 4278 slave.cpp:1572] Using default CRAM-MD5 authenticatee I0819 14:08:49.748200 4282 authenticatee.cpp:121] Creating new client SASL connection I0819 14:08:49.748651 4270 master.cpp:9720] Authenticating slave(1248)@172.17.0.2:36585 I0819 14:08:49.748884 4265 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2114)@172.17.0.2:36585 I0819 14:08:49.749265 4286 authenticator.cpp:98] Creating new server SASL connection I0819 14:08:49.749619 4284 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0819 14:08:49.749670 4284 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0819 14:08:49.749842 4285 authenticator.cpp:204] Received SASL authentication start I0819 14:08:49.749948 4285 authenticator.cpp:326] Authentication requires more steps I0819 14:08:49.750123 4285 authenticatee.cpp:259] Received SASL authentication step I0819 14:08:49.750325 4276 authenticator.cpp:232] Received SASL authentication step I0819 14:08:49.750381 4276 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '455040d4d5e3' server FQDN: '455040d4d5e3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0819 14:08:49.750403 4276 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0819 14:08:49.750465 4276 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0819 14:08:49.750509 4276 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '455040d4d5e3' server FQDN: '455040d4d5e3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0819 14:08:49.750543 4276 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0819 14:08:49.750573 4276 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0819 14:08:49.750607 4276 authenticator.cpp:318] Authentication success I0819 14:08:49.750748 4272 authenticatee.cpp:299] Authentication success I0819 14:08:49.750893 4264 master.cpp:9752] Successfully authenticated principal 'test-principal' at slave(1248)@172.17.0.2:36585 I0819 14:08:49.750964 4271 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2114)@172.17.0.2:36585 I0819 14:08:49.751283 4277 slave.cpp:1663] Successfully authenticated with master [email protected]:36585 I0819 14:08:49.751850 4277 slave.cpp:2113] Will retry registration in 15.054578ms if necessary I0819 14:08:49.752180 4274 master.cpp:6214] Received register agent message from slave(1248)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:49.752817 4274 master.cpp:3745] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0819 14:08:49.753674 4275 master.cpp:6281] Authorized registration of agent at slave(1248)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:49.753819 4275 master.cpp:6393] Registering agent at slave(1248)@172.17.0.2:36585 (455040d4d5e3) with id 39b6b829-d60f-4535-818f-4820615671a0-S0 I0819 14:08:49.754824 4279 registrar.cpp:487] Applied 1 operations in 330095ns; attempting to update the registry I0819 14:08:49.756018 4279 registrar.cpp:544] Successfully updated the registry in 1.103872ms I0819 14:08:49.756331 4286 master.cpp:6441] Admitted agent 39b6b829-d60f-4535-818f-4820615671a0-S0 at slave(1248)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:49.757438 4286 master.cpp:6486] Registered agent 39b6b829-d60f-4535-818f-4820615671a0-S0 at slave(1248)@172.17.0.2:36585 (455040d4d5e3) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0819 14:08:49.757601 4269 slave.cpp:1696] Registered with master [email protected]:36585; given agent ID 39b6b829-d60f-4535-818f-4820615671a0-S0 I0819 14:08:49.757733 4284 hierarchical.cpp:1039] Added agent 39b6b829-d60f-4535-818f-4820615671a0-S0 (455040d4d5e3) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0819 14:08:49.757776 4264 task_status_update_manager.cpp:188] Resuming sending task status updates I0819 14:08:49.758177 4284 hierarchical.cpp:1933] Performed allocation for 1 agents in 168160ns I0819 14:08:49.758222 4269 slave.cpp:1731] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_LxpCoD/meta/slaves/39b6b829-d60f-4535-818f-4820615671a0-S0/slave.info' I0819 14:08:49.758312 4267 status_update_manager_process.hpp:385] Resuming operation status update manager I0819 14:08:49.759877 4269 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"rrgaheO0QsqWfBoVB4HVQw=="},"slave_id":{"value":"39b6b829-d60f-4535-818f-4820615671a0-S0"},"update_oversubscribed_resources":false} I0819 14:08:49.760848 4271 master.cpp:7628] Ignoring update on agent 39b6b829-d60f-4535-818f-4820615671a0-S0 at slave(1248)@172.17.0.2:36585 (455040d4d5e3) as it reports no changes I0819 14:08:49.765765 4279 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1' I0819 14:08:49.767314 4267 http.cpp:1436] HTTP POST for /slave(1248)/api/v1 from 172.17.0.2:59952 I0819 14:08:49.768232 4267 http.cpp:2828] Processing GET_CONTAINERS call I0819 14:08:49.775900 4265 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:49.779594 4276 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1' I0819 14:08:49.781145 4267 http.cpp:1436] HTTP POST for /slave(1248)/api/v1 from 172.17.0.2:59954 I0819 14:08:49.782411 4267 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:49.783898 4267 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_LxpCoD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:49.783967 4266 hierarchical.cpp:1933] Performed allocation for 1 agents in 212999ns I0819 14:08:49.784775 4267 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:49.785674 4267 containerizer.cpp:3414] 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 390144ns I0819 14:08:49.787122 4267 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_PCGM4U/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0819 14:08:49.787195 4267 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.523968ms I0819 14:08:49.790355 4270 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_RTftIl","--available_capacity=0B","--volumes=","--forward=unix:///tmp/Pt5v53/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_LxpCoD/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-qdMkUl/endpoint.sock"},{"name":"MESOS_AGENT_ID","type":"VALUE","value":"39b6b829-d60f-4535-818f-4820615671a0-S0"}]},"task_environment":{},"working _directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_LxpCoD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="112" --pipe_write="113" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_PCGM4U/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0819 14:08:49.802132 4270 launcher.cpp:145] Forked child with pid '18719' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:49.803159 4270 containerizer.cpp:3414] 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.952896ms I0819 14:08:49.804757 4270 containerizer.cpp:3414] 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.598976ms I0819 14:08:49.805104 4269 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_LxpCoD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:49.806298 4277 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 1.483008ms I0819 14:08:49.810091 4267 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' I0819 14:08:49.810326 4267 service_manager.cpp:795] Connecting to endpoint 'unix:///tmp/mesos-csi-qdMkUl/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:49.835440 4285 hierarchical.cpp:1933] Performed allocation for 1 agents in 191387ns I0819 14:08:49.886801 4270 hierarchical.cpp:1933] Performed allocation for 1 agents in 250832ns I0819 14:08:49.937863 4272 hierarchical.cpp:1933] Performed allocation for 1 agents in 200755ns I0819 14:08:49.988991 4265 hierarchical.cpp:1933] Performed allocation for 1 agents in 190671ns I0819 14:08:50.040302 4264 hierarchical.cpp:1933] Performed allocation for 1 agents in 190009ns I0819 14:08:50.091970 4277 hierarchical.cpp:1933] Performed allocation for 1 agents in 212151ns I0819 14:08:50.143124 4274 hierarchical.cpp:1933] Performed allocation for 1 agents in 254734ns I0819 14:08:50.194968 4279 hierarchical.cpp:1933] Performed allocation for 1 agents in 194481ns I0819 14:08:50.246419 4284 hierarchical.cpp:1933] Performed allocation for 1 agents in 195256ns I0819 14:08:50.272892 4271 service_manager.cpp:622] Probing endpoint 'unix:///tmp/mesos-csi-qdMkUl/endpoint.sock' with CSI v1 I0819 14:08:50.275027 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call I0819 14:08:50.278602 4275 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:50.281833 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call I0819 14:08:50.282485 4285 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1' I0819 14:08:50.283998 4270 http.cpp:1436] HTTP POST for /slave(1248)/api/v1 from 172.17.0.2:60010 I0819 14:08:50.284713 4270 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:50.287870 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0819 14:08:50.288344 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0819 14:08:50.290446 4282 v1_volume_manager.cpp:674] NODE_SERVICE loaded: {} I0819 14:08:50.291215 4282 v1_volume_manager.cpp:674] CONTROLLER_SERVICE loaded: {} I0819 14:08:50.294052 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call I0819 14:08:50.297857 4281 hierarchical.cpp:1933] Performed allocation for 1 agents in 274059ns I0819 14:08:50.299726 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call I0819 14:08:50.303875 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call I0819 14:08:50.306552 4273 provider.cpp:677] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0819 14:08:50.306813 4275 status_update_manager_process.hpp:379] Pausing operation status update manager I0819 14:08:50.307302 4264 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:36585/slave(1248)/api/v1/resource_provider I0819 14:08:50.313300 4279 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:36585/slave(1248)/api/v1/resource_provider I0819 14:08:50.314100 4281 provider.cpp:476] Connected to resource provider manager I0819 14:08:50.315357 4266 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:36585/slave(1248)/api/v1/resource_provider I0819 14:08:50.316934 4271 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider' I0819 14:08:50.319489 4273 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:60014 I0819 14:08:50.320274 4273 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_RTftIl","--available_capacity=0B","--volumes=","--forward=unix:///tmp/Pt5v53/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.11.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"} I0819 14:08:50.349534 4276 hierarchical.cpp:1933] Performed allocation for 1 agents in 195572ns I0819 14:08:50.355878 4284 slave.cpp:8714] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"d90e1ca2-9837-4ecd-a3ed-42488e01750a"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.11.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_RTftIl","--available_capacity=0B","--volumes=","--forward=unix:///tmp/Pt5v53/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.11.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"}' I0819 14:08:50.358161 4263 provider.cpp:498] Received SUBSCRIBED event I0819 14:08:50.358213 4263 provider.cpp:1310] Subscribed with ID d90e1ca2-9837-4ecd-a3ed-42488e01750a I0819 14:08:50.359180 4275 status_update_manager_process.hpp:314] Recovering operation status update manager I0819 14:08:50.401422 4273 hierarchical.cpp:1933] Performed allocation for 1 agents in 191662ns I0819 14:08:50.413657 4274 provider.cpp:791] Reconciling storage pools and volumes I0819 14:08:50.416494 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0819 14:08:50.419376 4281 provider.cpp:2218] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 39b6b829-d60f-4535-818f-4820615671a0-S0 I0819 14:08:50.419705 4271 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:36585/slave(1248)/api/v1/resource_provider I0819 14:08:50.419775 4281 provider.cpp:749] Resource provider d90e1ca2-9837-4ecd-a3ed-42488e01750a is in READY state I0819 14:08:50.419901 4283 status_update_manager_process.hpp:385] Resuming operation status update manager I0819 14:08:50.420598 4273 provider.cpp:1236] Updating profiles { test } for resource provider d90e1ca2-9837-4ecd-a3ed-42488e01750a I0819 14:08:50.421105 4276 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider' I0819 14:08:50.421767 4278 provider.cpp:791] Reconciling storage pools and volumes I0819 14:08:50.423157 4271 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:60012 I0819 14:08:50.423908 4275 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider d90e1ca2-9837-4ecd-a3ed-42488e01750a I0819 14:08:50.424135 4279 slave.cpp:8714] Handling resource provider message 'UPDATE_STATE: d90e1ca2-9837-4ecd-a3ed-42488e01750a {}' I0819 14:08:50.424235 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0819 14:08:50.424244 4279 slave.cpp:8834] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0819 14:08:50.424685 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0819 14:08:50.426224 4272 hierarchical.cpp:1190] Grew agent 39b6b829-d60f-4535-818f-4820615671a0-S0 by {} (total), { } (used) I0819 14:08:50.426600 4272 hierarchical.cpp:1147] Agent 39b6b829-d60f-4535-818f-4820615671a0-S0 (455040d4d5e3) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0819 14:08:50.431531 4268 hierarchical.cpp:1933] Performed allocation for 1 agents in 303994ns I0819 14:08:50.431640 4286 provider.cpp:791] Reconciling storage pools and volumes I0819 14:08:50.434178 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0819 14:08:50.434545 18723 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0819 14:08:50.445132 4285 slave.cpp:1000] Agent terminating I0819 14:08:50.445878 4285 manager.cpp:127] Terminating resource provider d90e1ca2-9837-4ecd-a3ed-42488e01750a I0819 14:08:50.446417 4283 master.cpp:1294] Agent 39b6b829-d60f-4535-818f-4820615671a0-S0 at slave(1248)@172.17.0.2:36585 (455040d4d5e3) disconnected I0819 14:08:50.446463 4283 master.cpp:3413] Disconnecting agent 39b6b829-d60f-4535-818f-4820615671a0-S0 at slave(1248)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:50.446565 4283 master.cpp:3432] Deactivating agent 39b6b829-d60f-4535-818f-4820615671a0-S0 at slave(1248)@172.17.0.2:36585 (455040d4d5e3) I0819 14:08:50.446766 4271 hierarchical.cpp:1236] Agent 39b6b829-d60f-4535-818f-4820615671a0-S0 deactivated E0819 14:08:50.447067 4281 http_connection.hpp:449] End-Of-File received I0819 14:08:50.447582 4281 http_connection.hpp:217] Re-detecting endpoint I0819 14:08:50.448029 4281 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0819 14:08:50.448084 4281 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0819 14:08:50.448128 4268 provider.cpp:488] Disconnected from resource provider manager I0819 14:08:50.448150 4281 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:36585/slave(1248)/api/v1/resource_provider I0819 14:08:50.448336 4272 status_update_manager_process.hpp:379] Pausing operation status update manager I0819 14:08:50.449697 4285 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0819 14:08:50.449753 4285 containerizer.cpp:3414] 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.643529984secs I0819 14:08:50.450196 4285 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:50.451117 4278 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:36585/slave(1248)/api/v1/resource_provider I0819 14:08:50.451727 4280 provider.cpp:476] Connected to resource provider manager I0819 14:08:50.452451 4279 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:36585/slave(1248)/api/v1/resource_provider I0819 14:08:50.453385 4287 process.cpp:2781] Returning '404 Not Found' for '/slave(1248)/api/v1/resource_provider' E0819 14:08:50.454712 4267 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0819 14:08:50.478025 4281 hierarchical.cpp:1933] Performed allocation for 1 agents in 152150ns I0819 14:08:50.527554 4270 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0819 14:08:50.529625 4278 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 I0819 14:08:50.530055 4275 hierarchical.cpp:1933] Performed allocation for 1 agents in 206368ns I0819 14:08:50.532352 4281 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' I0819 14:08:50.532622 4282 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-qdMkUl/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0819 14:08:50.532888 4271 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0819 14:08:50.535666 4287 process.cpp:2781] Returning '404 Not Found' for '/slave(1248)/api/v1' I0819 14:08:50.550438 4262 master.cpp:1142] Master terminating I0819 14:08:50.550827 4273 hierarchical.cpp:1212] Removed all filters for agent 39b6b829-d60f-4535-818f-4820615671a0-S0 I0819 14:08:50.550875 4273 hierarchical.cpp:1088] Removed agent 39b6b829-d60f-4535-818f-4820615671a0-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (873 ms) [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (133453 ms total) [----------] Global test environment tear-down [==========] 2334 tests from 224 test cases ran. (1420030 ms total) [ PASSED ] 2333 tests. [ FAILED ] 1 test, listed below: [ FAILED ] ExamplesTest.PythonFramework 1 FAILED TEST YOU HAVE 34 DISABLED TESTS I0819 14:08:50.676327 4287 process.cpp:935] Stopped the socket accept loop Makefile:16020: recipe for target 'check-local' failed make[4]: *** [check-local] Error 1 make[4]: Leaving directory '/tmp/SRC/build/mesos-1.11.0/_build/sub/src' Makefile:15128: recipe for target 'check-am' failed make[3]: *** [check-am] Error 2 make[3]: Leaving directory '/tmp/SRC/build/mesos-1.11.0/_build/sub/src' Makefile:15132: recipe for target 'check' failed make[2]: *** [check] Error 2 make[2]: Leaving directory '/tmp/SRC/build/mesos-1.11.0/_build/sub/src' Makefile:785: recipe for target 'check-recursive' failed make[1]: *** [check-recursive] Error 1 make[1]: Leaving directory '/tmp/SRC/build/mesos-1.11.0/_build/sub' Makefile:991: recipe for target 'distcheck' failed make: *** [distcheck] Error 1 Untagged: mesos/mesos-build:ubuntu-16.04 Untagged: mesos/mesos-build@sha256:fa967cbcfb44f55708a3cbc87f245c6d29dd891464db558af56a03ee321526bb Deleted: sha256:e895c0531b9a9a288fabe479a49f7059aed83645351ac99ec2ea2616822c9f97 Deleted: sha256:09119b0b314a69ba6ec6251f2e89f4199fe1e874c84f9abf07dcbd23dbc3f1c1 Deleted: sha256:562fe6af5a3883058be9c784a839392215ed4185a21d21f1d99df0d17f3ae6e7 Deleted: sha256:0dcdfbe322a4f332f73ac70905d557300ec6dae3bd19586758772c750c7b4a19 Deleted: sha256:c66652d605f01094e2db53d62505dbd524e076d5aa69b89d5e620003803eb149 Deleted: sha256:a2cf79bfb9593c05fd7142ddb49afef77ea4ad5d2464e841f09fe62ffee396e0 Deleted: sha256:f7a904214b390f39d98573882f631dc908df8b2b540cf04e1062f8182c1efffd Deleted: sha256:ce1f6fcaa83dfce189d76e08f184085732eab4eeb2562d2399953958405c5bec Deleted: sha256:cce92fda689ab9033f0b8db214bc63edd1ae3e05831a0f3a9418976d7dc7ccdd Deleted: sha256:d22094bbd65447c59a42c580eaa3a44cee9cd855f00905f59409be21bcefc745 Deleted: sha256:b8976847450013f3eb5e9a81a5778f73ed7bef67e6393049712ef17102b4b7b7 Deleted: sha256:b8c891f0ffec910a12757d733b178e3f62d81dbbde2b31d3b754071c416108ed Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/11997/console - Mesos Reviewbot On Aug. 19, 2020, 12:09 p.m., Andrei Sekretenko wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/72787/ > ----------------------------------------------------------- > > (Updated Aug. 19, 2020, 12:09 p.m.) > > > Review request for mesos and Benjamin Mahler. > > > Bugs: MESOS-10173 > https://issues.apache.org/jira/browse/MESOS-10173 > > > Repository: mesos > > > Description > ------- > > Added basic tests for regexp-based constraints. > > > Diffs > ----- > > src/tests/master/offer_constraints_filter_tests.cpp PRE-CREATION > > > Diff: https://reviews.apache.org/r/72787/diff/2/ > > > Testing > ------- > > > Thanks, > > Andrei Sekretenko > >
