----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/72233/#review219929 -----------------------------------------------------------
Bad patch! Reviews applied: [72233] 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_72233"] Error: ...<truncated>... atus update OPERATION_FINISHED (Status UUID: 8bd91c02-2b7a-4d76-8a5b-4ac211bee585) for operation UUID 98d3bdb4-9d59-433b-adac-3668a25ed339 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.156639 3082 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:43769/slave(1237)/api/v1/resource_provider I0313 00:06:49.158118 3096 process.cpp:3671] Handling HTTP event for process 'slave(1237)' with path: '/slave(1237)/api/v1/resource_provider' I0313 00:06:49.162569 3088 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.764905ms I0313 00:06:49.163259 3092 master.cpp:9485] Sending offers [ a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O3 ] to framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 I0313 00:06:49.163908 3092 sched.cpp:934] Scheduler::resourceOffers took 82296ns I0313 00:06:49.167528 3085 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0313 00:06:49.170282 3083 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:59554 I0313 00:06:49.170552 3083 http.cpp:277] Processing call CREATE_VOLUMES I0313 00:06:49.171536 3083 master.cpp:3705] Authorizing principal 'test-principal' to perform action CREATE_VOLUME on object {"value":"storage/default-role","resource":{"provider_id":{"value":"09cf7286-d072-4e9f-b244-fac5e5f263af"},"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":"a19b626b-4ba9-4163-8cb8-4af013820fd3","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_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa","profile":"test"}}}} I0313 00:06:49.173388 3091 sched.cpp:960] Rescinded offer a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O3 I0313 00:06:49.173463 3091 sched.cpp:971] Scheduler::offerRescinded took 23066ns I0313 00:06:49.173961 3092 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa,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_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa,test)]:2048, offered or allocated: {}) on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 from framework a330d 48b-9410-478c-8b3a-a92f5a5a0d6e-0000 I0313 00:06:49.174172 3096 master.cpp:11784] Removing offer a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O3 I0313 00:06:49.175734 3092 hierarchical.cpp:1625] Framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 filtered agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 for 5secs I0313 00:06:49.178416 3085 master.cpp:11649] Sending operation '' (uuid: 17a3a443-f24e-4549-ba5a-31cb147963f5) to agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 at slave(1237)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:49.179114 3087 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0313 00:06:49.182605 3090 provider.cpp:498] Received APPLY_OPERATION event I0313 00:06:49.182662 3090 provider.cpp:1351] Received CREATE operation '' (uuid: 17a3a443-f24e-4549-ba5a-31cb147963f5) I0313 00:06:49.185658 3086 master.cpp:5533] Processing REVIVE call for framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 I0313 00:06:49.186375 3086 hierarchical.cpp:1721] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 I0313 00:06:49.187953 3086 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.307842ms I0313 00:06:49.188395 3086 hierarchical.cpp:1853] Performed allocation for 1 agents in 209409ns I0313 00:06:49.188756 3089 master.cpp:9485] Sending offers [ a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O4 ] to framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 I0313 00:06:49.189604 3081 sched.cpp:934] Scheduler::resourceOffers took 108479ns I0313 00:06:49.201472 3096 http.cpp:1405] HTTP POST for /slave(1237)/api/v1/resource_provider from 172.17.0.2:59548 I0313 00:06:49.202409 3092 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 98d3bdb4-9d59-433b-adac-3668a25ed339) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0313 00:06:49.202567 3092 slave.cpp:9050] Updating the state of operation with no ID (uuid: 98d3bdb4-9d59-433b-adac-3668a25ed339) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0313 00:06:49.202613 3092 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: 98d3bdb4-9d59-433b-adac-3668a25ed339) for an operator API call I0313 00:06:49.202987 3085 master.cpp:11301] Updating the state of operation '' (uuid: 98d3bdb4-9d59-433b-adac-3668a25ed339) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0313 00:06:49.203852 3093 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0313 00:06:49.289564 3092 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: de013c45-2628-402b-b4e2-b95499d3a5fd) for operation UUID 17a3a443-f24e-4549-ba5a-31cb147963f5 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.289623 3090 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0313 00:06:49.289636 3092 status_update_manager_process.hpp:414] Creating operation status update stream 17a3a443-f24e-4549-ba5a-31cb147963f5 checkpoint=true I0313 00:06:49.289903 3092 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: de013c45-2628-402b-b4e2-b95499d3a5fd) for operation UUID 17a3a443-f24e-4549-ba5a-31cb147963f5 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.362073 3092 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: de013c45-2628-402b-b4e2-b95499d3a5fd) for operation UUID 17a3a443-f24e-4549-ba5a-31cb147963f5 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.362403 3092 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 8bd91c02-2b7a-4d76-8a5b-4ac211bee585) for stream 98d3bdb4-9d59-433b-adac-3668a25ed339 I0313 00:06:49.362478 3092 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 8bd91c02-2b7a-4d76-8a5b-4ac211bee585) for operation UUID 98d3bdb4-9d59-433b-adac-3668a25ed339 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.363095 3088 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:43769/slave(1237)/api/v1/resource_provider I0313 00:06:49.364243 3089 process.cpp:3671] Handling HTTP event for process 'slave(1237)' with path: '/slave(1237)/api/v1/resource_provider' I0313 00:06:49.405709 3083 http.cpp:1405] HTTP POST for /slave(1237)/api/v1/resource_provider from 172.17.0.2:59548 I0313 00:06:49.407053 3084 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 17a3a443-f24e-4549-ba5a-31cb147963f5) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0313 00:06:49.407313 3084 slave.cpp:9050] Updating the state of operation with no ID (uuid: 17a3a443-f24e-4549-ba5a-31cb147963f5) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0313 00:06:49.407400 3084 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: 17a3a443-f24e-4549-ba5a-31cb147963f5) for an operator API call I0313 00:06:49.407866 3090 master.cpp:11301] Updating the state of operation '' (uuid: 17a3a443-f24e-4549-ba5a-31cb147963f5) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0313 00:06:49.408469 3088 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0313 00:06:49.410112 3083 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0313 00:06:49.412149 3092 status_update_manager_process.hpp:490] Cleaning up operation status update stream 98d3bdb4-9d59-433b-adac-3668a25ed339 I0313 00:06:49.412338 3092 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: de013c45-2628-402b-b4e2-b95499d3a5fd) for stream 17a3a443-f24e-4549-ba5a-31cb147963f5 I0313 00:06:49.412403 3092 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: de013c45-2628-402b-b4e2-b95499d3a5fd) for operation UUID 17a3a443-f24e-4549-ba5a-31cb147963f5 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.482355 3092 status_update_manager_process.hpp:490] Cleaning up operation status update stream 17a3a443-f24e-4549-ba5a-31cb147963f5 I0313 00:06:49.543581 3093 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0313 00:06:49.546072 3081 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:59556 I0313 00:06:49.546350 3081 http.cpp:277] Processing call DESTROY_VOLUMES I0313 00:06:49.547482 3081 master.cpp:3705] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"09cf7286-d072-4e9f-b244-fac5e5f263af"},"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":"a19b626b-4ba9-4163-8cb8-4af013820fd3","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_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa","profile":"test"}}}} I0313 00:06:49.549583 3083 sched.cpp:960] Rescinded offer a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O4 I0313 00:06:49.549680 3083 sched.cpp:971] Scheduler::offerRescinded took 26200ns I0313 00:06:49.550285 3092 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa,test),a19b626b-4ba9-4163-8cb8-4af013820fd3: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_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa,test),a19b626b-4ba9-4163-8cb8-4af013820fd3:volume]:2048, offered or allocated: {}) on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 from framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 I0313 00:06:49.550417 3082 master.cpp:11784] Removing offer a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O4 I0313 00:06:49.552570 3092 hierarchical.cpp:1625] Framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 filtered agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 for 5secs I0313 00:06:49.556190 3090 master.cpp:11649] Sending operation '' (uuid: e911cdb4-91d1-40ce-a165-f65a79f0eaa3) to agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 at slave(1237)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:49.556963 3089 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0313 00:06:49.560705 3084 provider.cpp:498] Received APPLY_OPERATION event I0313 00:06:49.560770 3084 provider.cpp:1351] Received DESTROY operation '' (uuid: e911cdb4-91d1-40ce-a165-f65a79f0eaa3) I0313 00:06:49.564193 3085 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.229909ms I0313 00:06:49.564985 3096 master.cpp:9485] Sending offers [ a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O5 ] to framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 I0313 00:06:49.565783 3096 sched.cpp:934] Scheduler::resourceOffers took 91443ns I0313 00:06:49.658778 3093 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 14a09f2f-85d2-44e2-869d-a632a4e76a17) for operation UUID e911cdb4-91d1-40ce-a165-f65a79f0eaa3 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.658870 3093 status_update_manager_process.hpp:414] Creating operation status update stream e911cdb4-91d1-40ce-a165-f65a79f0eaa3 checkpoint=true I0313 00:06:49.659224 3093 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 14a09f2f-85d2-44e2-869d-a632a4e76a17) for operation UUID e911cdb4-91d1-40ce-a165-f65a79f0eaa3 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.724579 3093 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 14a09f2f-85d2-44e2-869d-a632a4e76a17) for operation UUID e911cdb4-91d1-40ce-a165-f65a79f0eaa3 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.725620 3089 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:43769/slave(1237)/api/v1/resource_provider I0313 00:06:49.726660 3088 process.cpp:3671] Handling HTTP event for process 'slave(1237)' with path: '/slave(1237)/api/v1/resource_provider' I0313 00:06:49.730278 3083 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I0313 00:06:49.732432 3084 http.cpp:1405] HTTP POST for /master/api/v1 from 172.17.0.2:59558 I0313 00:06:49.732772 3084 http.cpp:277] Processing call UNRESERVE_RESOURCES I0313 00:06:49.733669 3084 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"09cf7286-d072-4e9f-b244-fac5e5f263af"},"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_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa","profile":"test"}}}} I0313 00:06:49.735277 3086 sched.cpp:960] Rescinded offer a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O5 I0313 00:06:49.735389 3086 sched.cpp:971] Scheduler::offerRescinded took 47122ns I0313 00:06:49.735859 3088 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa,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_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa,test)]:2048, offered or allocated: {}) on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 from framework a330d 48b-9410-478c-8b3a-a92f5a5a0d6e-0000 I0313 00:06:49.736093 3089 master.cpp:11784] Removing offer a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O5 I0313 00:06:49.737331 3088 hierarchical.cpp:1625] Framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 filtered agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 for 5secs I0313 00:06:49.739845 3091 master.cpp:11649] Sending operation '' (uuid: 6991cdf0-d7fd-423b-953d-a092daf50005) to agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 at slave(1237)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:49.740465 3091 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0313 00:06:49.743357 3082 provider.cpp:498] Received APPLY_OPERATION event I0313 00:06:49.743410 3082 provider.cpp:1351] Received UNRESERVE operation '' (uuid: 6991cdf0-d7fd-423b-953d-a092daf50005) I0313 00:06:49.750916 3092 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.273807ms I0313 00:06:49.751646 3085 master.cpp:9485] Sending offers [ a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O6 ] to framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 I0313 00:06:49.752351 3081 sched.cpp:934] Scheduler::resourceOffers took 83868ns I0313 00:06:49.769485 3095 http.cpp:1405] HTTP POST for /slave(1237)/api/v1/resource_provider from 172.17.0.2:59548 I0313 00:06:49.770766 3089 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: e911cdb4-91d1-40ce-a165-f65a79f0eaa3) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0313 00:06:49.770962 3089 slave.cpp:9050] Updating the state of operation with no ID (uuid: e911cdb4-91d1-40ce-a165-f65a79f0eaa3) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0313 00:06:49.771021 3089 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: e911cdb4-91d1-40ce-a165-f65a79f0eaa3) for an operator API call I0313 00:06:49.771340 3088 master.cpp:11301] Updating the state of operation '' (uuid: e911cdb4-91d1-40ce-a165-f65a79f0eaa3) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0313 00:06:49.771955 3083 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0313 00:06:49.856952 3089 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: f829b941-0f0e-4073-ba33-15ef6ae4e35a) for operation UUID 6991cdf0-d7fd-423b-953d-a092daf50005 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.857033 3082 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0313 00:06:49.857039 3089 status_update_manager_process.hpp:414] Creating operation status update stream 6991cdf0-d7fd-423b-953d-a092daf50005 checkpoint=true I0313 00:06:49.857437 3089 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: f829b941-0f0e-4073-ba33-15ef6ae4e35a) for operation UUID 6991cdf0-d7fd-423b-953d-a092daf50005 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.907124 3089 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: f829b941-0f0e-4073-ba33-15ef6ae4e35a) for operation UUID 6991cdf0-d7fd-423b-953d-a092daf50005 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.907480 3089 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 14a09f2f-85d2-44e2-869d-a632a4e76a17) for stream e911cdb4-91d1-40ce-a165-f65a79f0eaa3 I0313 00:06:49.907573 3089 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 14a09f2f-85d2-44e2-869d-a632a4e76a17) for operation UUID e911cdb4-91d1-40ce-a165-f65a79f0eaa3 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:49.907946 3087 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:43769/slave(1237)/api/v1/resource_provider I0313 00:06:49.908864 3081 process.cpp:3671] Handling HTTP event for process 'slave(1237)' with path: '/slave(1237)/api/v1/resource_provider' I0313 00:06:49.953750 3084 http.cpp:1405] HTTP POST for /slave(1237)/api/v1/resource_provider from 172.17.0.2:59548 I0313 00:06:49.954872 3095 slave.cpp:8597] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 6991cdf0-d7fd-423b-953d-a092daf50005) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I0313 00:06:49.955081 3095 slave.cpp:9050] Updating the state of operation with no ID (uuid: 6991cdf0-d7fd-423b-953d-a092daf50005) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I0313 00:06:49.955138 3095 slave.cpp:8804] Forwarding status update of operation with no ID (operation_uuid: 6991cdf0-d7fd-423b-953d-a092daf50005) for an operator API call I0313 00:06:49.955515 3082 master.cpp:11301] Updating the state of operation '' (uuid: 6991cdf0-d7fd-423b-953d-a092daf50005) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I0313 00:06:49.956064 3083 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version I0313 00:06:49.957893 3096 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I0313 00:06:49.959666 3089 status_update_manager_process.hpp:490] Cleaning up operation status update stream e911cdb4-91d1-40ce-a165-f65a79f0eaa3 I0313 00:06:49.959944 3089 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: f829b941-0f0e-4073-ba33-15ef6ae4e35a) for stream 6991cdf0-d7fd-423b-953d-a092daf50005 I0313 00:06:49.960019 3089 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: f829b941-0f0e-4073-ba33-15ef6ae4e35a) for operation UUID 6991cdf0-d7fd-423b-953d-a092daf50005 on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:50.025910 3089 status_update_manager_process.hpp:490] Cleaning up operation status update stream 6991cdf0-d7fd-423b-953d-a092daf50005 I0313 00:06:50.077294 3082 master.cpp:1407] Framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 disconnected I0313 00:06:50.077343 3082 master.cpp:3326] Deactivating framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 I0313 00:06:50.077639 3083 hierarchical.cpp:813] Deactivated framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 I0313 00:06:50.078107 3084 slave.cpp:995] Agent terminating I0313 00:06:50.078188 3085 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa,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_u1NRe6/2GB-0e93e415-ba68-4b66-bf0d-7bc7611ba6aa,test)]:2048, offered or allocated: {}) on agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 from framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 I0313 00:06:50.078599 3082 master.cpp:11784] Removing offer a330d48b-9410-478c-8b3a-a92f5a5a0d6e-O6 I0313 00:06:50.078693 3082 master.cpp:3310] Disconnecting framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 I0313 00:06:50.078871 3082 master.cpp:1422] Giving framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 0ns to failover I0313 00:06:50.079123 3084 manager.cpp:127] Terminating resource provider 09cf7286-d072-4e9f-b244-fac5e5f263af I0313 00:06:50.079687 3083 master.cpp:1292] Agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 at slave(1237)@172.17.0.2:43769 (b49bdfa63993) disconnected I0313 00:06:50.079732 3083 master.cpp:3361] Disconnecting agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 at slave(1237)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:50.079896 3083 master.cpp:3380] Deactivating agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 at slave(1237)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:50.080190 3083 master.cpp:9269] Framework failover timeout, removing framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 I0313 00:06:50.080229 3083 master.cpp:10285] Removing framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 (default) at [email protected]:43769 E0313 00:06:50.080364 3088 http_connection.hpp:449] End-Of-File received I0313 00:06:50.080647 3085 hierarchical.cpp:1156] Agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 deactivated I0313 00:06:50.080693 3085 hierarchical.cpp:1777] Allocation paused I0313 00:06:50.080982 3088 http_connection.hpp:217] Re-detecting endpoint I0313 00:06:50.081223 3085 hierarchical.cpp:757] Removed framework a330d48b-9410-478c-8b3a-a92f5a5a0d6e-0000 I0313 00:06:50.081284 3085 hierarchical.cpp:1787] Allocation resumed I0313 00:06:50.081511 3088 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0313 00:06:50.081591 3094 provider.cpp:488] Disconnected from resource provider manager I0313 00:06:50.081634 3088 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0313 00:06:50.081748 3083 status_update_manager_process.hpp:379] Pausing operation status update manager I0313 00:06:50.081820 3088 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:43769/slave(1237)/api/v1/resource_provider I0313 00:06:50.083210 3084 containerizer.cpp:2619] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0313 00:06:50.083300 3084 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 2.405097088secs I0313 00:06:50.083842 3084 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:50.085407 3089 hierarchical.cpp:1853] Performed allocation for 1 agents in 177131ns I0313 00:06:50.085711 3083 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:43769/slave(1237)/api/v1/resource_provider I0313 00:06:50.086438 3092 provider.cpp:476] Connected to resource provider manager I0313 00:06:50.087188 3096 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:43769/slave(1237)/api/v1/resource_provider I0313 00:06:50.088083 3097 process.cpp:2781] Returning '404 Not Found' for '/slave(1237)/api/v1/resource_provider' E0313 00:06:50.089303 3086 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0313 00:06:50.136198 3082 hierarchical.cpp:1853] Performed allocation for 1 agents in 145076ns I0313 00:06:50.187722 3088 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0313 00:06:50.187995 3081 hierarchical.cpp:1853] Performed allocation for 1 agents in 141479ns I0313 00:06:50.189628 3084 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 I0313 00:06:50.192525 3093 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' I0313 00:06:50.192843 3093 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-GzoK8v/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:50.193126 3093 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:50.195777 3097 process.cpp:2781] Returning '404 Not Found' for '/slave(1237)/api/v1' I0313 00:06:50.209123 3080 master.cpp:1140] Master terminating I0313 00:06:50.209882 3083 hierarchical.cpp:1132] Removed all filters for agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 I0313 00:06:50.209906 3083 hierarchical.cpp:1008] Removed agent a330d48b-9410-478c-8b3a-a92f5a5a0d6e-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2290 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 I0313 00:06:50.224995 3080 cluster.cpp:186] Creating default 'local' authorizer I0313 00:06:50.229724 3081 master.cpp:443] Master adeea4b8-af7f-4cea-b692-0058fd178e86 (b49bdfa63993) started on 172.17.0.2:43769 I0313 00:06:50.229758 3081 master.cpp:446] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/8ETUZe/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.10.0/_inst/share/mesos/webui" --work_dir="/tmp/8ETUZe/master" --zk_session_timeout="10secs" I0313 00:06:50.230170 3081 master.cpp:495] Master only allowing authenticated frameworks to register I0313 00:06:50.230183 3081 master.cpp:501] Master only allowing authenticated agents to register I0313 00:06:50.230191 3081 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0313 00:06:50.230201 3081 credentials.hpp:37] Loading credentials for authentication from '/tmp/8ETUZe/credentials' I0313 00:06:50.230453 3081 master.cpp:551] Using default 'crammd5' authenticator I0313 00:06:50.230659 3081 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0313 00:06:50.230906 3081 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0313 00:06:50.231096 3081 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0313 00:06:50.231325 3081 master.cpp:632] Authorization enabled I0313 00:06:50.231747 3082 hierarchical.cpp:567] Initialized hierarchical allocator process I0313 00:06:50.231791 3096 whitelist_watcher.cpp:77] No whitelist given I0313 00:06:50.234853 3093 master.cpp:2165] Elected as the leading master! I0313 00:06:50.234891 3093 master.cpp:1661] Recovering from registrar I0313 00:06:50.235137 3089 registrar.cpp:339] Recovering registrar I0313 00:06:50.235991 3089 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0313 00:06:50.236156 3089 registrar.cpp:487] Applied 1 operations in 55345ns; attempting to update the registry I0313 00:06:50.236879 3089 registrar.cpp:544] Successfully updated the registry in 0ns I0313 00:06:50.237056 3089 registrar.cpp:416] Successfully recovered registrar I0313 00:06:50.237607 3082 master.cpp:1814] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0313 00:06:50.237632 3081 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover W0313 00:06:50.243394 3080 process.cpp:2877] Attempted to spawn already running process [email protected]:43769 I0313 00:06:50.244820 3080 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0313 00:06:50.245390 3080 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0313 00:06:50.245417 3080 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0313 00:06:50.245432 3080 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0313 00:06:50.245463 3080 provisioner.cpp:294] Using default backend 'copy' I0313 00:06:50.248134 3080 cluster.cpp:533] Creating default 'local' authorizer I0313 00:06:50.251319 3087 slave.cpp:274] Mesos agent started on (1238)@172.17.0.2:43769 I0313 00:06:50.251353 3087 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/8ETUZe/KKHzXq/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/8ETUZe/KKHzXq/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/8ETUZe/KKHzXq/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/8ETUZe/KKHzXq/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/8ETUZe/KKHzXq/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/8ETUZe/KKHzXq/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posi x" --launcher_dir="/tmp/SRC/build/mesos-1.10.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/8ETUZe/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_I7Kls8" --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_AHt8WP" --zk_session_timeout="10secs" I0313 00:06:50.252144 3087 credentials.hpp:86] Loading credential for authentication from '/tmp/8ETUZe/KKHzXq/credential' I0313 00:06:50.252398 3087 slave.cpp:307] Agent using credential for: test-principal I0313 00:06:50.252434 3087 credentials.hpp:37] Loading credentials for authentication from '/tmp/8ETUZe/KKHzXq/http_credentials' I0313 00:06:50.252729 3087 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0313 00:06:50.253211 3087 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0313 00:06:50.255123 3082 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0313 00:06:50.255162 3087 slave.cpp:622] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] I0313 00:06:50.255504 3087 slave.cpp:630] Agent attributes: [ ] I0313 00:06:50.255527 3087 slave.cpp:639] Agent hostname: b49bdfa63993 I0313 00:06:50.255730 3095 status_update_manager_process.hpp:379] Pausing operation status update manager I0313 00:06:50.255744 3083 task_status_update_manager.cpp:181] Pausing sending task status updates I0313 00:06:50.258070 3084 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_AHt8WP/meta' I0313 00:06:50.258325 3085 slave.cpp:7606] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_AHt8WP/meta', beginning agent recovery I0313 00:06:50.259016 3094 task_status_update_manager.cpp:207] Recovering task status update manager I0313 00:06:50.259546 3089 containerizer.cpp:820] Recovering Mesos containers I0313 00:06:50.260028 3089 containerizer.cpp:1160] Recovering isolators I0313 00:06:50.260993 3085 containerizer.cpp:1199] Recovering provisioner I0313 00:06:50.261613 3081 hierarchical.cpp:1853] Performed allocation for 0 agents in 108259ns I0313 00:06:50.261890 3094 provisioner.cpp:518] Provisioner recovery complete I0313 00:06:50.262867 3090 composing.cpp:339] Finished recovering all containerizers I0313 00:06:50.263231 3096 slave.cpp:8088] Recovering executors I0313 00:06:50.263361 3096 slave.cpp:8241] Finished recovery I0313 00:06:50.264322 3082 task_status_update_manager.cpp:181] Pausing sending task status updates I0313 00:06:50.264382 3094 status_update_manager_process.hpp:379] Pausing operation status update manager I0313 00:06:50.264453 3088 slave.cpp:1454] New master detected at [email protected]:43769 I0313 00:06:50.264591 3088 slave.cpp:1519] Detecting new master I0313 00:06:50.273066 3089 slave.cpp:1546] Authenticating with master [email protected]:43769 I0313 00:06:50.273205 3089 slave.cpp:1555] Using default CRAM-MD5 authenticatee I0313 00:06:50.273612 3084 authenticatee.cpp:121] Creating new client SASL connection I0313 00:06:50.273988 3084 master.cpp:9676] Authenticating slave(1238)@172.17.0.2:43769 I0313 00:06:50.274157 3083 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2099)@172.17.0.2:43769 I0313 00:06:50.274551 3092 authenticator.cpp:98] Creating new server SASL connection I0313 00:06:50.274828 3090 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0313 00:06:50.274868 3090 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0313 00:06:50.275056 3087 authenticator.cpp:204] Received SASL authentication start I0313 00:06:50.275143 3087 authenticator.cpp:326] Authentication requires more steps I0313 00:06:50.275300 3087 authenticatee.cpp:259] Received SASL authentication step I0313 00:06:50.275490 3087 authenticator.cpp:232] Received SASL authentication step I0313 00:06:50.275533 3087 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b49bdfa63993' server FQDN: 'b49bdfa63993' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0313 00:06:50.275558 3087 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0313 00:06:50.275619 3087 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0313 00:06:50.275692 3087 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b49bdfa63993' server FQDN: 'b49bdfa63993' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0313 00:06:50.275718 3087 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0313 00:06:50.275737 3087 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0313 00:06:50.275763 3087 authenticator.cpp:318] Authentication success I0313 00:06:50.275913 3081 authenticatee.cpp:299] Authentication success I0313 00:06:50.276047 3085 master.cpp:9708] Successfully authenticated principal 'test-principal' at slave(1238)@172.17.0.2:43769 I0313 00:06:50.276139 3087 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2099)@172.17.0.2:43769 I0313 00:06:50.276546 3091 slave.cpp:1646] Successfully authenticated with master [email protected]:43769 I0313 00:06:50.277004 3091 slave.cpp:2096] Will retry registration in 15.751324ms if necessary I0313 00:06:50.277278 3095 master.cpp:6174] Received register agent message from slave(1238)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:50.277734 3095 master.cpp:3705] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0313 00:06:50.278419 3096 master.cpp:6241] Authorized registration of agent at slave(1238)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:50.278527 3096 master.cpp:6353] Registering agent at slave(1238)@172.17.0.2:43769 (b49bdfa63993) with id adeea4b8-af7f-4cea-b692-0058fd178e86-S0 I0313 00:06:50.279291 3082 registrar.cpp:487] Applied 1 operations in 254758ns; attempting to update the registry I0313 00:06:50.280097 3082 registrar.cpp:544] Successfully updated the registry in 732672ns I0313 00:06:50.280303 3081 master.cpp:6401] Admitted agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 at slave(1238)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:50.281188 3081 master.cpp:6446] Registered agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 at slave(1238)@172.17.0.2:43769 (b49bdfa63993) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0313 00:06:50.281283 3087 slave.cpp:1679] Registered with master [email protected]:43769; given agent ID adeea4b8-af7f-4cea-b692-0058fd178e86-S0 I0313 00:06:50.281407 3089 hierarchical.cpp:959] Added agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 (b49bdfa63993) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0313 00:06:50.281483 3095 task_status_update_manager.cpp:188] Resuming sending task status updates I0313 00:06:50.281819 3089 hierarchical.cpp:1853] Performed allocation for 1 agents in 157465ns I0313 00:06:50.281824 3087 slave.cpp:1714] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_AHt8WP/meta/slaves/adeea4b8-af7f-4cea-b692-0058fd178e86-S0/slave.info' I0313 00:06:50.281914 3084 status_update_manager_process.hpp:385] Resuming operation status update manager I0313 00:06:50.283354 3087 slave.cpp:1766] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"uHfoHY/nRpiVGolfEA9+sw=="},"slave_id":{"value":"adeea4b8-af7f-4cea-b692-0058fd178e86-S0"},"update_oversubscribed_resources":false} I0313 00:06:50.284221 3085 master.cpp:7584] Ignoring update on agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 at slave(1238)@172.17.0.2:43769 (b49bdfa63993) as it reports no changes I0313 00:06:50.288925 3092 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1' I0313 00:06:50.290448 3085 http.cpp:1405] HTTP POST for /slave(1238)/api/v1 from 172.17.0.2:59566 I0313 00:06:50.291030 3085 http.cpp:2828] Processing GET_CONTAINERS call I0313 00:06:50.311097 3085 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:50.313151 3095 hierarchical.cpp:1853] Performed allocation for 1 agents in 152987ns I0313 00:06:50.314424 3083 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1' I0313 00:06:50.315706 3092 http.cpp:1405] HTTP POST for /slave(1238)/api/v1 from 172.17.0.2:59568 I0313 00:06:50.316541 3092 http.cpp:3288] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:50.317643 3082 http.cpp:3392] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_AHt8WP/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:50.318547 3095 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:50.319124 3095 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 233216ns I0313 00:06:50.364684 3091 hierarchical.cpp:1853] Performed allocation for 1 agents in 180402ns I0313 00:06:50.369781 3095 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_I7Kls8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0313 00:06:50.369832 3095 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 50.710784ms I0313 00:06:50.373160 3096 containerizer.cpp:2099] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_OebWrx","--available_capacity=0B","--volumes=","--forward=unix:///tmp/8ETUZe/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_AHt8WP/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-qvlCvD/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_AHt8WP/containers/o rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="109" --pipe_write="110" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_I7Kls8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0313 00:06:50.384306 3096 launcher.cpp:145] Forked child with pid '14650' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:50.385174 3096 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 15.336192ms I0313 00:06:50.386718 3096 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 1.539072ms I0313 00:06:50.387037 3094 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_AHt8WP/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:50.388327 3093 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 1.551872ms I0313 00:06:50.391561 3091 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' I0313 00:06:50.391927 3085 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-qvlCvD/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:50.415550 3094 hierarchical.cpp:1853] Performed allocation for 1 agents in 195933ns I0313 00:06:50.467123 3082 hierarchical.cpp:1853] Performed allocation for 1 agents in 199599ns I0313 00:06:50.518622 3086 hierarchical.cpp:1853] Performed allocation for 1 agents in 191044ns I0313 00:06:50.569546 3082 hierarchical.cpp:1853] Performed allocation for 1 agents in 159509ns I0313 00:06:50.620983 3095 hierarchical.cpp:1853] Performed allocation for 1 agents in 145319ns I0313 00:06:50.672248 3092 hierarchical.cpp:1853] Performed allocation for 1 agents in 145992ns I0313 00:06:50.713711 3090 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-qvlCvD/endpoint.sock' with CSI v1 I0313 00:06:50.716477 3095 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-qvlCvD/endpoint.sock' with CSI v0 I0313 00:06:50.717669 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/Probe call I0313 00:06:50.720767 3094 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:50.723134 3087 hierarchical.cpp:1853] Performed allocation for 1 agents in 149579ns I0313 00:06:50.724088 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginCapabilities call I0313 00:06:50.724623 3090 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1' I0313 00:06:50.725947 3093 http.cpp:1405] HTTP POST for /slave(1238)/api/v1 from 172.17.0.2:59570 I0313 00:06:50.726516 3093 http.cpp:3506] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:50.728479 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0313 00:06:50.728850 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call I0313 00:06:50.730635 3095 v0_volume_manager.cpp:628] NODE_SERVICE loaded: {} I0313 00:06:50.731212 3095 v0_volume_manager.cpp:628] CONTROLLER_SERVICE loaded: {} I0313 00:06:50.733870 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ControllerGetCapabilities call I0313 00:06:50.737839 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetCapabilities call I0313 00:06:50.741509 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetId call I0313 00:06:50.744079 3094 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0313 00:06:50.744243 3092 status_update_manager_process.hpp:379] Pausing operation status update manager I0313 00:06:50.744632 3093 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:43769/slave(1238)/api/v1/resource_provider I0313 00:06:50.747879 3091 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:43769/slave(1238)/api/v1/resource_provider I0313 00:06:50.748572 3095 provider.cpp:476] Connected to resource provider manager I0313 00:06:50.749301 3088 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:43769/slave(1238)/api/v1/resource_provider I0313 00:06:50.750540 3093 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1/resource_provider' I0313 00:06:50.752460 3082 http.cpp:1405] HTTP POST for /slave(1238)/api/v1/resource_provider from 172.17.0.2:59574 I0313 00:06:50.753214 3082 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_OebWrx","--available_capacity=0B","--volumes=","--forward=unix:///tmp/8ETUZe/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"} I0313 00:06:50.774268 3094 hierarchical.cpp:1853] Performed allocation for 1 agents in 188217ns I0313 00:06:50.795527 3081 slave.cpp:8597] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"3b27feda-a4de-4aef-9f36-693b863044c7"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_OebWrx","--available_capacity=0B","--volumes=","--forward=unix:///tmp/8ETUZe/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}' I0313 00:06:50.797250 3086 provider.cpp:498] Received SUBSCRIBED event I0313 00:06:50.797304 3086 provider.cpp:1309] Subscribed with ID 3b27feda-a4de-4aef-9f36-693b863044c7 I0313 00:06:50.798126 3095 status_update_manager_process.hpp:314] Recovering operation status update manager I0313 00:06:50.825328 3089 hierarchical.cpp:1853] Performed allocation for 1 agents in 143866ns I0313 00:06:50.853859 3094 provider.cpp:790] Reconciling storage pools and volumes I0313 00:06:50.856174 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0313 00:06:50.859138 3092 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 I0313 00:06:50.859421 3094 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:43769/slave(1238)/api/v1/resource_provider I0313 00:06:50.859560 3092 provider.cpp:748] Resource provider 3b27feda-a4de-4aef-9f36-693b863044c7 is in READY state I0313 00:06:50.859620 3093 status_update_manager_process.hpp:385] Resuming operation status update manager I0313 00:06:50.860523 3082 provider.cpp:1235] Updating profiles { test } for resource provider 3b27feda-a4de-4aef-9f36-693b863044c7 I0313 00:06:50.860827 3085 process.cpp:3671] Handling HTTP event for process 'slave(1238)' with path: '/slave(1238)/api/v1/resource_provider' I0313 00:06:50.861853 3094 provider.cpp:790] Reconciling storage pools and volumes I0313 00:06:50.862596 3082 http.cpp:1405] HTTP POST for /slave(1238)/api/v1/resource_provider from 172.17.0.2:59572 I0313 00:06:50.863242 3083 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 3b27feda-a4de-4aef-9f36-693b863044c7 I0313 00:06:50.863489 3095 slave.cpp:8597] Handling resource provider message 'UPDATE_STATE: 3b27feda-a4de-4aef-9f36-693b863044c7 {}' I0313 00:06:50.863608 3095 slave.cpp:8717] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0313 00:06:50.864223 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0313 00:06:50.864708 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0313 00:06:50.866019 3093 hierarchical.cpp:1110] Grew agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 by {} (total), { } (used) I0313 00:06:50.866449 3093 hierarchical.cpp:1067] Agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 (b49bdfa63993) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0313 00:06:50.871342 3084 hierarchical.cpp:1853] Performed allocation for 1 agents in 149263ns I0313 00:06:50.871712 3092 provider.cpp:790] Reconciling storage pools and volumes I0313 00:06:50.874101 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call I0313 00:06:50.874667 14654 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call I0313 00:06:50.885581 3080 slave.cpp:995] Agent terminating I0313 00:06:50.886495 3080 manager.cpp:127] Terminating resource provider 3b27feda-a4de-4aef-9f36-693b863044c7 I0313 00:06:50.887035 3090 master.cpp:1292] Agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 at slave(1238)@172.17.0.2:43769 (b49bdfa63993) disconnected I0313 00:06:50.887079 3090 master.cpp:3361] Disconnecting agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 at slave(1238)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:50.887164 3090 master.cpp:3380] Deactivating agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 at slave(1238)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:50.887311 3087 hierarchical.cpp:1156] Agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 deactivated E0313 00:06:50.887639 3086 http_connection.hpp:449] End-Of-File received I0313 00:06:50.888146 3086 http_connection.hpp:217] Re-detecting endpoint I0313 00:06:50.888624 3086 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0313 00:06:50.888713 3086 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0313 00:06:50.888744 3083 provider.cpp:488] Disconnected from resource provider manager I0313 00:06:50.888808 3086 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:43769/slave(1238)/api/v1/resource_provider I0313 00:06:50.888978 3083 status_update_manager_process.hpp:379] Pausing operation status update manager I0313 00:06:50.890609 3091 containerizer.cpp:2619] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0313 00:06:50.890678 3091 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.502409984secs I0313 00:06:50.891132 3091 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:50.892364 3083 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:43769/slave(1238)/api/v1/resource_provider I0313 00:06:50.893105 3086 provider.cpp:476] Connected to resource provider manager I0313 00:06:50.893710 3081 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:43769/slave(1238)/api/v1/resource_provider I0313 00:06:50.894690 3097 process.cpp:2781] Returning '404 Not Found' for '/slave(1238)/api/v1/resource_provider' E0313 00:06:50.896138 3085 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0313 00:06:50.918251 3095 hierarchical.cpp:1853] Performed allocation for 1 agents in 163104ns I0313 00:06:50.967586 3090 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0313 00:06:50.969472 3090 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 I0313 00:06:50.970026 3085 hierarchical.cpp:1853] Performed allocation for 1 agents in 171899ns I0313 00:06:50.972889 3086 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' I0313 00:06:50.973121 3086 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-qvlCvD/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:50.973366 3096 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:50.976614 3097 process.cpp:2781] Returning '404 Not Found' for '/slave(1238)/api/v1' I0313 00:06:50.988596 3080 master.cpp:1140] Master terminating I0313 00:06:50.989029 3092 hierarchical.cpp:1132] Removed all filters for agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 I0313 00:06:50.989056 3092 hierarchical.cpp:1008] Removed agent adeea4b8-af7f-4cea-b692-0058fd178e86-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (777 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 I0313 00:06:51.005738 3080 cluster.cpp:186] Creating default 'local' authorizer I0313 00:06:51.010594 3090 master.cpp:443] Master d52c6d46-1166-42cc-a4ba-6fa17843d194 (b49bdfa63993) started on 172.17.0.2:43769 I0313 00:06:51.010622 3090 master.cpp:446] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/zD2t7u/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/tmp/SRC/build/mesos-1.10.0/_inst/share/mesos/webui" --work_dir="/tmp/zD2t7u/master" --zk_session_timeout="10secs" I0313 00:06:51.010921 3090 master.cpp:495] Master only allowing authenticated frameworks to register I0313 00:06:51.010936 3090 master.cpp:501] Master only allowing authenticated agents to register I0313 00:06:51.010943 3090 master.cpp:507] Master only allowing authenticated HTTP frameworks to register I0313 00:06:51.010952 3090 credentials.hpp:37] Loading credentials for authentication from '/tmp/zD2t7u/credentials' I0313 00:06:51.011183 3090 master.cpp:551] Using default 'crammd5' authenticator I0313 00:06:51.011390 3090 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I0313 00:06:51.011636 3090 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I0313 00:06:51.011837 3090 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I0313 00:06:51.012030 3090 master.cpp:632] Authorization enabled I0313 00:06:51.012434 3084 whitelist_watcher.cpp:77] No whitelist given I0313 00:06:51.012562 3081 hierarchical.cpp:567] Initialized hierarchical allocator process I0313 00:06:51.015385 3087 master.cpp:2165] Elected as the leading master! I0313 00:06:51.015421 3087 master.cpp:1661] Recovering from registrar I0313 00:06:51.015627 3083 registrar.cpp:339] Recovering registrar I0313 00:06:51.016541 3083 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I0313 00:06:51.016717 3083 registrar.cpp:487] Applied 1 operations in 57925ns; attempting to update the registry I0313 00:06:51.017467 3083 registrar.cpp:544] Successfully updated the registry in 0ns I0313 00:06:51.017652 3083 registrar.cpp:416] Successfully recovered registrar I0313 00:06:51.018165 3084 master.cpp:1814] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I0313 00:06:51.018208 3081 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover W0313 00:06:51.023938 3080 process.cpp:2877] Attempted to spawn already running process [email protected]:43769 I0313 00:06:51.025317 3080 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W0313 00:06:51.025899 3080 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W0313 00:06:51.025925 3080 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W0313 00:06:51.025941 3080 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I0313 00:06:51.025971 3080 provisioner.cpp:294] Using default backend 'copy' I0313 00:06:51.028748 3080 cluster.cpp:533] Creating default 'local' authorizer I0313 00:06:51.031178 3091 slave.cpp:274] Mesos agent started on (1239)@172.17.0.2:43769 I0313 00:06:51.031211 3091 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/zD2t7u/zGPcgP/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/zD2t7u/zGPcgP/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/zD2t7u/zGPcgP/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/zD2t7u/zGPcgP/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/zD2t7u/zGPcgP/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/zD2t7u/zGPcgP/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posi x" --launcher_dir="/tmp/SRC/build/mesos-1.10.0/_build/sub/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_provider_config_dir="/tmp/zD2t7u/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_BrMcIu" --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_TGldaa" --zk_session_timeout="10secs" I0313 00:06:51.031796 3091 credentials.hpp:86] Loading credential for authentication from '/tmp/zD2t7u/zGPcgP/credential' I0313 00:06:51.032044 3091 slave.cpp:307] Agent using credential for: test-principal I0313 00:06:51.032085 3091 credentials.hpp:37] Loading credentials for authentication from '/tmp/zD2t7u/zGPcgP/http_credentials' I0313 00:06:51.032380 3091 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I0313 00:06:51.032902 3091 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I0313 00:06:51.034477 3090 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I0313 00:06:51.034837 3091 slave.cpp:622] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] I0313 00:06:51.035131 3091 slave.cpp:630] Agent attributes: [ ] I0313 00:06:51.035151 3091 slave.cpp:639] Agent hostname: b49bdfa63993 I0313 00:06:51.035377 3086 status_update_manager_process.hpp:379] Pausing operation status update manager I0313 00:06:51.035392 3089 task_status_update_manager.cpp:181] Pausing sending task status updates I0313 00:06:51.037262 3093 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_TGldaa/meta' I0313 00:06:51.037619 3094 slave.cpp:7606] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_TGldaa/meta', beginning agent recovery I0313 00:06:51.038286 3085 task_status_update_manager.cpp:207] Recovering task status update manager I0313 00:06:51.038892 3082 containerizer.cpp:820] Recovering Mesos containers I0313 00:06:51.039295 3082 containerizer.cpp:1160] Recovering isolators I0313 00:06:51.040577 3095 containerizer.cpp:1199] Recovering provisioner I0313 00:06:51.041442 3085 provisioner.cpp:518] Provisioner recovery complete I0313 00:06:51.042431 3090 hierarchical.cpp:1853] Performed allocation for 0 agents in 130332ns I0313 00:06:51.042513 3082 composing.cpp:339] Finished recovering all containerizers I0313 00:06:51.042907 3087 slave.cpp:8088] Recovering executors I0313 00:06:51.043045 3087 slave.cpp:8241] Finished recovery I0313 00:06:51.044023 3084 task_status_update_manager.cpp:181] Pausing sending task status updates I0313 00:06:51.044049 3094 slave.cpp:1454] New master detected at [email protected]:43769 I0313 00:06:51.044065 3085 status_update_manager_process.hpp:379] Pausing operation status update manager I0313 00:06:51.044179 3094 slave.cpp:1519] Detecting new master I0313 00:06:51.045554 3083 slave.cpp:1546] Authenticating with master [email protected]:43769 I0313 00:06:51.045706 3083 slave.cpp:1555] Using default CRAM-MD5 authenticatee I0313 00:06:51.046064 3091 authenticatee.cpp:121] Creating new client SASL connection I0313 00:06:51.046432 3092 master.cpp:9676] Authenticating slave(1239)@172.17.0.2:43769 I0313 00:06:51.046634 3086 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2100)@172.17.0.2:43769 I0313 00:06:51.047029 3090 authenticator.cpp:98] Creating new server SASL connection I0313 00:06:51.047298 3082 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I0313 00:06:51.047338 3082 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I0313 00:06:51.047479 3082 authenticator.cpp:204] Received SASL authentication start I0313 00:06:51.047564 3082 authenticator.cpp:326] Authentication requires more steps I0313 00:06:51.047706 3082 authenticatee.cpp:259] Received SASL authentication step I0313 00:06:51.047890 3096 authenticator.cpp:232] Received SASL authentication step I0313 00:06:51.047945 3096 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b49bdfa63993' server FQDN: 'b49bdfa63993' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I0313 00:06:51.047974 3096 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I0313 00:06:51.048041 3096 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I0313 00:06:51.048105 3096 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'b49bdfa63993' server FQDN: 'b49bdfa63993' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I0313 00:06:51.048130 3096 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I0313 00:06:51.048149 3096 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I0313 00:06:51.048179 3096 authenticator.cpp:318] Authentication success I0313 00:06:51.048293 3095 authenticatee.cpp:299] Authentication success I0313 00:06:51.048430 3093 master.cpp:9708] Successfully authenticated principal 'test-principal' at slave(1239)@172.17.0.2:43769 I0313 00:06:51.048521 3084 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2100)@172.17.0.2:43769 I0313 00:06:51.048753 3085 slave.cpp:1646] Successfully authenticated with master [email protected]:43769 I0313 00:06:51.049221 3085 slave.cpp:2096] Will retry registration in 10.657038ms if necessary I0313 00:06:51.049418 3091 master.cpp:6174] Received register agent message from slave(1239)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:51.049800 3091 master.cpp:3705] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I0313 00:06:51.050429 3090 master.cpp:6241] Authorized registration of agent at slave(1239)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:51.050561 3090 master.cpp:6353] Registering agent at slave(1239)@172.17.0.2:43769 (b49bdfa63993) with id d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 I0313 00:06:51.051299 3087 registrar.cpp:487] Applied 1 operations in 267806ns; attempting to update the registry I0313 00:06:51.052079 3087 registrar.cpp:544] Successfully updated the registry in 712960ns I0313 00:06:51.052310 3089 master.cpp:6401] Admitted agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 at slave(1239)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:51.053158 3089 master.cpp:6446] Registered agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 at slave(1239)@172.17.0.2:43769 (b49bdfa63993) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0313 00:06:51.053328 3083 slave.cpp:1679] Registered with master [email protected]:43769; given agent ID d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 I0313 00:06:51.053402 3095 hierarchical.cpp:959] Added agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 (b49bdfa63993) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I0313 00:06:51.053490 3085 task_status_update_manager.cpp:188] Resuming sending task status updates I0313 00:06:51.053848 3095 hierarchical.cpp:1853] Performed allocation for 1 agents in 146206ns I0313 00:06:51.053869 3083 slave.cpp:1714] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_TGldaa/meta/slaves/d52c6d46-1166-42cc-a4ba-6fa17843d194-S0/slave.info' I0313 00:06:51.053972 3092 status_update_manager_process.hpp:385] Resuming operation status update manager I0313 00:06:51.055297 3083 slave.cpp:1766] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"NX+Mb6dpTOKW4zaP23KegQ=="},"slave_id":{"value":"d52c6d46-1166-42cc-a4ba-6fa17843d194-S0"},"update_oversubscribed_resources":false} I0313 00:06:51.056265 3088 master.cpp:7584] Ignoring update on agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 at slave(1239)@172.17.0.2:43769 (b49bdfa63993) as it reports no changes I0313 00:06:51.060537 3092 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1' I0313 00:06:51.061921 3088 http.cpp:1405] HTTP POST for /slave(1239)/api/v1 from 172.17.0.2:59582 I0313 00:06:51.062461 3088 http.cpp:2828] Processing GET_CONTAINERS call I0313 00:06:51.089306 3088 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:51.092301 3085 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1' I0313 00:06:51.093497 3096 http.cpp:1405] HTTP POST for /slave(1239)/api/v1 from 172.17.0.2:59584 I0313 00:06:51.094290 3096 http.cpp:3288] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:51.094358 3081 hierarchical.cpp:1853] Performed allocation for 1 agents in 182964ns I0313 00:06:51.095494 3083 http.cpp:3392] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_TGldaa/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:51.096284 3088 containerizer.cpp:1395] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:51.096979 3088 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 273920ns I0313 00:06:51.114364 3088 containerizer.cpp:1573] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_BrMcIu/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I0313 00:06:51.114440 3088 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 17.4592ms I0313 00:06:51.117753 3086 containerizer.cpp:2099] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_V3SeCP","--available_capacity=0B","--volumes=","--forward=unix:///tmp/zD2t7u/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_TGldaa/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-LvA5W9/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_TGldaa/containers/o rg-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="109" --pipe_write="110" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_BrMcIu/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I0313 00:06:51.128803 3086 launcher.cpp:145] Forked child with pid '14663' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:51.129703 3086 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 15.256832ms I0313 00:06:51.131217 3086 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 1.511936ms I0313 00:06:51.131451 3086 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_TGldaa/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:51.132537 3093 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 1.231104ms I0313 00:06:51.135741 3081 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' I0313 00:06:51.136135 3095 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-LvA5W9/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:51.145854 3082 hierarchical.cpp:1853] Performed allocation for 1 agents in 182775ns I0313 00:06:51.197022 3085 hierarchical.cpp:1853] Performed allocation for 1 agents in 205521ns I0313 00:06:51.248306 3082 hierarchical.cpp:1853] Performed allocation for 1 agents in 162526ns I0313 00:06:51.299660 3085 hierarchical.cpp:1853] Performed allocation for 1 agents in 131150ns I0313 00:06:51.351009 3081 hierarchical.cpp:1853] Performed allocation for 1 agents in 212431ns I0313 00:06:51.402806 3086 hierarchical.cpp:1853] Performed allocation for 1 agents in 153647ns I0313 00:06:51.454041 3087 hierarchical.cpp:1853] Performed allocation for 1 agents in 164424ns I0313 00:06:51.456374 3083 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-LvA5W9/endpoint.sock' with CSI v1 I0313 00:06:51.458331 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call I0313 00:06:51.461280 3082 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:51.464092 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call I0313 00:06:51.464890 3089 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1' I0313 00:06:51.466372 3090 http.cpp:1405] HTTP POST for /slave(1239)/api/v1 from 172.17.0.2:59586 I0313 00:06:51.466907 3090 http.cpp:3506] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:51.468448 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0313 00:06:51.468822 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call I0313 00:06:51.470569 3083 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {} I0313 00:06:51.471101 3083 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {} I0313 00:06:51.473330 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call I0313 00:06:51.477227 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call I0313 00:06:51.480979 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call I0313 00:06:51.483582 3086 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I0313 00:06:51.483762 3092 status_update_manager_process.hpp:379] Pausing operation status update manager I0313 00:06:51.484185 3086 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:43769/slave(1239)/api/v1/resource_provider I0313 00:06:51.487736 3096 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:43769/slave(1239)/api/v1/resource_provider I0313 00:06:51.488548 3083 provider.cpp:476] Connected to resource provider manager I0313 00:06:51.489281 3092 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:43769/slave(1239)/api/v1/resource_provider I0313 00:06:51.490514 3086 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1/resource_provider' I0313 00:06:51.492341 3085 http.cpp:1405] HTTP POST for /slave(1239)/api/v1/resource_provider from 172.17.0.2:59590 I0313 00:06:51.493089 3085 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_V3SeCP","--available_capacity=0B","--volumes=","--forward=unix:///tmp/zD2t7u/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"} I0313 00:06:51.505096 3090 hierarchical.cpp:1853] Performed allocation for 1 agents in 191749ns I0313 00:06:51.522521 3086 slave.cpp:8597] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"44fd3d2b-5f85-48c3-ad0f-221e3e7a4746"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_V3SeCP","--available_capacity=0B","--volumes=","--forward=unix:///tmp/zD2t7u/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.10.0/_build/sub/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}' I0313 00:06:51.524333 3095 provider.cpp:498] Received SUBSCRIBED event I0313 00:06:51.524384 3095 provider.cpp:1309] Subscribed with ID 44fd3d2b-5f85-48c3-ad0f-221e3e7a4746 I0313 00:06:51.525207 3092 status_update_manager_process.hpp:314] Recovering operation status update manager I0313 00:06:51.556222 3090 hierarchical.cpp:1853] Performed allocation for 1 agents in 134069ns I0313 00:06:51.564035 3083 provider.cpp:790] Reconciling storage pools and volumes I0313 00:06:51.566395 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0313 00:06:51.569602 3091 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 I0313 00:06:51.569973 3091 provider.cpp:748] Resource provider 44fd3d2b-5f85-48c3-ad0f-221e3e7a4746 is in READY state I0313 00:06:51.569957 3081 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:43769/slave(1239)/api/v1/resource_provider I0313 00:06:51.570129 3088 status_update_manager_process.hpp:385] Resuming operation status update manager I0313 00:06:51.570684 3089 provider.cpp:1235] Updating profiles { test } for resource provider 44fd3d2b-5f85-48c3-ad0f-221e3e7a4746 I0313 00:06:51.571244 3092 process.cpp:3671] Handling HTTP event for process 'slave(1239)' with path: '/slave(1239)/api/v1/resource_provider' I0313 00:06:51.571893 3094 provider.cpp:790] Reconciling storage pools and volumes I0313 00:06:51.572963 3085 http.cpp:1405] HTTP POST for /slave(1239)/api/v1/resource_provider from 172.17.0.2:59588 I0313 00:06:51.573604 3085 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 44fd3d2b-5f85-48c3-ad0f-221e3e7a4746 I0313 00:06:51.573894 3081 slave.cpp:8597] Handling resource provider message 'UPDATE_STATE: 44fd3d2b-5f85-48c3-ad0f-221e3e7a4746 {}' I0313 00:06:51.573995 3081 slave.cpp:8717] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0313 00:06:51.574154 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0313 00:06:51.574923 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0313 00:06:51.576081 3082 hierarchical.cpp:1110] Grew agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 by {} (total), { } (used) I0313 00:06:51.576524 3082 hierarchical.cpp:1067] Agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 (b49bdfa63993) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I0313 00:06:51.580598 3094 hierarchical.cpp:1853] Performed allocation for 1 agents in 196939ns I0313 00:06:51.581014 3086 provider.cpp:790] Reconciling storage pools and volumes I0313 00:06:51.583153 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call I0313 00:06:51.583545 14667 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call I0313 00:06:51.594265 3080 slave.cpp:995] Agent terminating I0313 00:06:51.595202 3080 manager.cpp:127] Terminating resource provider 44fd3d2b-5f85-48c3-ad0f-221e3e7a4746 I0313 00:06:51.595733 3083 master.cpp:1292] Agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 at slave(1239)@172.17.0.2:43769 (b49bdfa63993) disconnected I0313 00:06:51.595772 3083 master.cpp:3361] Disconnecting agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 at slave(1239)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:51.595877 3083 master.cpp:3380] Deactivating agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 at slave(1239)@172.17.0.2:43769 (b49bdfa63993) I0313 00:06:51.596040 3091 hierarchical.cpp:1156] Agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 deactivated E0313 00:06:51.596244 3087 http_connection.hpp:449] End-Of-File received I0313 00:06:51.596760 3087 http_connection.hpp:217] Re-detecting endpoint I0313 00:06:51.597347 3087 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0313 00:06:51.597424 3087 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I0313 00:06:51.597513 3087 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:43769/slave(1239)/api/v1/resource_provider I0313 00:06:51.597538 3096 provider.cpp:488] Disconnected from resource provider manager I0313 00:06:51.597730 3096 status_update_manager_process.hpp:379] Pausing operation status update manager I0313 00:06:51.599243 3095 containerizer.cpp:2619] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I0313 00:06:51.599313 3095 containerizer.cpp:3317] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.466877952secs I0313 00:06:51.599786 3095 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:51.600850 3085 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:43769/slave(1239)/api/v1/resource_provider I0313 00:06:51.601521 3083 provider.cpp:476] Connected to resource provider manager I0313 00:06:51.602208 3087 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:43769/slave(1239)/api/v1/resource_provider I0313 00:06:51.603111 3097 process.cpp:2781] Returning '404 Not Found' for '/slave(1239)/api/v1/resource_provider' E0313 00:06:51.604403 3090 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I0313 00:06:51.627919 3093 hierarchical.cpp:1853] Performed allocation for 1 agents in 227784ns I0313 00:06:51.678125 3092 containerizer.cpp:3155] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I0313 00:06:51.679492 3088 hierarchical.cpp:1853] Performed allocation for 1 agents in 119289ns I0313 00:06:51.680012 3086 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 I0313 00:06:51.683215 3083 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' I0313 00:06:51.683456 3090 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-LvA5W9/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I0313 00:06:51.683753 3088 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I0313 00:06:51.687024 3097 process.cpp:2781] Returning '404 Not Found' for '/slave(1239)/api/v1' I0313 00:06:51.699250 3080 master.cpp:1140] Master terminating I0313 00:06:51.699623 3093 hierarchical.cpp:1132] Removed all filters for agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 I0313 00:06:51.699652 3093 hierarchical.cpp:1008] Removed agent d52c6d46-1166-42cc-a4ba-6fa17843d194-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (708 ms) [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (107754 ms total) [----------] Global test environment tear-down [==========] 2312 tests from 223 test cases ran. (1101400 ms total) [ PASSED ] 2311 tests. [ FAILED ] 1 test, listed below: [ FAILED ] CSIVersion/StorageLocalResourceProviderTest.CreateDestroyPreprovisionedVolume/v0, where GetParam() = "v0" 1 FAILED TEST YOU HAVE 34 DISABLED TESTS I0313 00:06:51.786792 3097 process.cpp:935] Stopped the socket accept loop Makefile:15957: recipe for target 'check-local' failed make[4]: *** [check-local] Error 1 make[4]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src' Makefile:15073: recipe for target 'check-am' failed make[3]: *** [check-am] Error 2 make[3]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src' Makefile:15077: recipe for target 'check' failed make[2]: *** [check] Error 2 make[2]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub/src' Makefile:785: recipe for target 'check-recursive' failed make[1]: *** [check-recursive] Error 1 make[1]: Leaving directory '/tmp/SRC/build/mesos-1.10.0/_build/sub' Makefile:991: recipe for target 'distcheck' failed make: *** [distcheck] Error 1 Untagged: mesos/mesos-build:ubuntu-16.04 Untagged: mesos/mesos-build@sha256:fa967cbcfb44f55708a3cbc87f245c6d29dd891464db558af56a03ee321526bb Deleted: sha256:e895c0531b9a9a288fabe479a49f7059aed83645351ac99ec2ea2616822c9f97 Deleted: sha256:09119b0b314a69ba6ec6251f2e89f4199fe1e874c84f9abf07dcbd23dbc3f1c1 Deleted: sha256:562fe6af5a3883058be9c784a839392215ed4185a21d21f1d99df0d17f3ae6e7 Deleted: sha256:0dcdfbe322a4f332f73ac70905d557300ec6dae3bd19586758772c750c7b4a19 Deleted: sha256:c66652d605f01094e2db53d62505dbd524e076d5aa69b89d5e620003803eb149 Deleted: sha256:a2cf79bfb9593c05fd7142ddb49afef77ea4ad5d2464e841f09fe62ffee396e0 Deleted: sha256:f7a904214b390f39d98573882f631dc908df8b2b540cf04e1062f8182c1efffd Deleted: sha256:ce1f6fcaa83dfce189d76e08f184085732eab4eeb2562d2399953958405c5bec Deleted: sha256:cce92fda689ab9033f0b8db214bc63edd1ae3e05831a0f3a9418976d7dc7ccdd Deleted: sha256:d22094bbd65447c59a42c580eaa3a44cee9cd855f00905f59409be21bcefc745 Deleted: sha256:b8976847450013f3eb5e9a81a5778f73ed7bef67e6393049712ef17102b4b7b7 Deleted: sha256:b8c891f0ffec910a12757d733b178e3f62d81dbbde2b31d3b754071c416108ed Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/7976/console - Mesos Reviewbot On March 12, 2020, 10 p.m., Benjamin Mahler wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/72233/ > ----------------------------------------------------------- > > (Updated March 12, 2020, 10 p.m.) > > > Review request for mesos and Andrei Sekretenko. > > > Bugs: MESOS-10103 > https://issues.apache.org/jira/browse/MESOS-10103 > > > Repository: mesos > > > Description > ------- > > Found by Andrei Sekretenko using -fsanitize=address, the following > expression has an intermediate temporary! > > const RepeatedPtrField<Resource::ReservationInfo>& > ancestorReservations = > RepeatedPtrField<Resource>(ancestor).begin()->reservations(); > > Therefore, the intermediate temporary will not have its lifetime > extended and this is undefined behavior which leads to a crash > in the windows CI. > > > Diffs > ----- > > src/master/authorization.cpp 6dfa59ad621d9aa0fd1dbbdbe4fa8965e413774f > > > Diff: https://reviews.apache.org/r/72233/diff/1/ > > > Testing > ------- > > Ran through windows CI. > > > Thanks, > > Benjamin Mahler > >
