----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/72956/#review222133 -----------------------------------------------------------
Bad patch! Reviews applied: [72964, 72955, 72956] 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_72956"] Error: ...<truncated>... or process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider' I1027 22:21:59.412524 4164 hierarchical.cpp:1953] Performed allocation for 1 agents in 1.524917ms I1027 22:21:59.413250 4169 master.cpp:9580] Sending offers [ 67d3d7f7-102e-4a76-bfce-e64091d7e007-O3 ] to framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 I1027 22:21:59.413980 4181 sched.cpp:937] Scheduler::resourceOffers took 99231ns I1027 22:21:59.417760 4175 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I1027 22:21:59.419952 4174 http.cpp:1436] HTTP POST for /master/api/v1 from 172.17.0.2:44026 I1027 22:21:59.420287 4174 http.cpp:277] Processing call CREATE_VOLUMES I1027 22:21:59.421416 4174 master.cpp:3795] Authorizing principal 'test-principal' to perform action CREATE_VOLUME on object {"value":"storage/default-role","resource":{"provider_id":{"value":"a0f4fd23-7a1e-48c6-9058-cf7bf61d4bde"},"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":"a4d8a0ad-ca5e-4edd-900b-ec712c7ac155","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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891","profile":"test"}}}} I1027 22:21:59.423686 4171 sched.cpp:963] Rescinded offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O3 I1027 22:21:59.423812 4171 sched.cpp:974] Scheduler::offerRescinded took 31015ns I1027 22:21:59.424187 4182 hierarchical.cpp:1676] 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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test)]:2048, offered or allocated: {}) on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 from framework 67d3d 7f7-102e-4a76-bfce-e64091d7e007-0000 I1027 22:21:59.424618 4167 master.cpp:11879] Removing offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O3 I1027 22:21:59.426604 4182 hierarchical.cpp:1725] Framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 filtered agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 for 5secs I1027 22:21:59.429592 4177 master.cpp:11744] Sending operation '' (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) to agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca) I1027 22:21:59.430387 4169 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version I1027 22:21:59.434455 4165 provider.cpp:498] Received APPLY_OPERATION event I1027 22:21:59.434523 4165 provider.cpp:1352] Received CREATE operation '' (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) I1027 22:21:59.435726 4162 master.cpp:5623] Processing REVIVE call for framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 I1027 22:21:59.436305 4173 hierarchical.cpp:1821] Unsuppressed offers and cleared filters for roles { storage/default-role } of framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 I1027 22:21:59.438428 4173 hierarchical.cpp:1953] Performed allocation for 1 agents in 1.769894ms I1027 22:21:59.438925 4173 hierarchical.cpp:1953] Performed allocation for 1 agents in 181270ns I1027 22:21:59.439420 4171 master.cpp:9580] Sending offers [ 67d3d7f7-102e-4a76-bfce-e64091d7e007-O4 ] to framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 I1027 22:21:59.440446 4167 sched.cpp:937] Scheduler::resourceOffers took 118458ns I1027 22:21:59.453526 4179 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:44020 I1027 22:21:59.455102 4176 slave.cpp:8733] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 0f6710b6-e104-4b56-8e67-4c39e7579154) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I1027 22:21:59.455387 4176 slave.cpp:9186] Updating the state of operation with no ID (uuid: 0f6710b6-e104-4b56-8e67-4c39e7579154) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I1027 22:21:59.455458 4176 slave.cpp:8940] Forwarding status update of operation with no ID (operation_uuid: 0f6710b6-e104-4b56-8e67-4c39e7579154) for an operator API call I1027 22:21:59.455878 4169 master.cpp:11396] Updating the state of operation '' (uuid: 0f6710b6-e104-4b56-8e67-4c39e7579154) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I1027 22:21:59.456435 4172 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version I1027 22:21:59.612226 4165 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I1027 22:21:59.612180 4167 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for operation UUID e650afe9-c7c0-4285-9dd9-969175eca9ad on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:21:59.612315 4167 status_update_manager_process.hpp:414] Creating operation status update stream e650afe9-c7c0-4285-9dd9-969175eca9ad checkpoint=true I1027 22:21:59.612658 4167 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for operation UUID e650afe9-c7c0-4285-9dd9-969175eca9ad on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:21:59.720906 4167 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for operation UUID e650afe9-c7c0-4285-9dd9-969175eca9ad on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:21:59.721508 4167 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 5f499b26-6d5a-4322-8a07-907d830b599a) for stream 0f6710b6-e104-4b56-8e67-4c39e7579154 I1027 22:21:59.721585 4167 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 5f499b26-6d5a-4322-8a07-907d830b599a) for operation UUID 0f6710b6-e104-4b56-8e67-4c39e7579154 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:21:59.722259 4163 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider I1027 22:21:59.723935 4181 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider' I1027 22:21:59.765915 4175 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:44020 I1027 22:21:59.767163 4172 slave.cpp:8733] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I1027 22:21:59.767416 4172 slave.cpp:9186] Updating the state of operation with no ID (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I1027 22:21:59.767472 4172 slave.cpp:8940] Forwarding status update of operation with no ID (operation_uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) for an operator API call I1027 22:21:59.768021 4166 master.cpp:11396] Updating the state of operation '' (uuid: e650afe9-c7c0-4285-9dd9-969175eca9ad) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I1027 22:21:59.768790 4170 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version I1027 22:21:59.770588 4177 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I1027 22:21:59.805400 4167 status_update_manager_process.hpp:490] Cleaning up operation status update stream 0f6710b6-e104-4b56-8e67-4c39e7579154 I1027 22:21:59.805846 4167 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for stream e650afe9-c7c0-4285-9dd9-969175eca9ad I1027 22:21:59.805996 4167 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 0f8acf96-5ac0-49b9-bbfc-420dfdd7c03e) for operation UUID e650afe9-c7c0-4285-9dd9-969175eca9ad on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:21:59.967684 4167 status_update_manager_process.hpp:490] Cleaning up operation status update stream e650afe9-c7c0-4285-9dd9-969175eca9ad I1027 22:22:00.080204 4169 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I1027 22:22:00.082646 4166 http.cpp:1436] HTTP POST for /master/api/v1 from 172.17.0.2:44038 I1027 22:22:00.082973 4166 http.cpp:277] Processing call DESTROY_VOLUMES I1027 22:22:00.084259 4166 master.cpp:3795] Authorizing principal 'test-principal' to perform action DESTROY_VOLUME on object {"value":"test-principal","resource":{"provider_id":{"value":"a0f4fd23-7a1e-48c6-9058-cf7bf61d4bde"},"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":"a4d8a0ad-ca5e-4edd-900b-ec712c7ac155","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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891","profile":"test"}}}} I1027 22:22:00.086537 4171 sched.cpp:963] Rescinded offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O4 I1027 22:22:00.086757 4171 sched.cpp:974] Scheduler::offerRescinded took 103691ns I1027 22:22:00.087441 4174 master.cpp:11879] Removing offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O4 I1027 22:22:00.087388 4168 hierarchical.cpp:1676] 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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test),a4d8a0ad-ca5e-4edd-900b-ec712c7ac155: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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test),a4d8a0ad-ca5e-4edd-900b-ec712c7ac155:volume]:2048, offered or allocated: {}) on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 from framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 I1027 22:22:00.090749 4168 hierarchical.cpp:1725] Framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 filtered agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 for 5secs I1027 22:22:00.094596 4182 master.cpp:11744] Sending operation '' (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) to agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:00.095216 4182 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version I1027 22:22:00.098735 4166 provider.cpp:498] Received APPLY_OPERATION event I1027 22:22:00.098783 4166 provider.cpp:1352] Received DESTROY operation '' (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) I1027 22:22:00.100574 4183 hierarchical.cpp:1953] Performed allocation for 1 agents in 2.618455ms I1027 22:22:00.101281 4173 master.cpp:9580] Sending offers [ 67d3d7f7-102e-4a76-bfce-e64091d7e007-O5 ] to framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 I1027 22:22:00.102133 4171 sched.cpp:937] Scheduler::resourceOffers took 120885ns I1027 22:22:00.201828 4174 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for operation UUID cd0bec9a-6e4e-40fb-996c-af10c13bdef1 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:22:00.201977 4174 status_update_manager_process.hpp:414] Creating operation status update stream cd0bec9a-6e4e-40fb-996c-af10c13bdef1 checkpoint=true I1027 22:22:00.202373 4174 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for operation UUID cd0bec9a-6e4e-40fb-996c-af10c13bdef1 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:22:00.268620 4174 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for operation UUID cd0bec9a-6e4e-40fb-996c-af10c13bdef1 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:22:00.269913 4165 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider I1027 22:22:00.271453 4167 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider' I1027 22:22:00.276281 4177 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I1027 22:22:00.278448 4175 http.cpp:1436] HTTP POST for /master/api/v1 from 172.17.0.2:44040 I1027 22:22:00.278779 4175 http.cpp:277] Processing call UNRESERVE_RESOURCES I1027 22:22:00.280036 4175 master.cpp:3795] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"provider_id":{"value":"a0f4fd23-7a1e-48c6-9058-cf7bf61d4bde"},"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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891","profile":"test"}}}} I1027 22:22:00.281949 4162 sched.cpp:963] Rescinded offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O5 I1027 22:22:00.282109 4162 sched.cpp:974] Scheduler::offerRescinded took 50546ns I1027 22:22:00.282766 4183 hierarchical.cpp:1676] 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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test)]:2048, offered or allocated: {}) on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 from framework 67d3d 7f7-102e-4a76-bfce-e64091d7e007-0000 I1027 22:22:00.282940 4176 master.cpp:11879] Removing offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O5 I1027 22:22:00.284926 4183 hierarchical.cpp:1725] Framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 filtered agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 for 5secs I1027 22:22:00.287570 4166 master.cpp:11744] Sending operation '' (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) to agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:00.288395 4165 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version I1027 22:22:00.292243 4177 provider.cpp:498] Received APPLY_OPERATION event I1027 22:22:00.292317 4177 provider.cpp:1352] Received UNRESERVE operation '' (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) I1027 22:22:00.297627 4175 hierarchical.cpp:1953] Performed allocation for 1 agents in 2.42387ms I1027 22:22:00.298494 4170 master.cpp:9580] Sending offers [ 67d3d7f7-102e-4a76-bfce-e64091d7e007-O6 ] to framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 I1027 22:22:00.299423 4184 sched.cpp:937] Scheduler::resourceOffers took 159178ns I1027 22:22:00.313318 4166 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:44020 I1027 22:22:00.314513 4168 slave.cpp:8733] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I1027 22:22:00.314716 4168 slave.cpp:9186] Updating the state of operation with no ID (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I1027 22:22:00.314769 4168 slave.cpp:8940] Forwarding status update of operation with no ID (operation_uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) for an operator API call I1027 22:22:00.315179 4163 master.cpp:11396] Updating the state of operation '' (uuid: cd0bec9a-6e4e-40fb-996c-af10c13bdef1) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I1027 22:22:00.315788 4165 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version I1027 22:22:00.462169 4184 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for operation UUID 1da16584-d1e3-4386-a9a1-27e6c572cebe on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:22:00.462246 4184 status_update_manager_process.hpp:414] Creating operation status update stream 1da16584-d1e3-4386-a9a1-27e6c572cebe checkpoint=true I1027 22:22:00.462481 4177 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I1027 22:22:00.462597 4184 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for operation UUID 1da16584-d1e3-4386-a9a1-27e6c572cebe on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:22:00.554447 4184 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for operation UUID 1da16584-d1e3-4386-a9a1-27e6c572cebe on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:22:00.554857 4184 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for stream cd0bec9a-6e4e-40fb-996c-af10c13bdef1 I1027 22:22:00.554939 4184 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 00c0e20f-15b8-4727-985b-9ca6b6f438d6) for operation UUID cd0bec9a-6e4e-40fb-996c-af10c13bdef1 on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:22:00.555320 4176 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider I1027 22:22:00.556428 4183 process.cpp:3671] Handling HTTP event for process 'slave(1248)' with path: '/slave(1248)/api/v1/resource_provider' I1027 22:22:00.601179 4165 http.cpp:1436] HTTP POST for /slave(1248)/api/v1/resource_provider from 172.17.0.2:44020 I1027 22:22:00.602291 4179 slave.cpp:8733] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) for framework (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I1027 22:22:00.602684 4179 slave.cpp:9186] Updating the state of operation with no ID (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I1027 22:22:00.602757 4179 slave.cpp:8940] Forwarding status update of operation with no ID (operation_uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) for an operator API call I1027 22:22:00.603193 4178 master.cpp:11396] Updating the state of operation '' (uuid: 1da16584-d1e3-4386-a9a1-27e6c572cebe) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I1027 22:22:00.603778 4185 slave.cpp:4576] Ignoring new checkpointed resources and operations identical to the current version I1027 22:22:00.605388 4171 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I1027 22:22:00.638206 4184 status_update_manager_process.hpp:490] Cleaning up operation status update stream cd0bec9a-6e4e-40fb-996c-af10c13bdef1 I1027 22:22:00.638445 4184 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for stream 1da16584-d1e3-4386-a9a1-27e6c572cebe I1027 22:22:00.638523 4184 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 8b3b9ea9-80e8-41c4-a39d-a97766ccba85) for operation UUID 1da16584-d1e3-4386-a9a1-27e6c572cebe on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:22:00.747154 4184 status_update_manager_process.hpp:490] Cleaning up operation status update stream 1da16584-d1e3-4386-a9a1-27e6c572cebe I1027 22:22:00.865804 4181 master.cpp:1416] Framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 disconnected I1027 22:22:00.865854 4181 master.cpp:3428] Deactivating framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 I1027 22:22:00.866282 4163 hierarchical.cpp:902] Deactivated framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 I1027 22:22:00.866811 4163 hierarchical.cpp:1676] 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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,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_iZ8Fei/2GB-2d24ab17-9fef-4574-ad29-d668429f8891,test)]:2048, offered or allocated: {}) on agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 from framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 I1027 22:22:00.866925 4181 master.cpp:11879] Removing offer 67d3d7f7-102e-4a76-bfce-e64091d7e007-O6 I1027 22:22:00.867043 4181 master.cpp:3412] Disconnecting framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 I1027 22:22:00.867173 4178 slave.cpp:1002] Agent terminating I1027 22:22:00.867252 4181 master.cpp:1431] Giving framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 0ns to failover I1027 22:22:00.868203 4178 manager.cpp:127] Terminating resource provider a0f4fd23-7a1e-48c6-9058-cf7bf61d4bde I1027 22:22:00.868628 4174 master.cpp:1301] Agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca) disconnected I1027 22:22:00.868665 4174 master.cpp:3463] Disconnecting agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:00.868753 4174 master.cpp:3482] Deactivating agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 at slave(1248)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:00.868990 4174 master.cpp:9364] Framework failover timeout, removing framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 I1027 22:22:00.869035 4174 master.cpp:10375] Removing framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 (default) at [email protected]:38707 E1027 22:22:00.869415 4179 http_connection.hpp:449] End-Of-File received I1027 22:22:00.869663 4163 hierarchical.cpp:1256] Agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 deactivated I1027 22:22:00.869719 4163 hierarchical.cpp:1877] Allocation paused I1027 22:22:00.869957 4179 http_connection.hpp:217] Re-detecting endpoint I1027 22:22:00.870350 4163 hierarchical.cpp:846] Removed framework 67d3d7f7-102e-4a76-bfce-e64091d7e007-0000 I1027 22:22:00.870421 4163 hierarchical.cpp:1887] Allocation resumed I1027 22:22:00.870460 4179 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I1027 22:22:00.870544 4179 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I1027 22:22:00.870642 4179 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider I1027 22:22:00.870723 4183 provider.cpp:488] Disconnected from resource provider manager I1027 22:22:00.870883 4171 status_update_manager_process.hpp:379] Pausing operation status update manager I1027 22:22:00.872409 4185 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I1027 22:22:00.872480 4185 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 3.658390144secs I1027 22:22:00.872956 4185 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:00.874639 4169 hierarchical.cpp:1953] Performed allocation for 1 agents in 206849ns I1027 22:22:00.874852 4175 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider I1027 22:22:00.875638 4173 provider.cpp:476] Connected to resource provider manager I1027 22:22:00.876456 4177 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1248)/api/v1/resource_provider I1027 22:22:00.877408 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1248)/api/v1/resource_provider' E1027 22:22:00.878964 4180 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I1027 22:22:00.926450 4184 hierarchical.cpp:1953] Performed allocation for 1 agents in 308058ns I1027 22:22:00.976565 4170 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I1027 22:22:00.978138 4169 hierarchical.cpp:1953] Performed allocation for 1 agents in 240284ns I1027 22:22:00.978746 4183 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 I1027 22:22:00.981992 4172 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' I1027 22:22:00.982364 4174 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-FiGDBq/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:00.982722 4164 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:00.986685 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1248)/api/v1' I1027 22:22:00.999568 4161 master.cpp:1149] Master terminating I1027 22:22:01.000471 4177 hierarchical.cpp:1232] Removed all filters for agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 I1027 22:22:01.000528 4177 hierarchical.cpp:1108] Removed agent 67d3d7f7-102e-4a76-bfce-e64091d7e007-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (3547 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 I1027 22:22:01.018968 4161 cluster.cpp:195] Creating default 'local' authorizer I1027 22:22:01.024662 4163 master.cpp:448] Master 2e0ec788-b347-4e29-8371-3a9f359e84ac (01d434b599ca) started on 172.17.0.2:38707 I1027 22:22:01.024700 4163 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --allocator_agent_recovery_factor="0.8" --allocator_recovery_timeout="10mins" --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/zb8n9j/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_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --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.12.0/_inst/share/mesos/webui" --work_dir="/tmp/zb8n9j/master" --zk_session_timeout="10secs" I1027 22:22:01.025372 4163 master.cpp:500] Master only allowing authenticated frameworks to register I1027 22:22:01.025395 4163 master.cpp:506] Master only allowing authenticated agents to register I1027 22:22:01.025416 4163 master.cpp:512] Master only allowing authenticated HTTP frameworks to register I1027 22:22:01.025436 4163 credentials.hpp:37] Loading credentials for authentication from '/tmp/zb8n9j/credentials' I1027 22:22:01.026286 4163 master.cpp:556] Using default 'crammd5' authenticator I1027 22:22:01.026599 4163 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I1027 22:22:01.026855 4163 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I1027 22:22:01.027052 4163 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I1027 22:22:01.027235 4163 master.cpp:637] Authorization enabled I1027 22:22:01.027681 4178 whitelist_watcher.cpp:77] No whitelist given I1027 22:22:01.027819 4167 hierarchical.cpp:656] Initialized hierarchical allocator process I1027 22:22:01.031508 4173 master.cpp:2174] Elected as the leading master! I1027 22:22:01.031553 4173 master.cpp:1670] Recovering from registrar I1027 22:22:01.031788 4185 registrar.cpp:339] Recovering registrar I1027 22:22:01.032675 4185 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I1027 22:22:01.032852 4185 registrar.cpp:487] Applied 1 operations in 53191ns; attempting to update the registry I1027 22:22:01.033653 4185 registrar.cpp:544] Successfully updated the registry in 0ns I1027 22:22:01.033829 4185 registrar.cpp:416] Successfully recovered registrar I1027 22:22:01.034605 4174 hierarchical.cpp:695] Skipping recovery of hierarchical allocator: nothing to recover I1027 22:22:01.034639 4162 master.cpp:1823] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister W1027 22:22:01.041569 4161 process.cpp:2877] Attempted to spawn already running process [email protected]:38707 I1027 22:22:01.042424 4161 resolver.cpp:69] Creating default secret resolver I1027 22:22:01.043359 4161 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W1027 22:22:01.044153 4161 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W1027 22:22:01.044186 4161 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W1027 22:22:01.044206 4161 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I1027 22:22:01.044245 4161 provisioner.cpp:294] Using default backend 'copy' I1027 22:22:01.047405 4161 cluster.cpp:620] Creating default 'local' authorizer I1027 22:22:01.050335 4169 slave.cpp:281] Mesos agent started on (1249)@172.17.0.2:38707 I1027 22:22:01.050369 4169 slave.cpp:282] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/zb8n9j/JMNS9U/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/zb8n9j/JMNS9U/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/zb8n9j/JMNS9U/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/zb8n9j/JMNS9U/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/zb8n9j/JMNS9U/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/zb8n9j/JMNS9U/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.12.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/zb8n9j/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_BianTL" --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_hm8RCC" --zk_session_timeout="10secs" I1027 22:22:01.050940 4169 credentials.hpp:73] Loading credential for authentication from '/tmp/zb8n9j/JMNS9U/credential' I1027 22:22:01.051164 4169 slave.cpp:314] Agent using credential for: test-principal I1027 22:22:01.051213 4169 credentials.hpp:37] Loading credentials for authentication from '/tmp/zb8n9j/JMNS9U/http_credentials' I1027 22:22:01.051476 4169 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I1027 22:22:01.052033 4169 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I1027 22:22:01.053933 4177 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I1027 22:22:01.053894 4169 slave.cpp:629] 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"}] I1027 22:22:01.054149 4169 slave.cpp:637] Agent attributes: [ ] I1027 22:22:01.054172 4169 slave.cpp:646] Agent hostname: 01d434b599ca I1027 22:22:01.054443 4179 task_status_update_manager.cpp:181] Pausing sending task status updates I1027 22:22:01.054508 4184 status_update_manager_process.hpp:379] Pausing operation status update manager I1027 22:22:01.054690 4176 hierarchical.cpp:1953] Performed allocation for 0 agents in 82125ns I1027 22:22:01.056529 4172 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/meta' I1027 22:22:01.056843 4164 slave.cpp:7742] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/meta', beginning agent recovery I1027 22:22:01.057611 4165 task_status_update_manager.cpp:207] Recovering task status update manager I1027 22:22:01.058221 4185 containerizer.cpp:830] Recovering Mesos containers I1027 22:22:01.058723 4185 containerizer.cpp:1170] Recovering isolators I1027 22:22:01.060046 4177 containerizer.cpp:1209] Recovering provisioner I1027 22:22:01.061256 4176 provisioner.cpp:518] Provisioner recovery complete I1027 22:22:01.062294 4174 composing.cpp:343] Finished recovering all containerizers I1027 22:22:01.062711 4175 slave.cpp:8224] Recovering executors I1027 22:22:01.062886 4175 slave.cpp:8377] Finished recovery I1027 22:22:01.063971 4167 task_status_update_manager.cpp:181] Pausing sending task status updates I1027 22:22:01.064052 4170 status_update_manager_process.hpp:379] Pausing operation status update manager I1027 22:22:01.064064 4178 slave.cpp:1473] New master detected at [email protected]:38707 I1027 22:22:01.064255 4178 slave.cpp:1538] Detecting new master I1027 22:22:01.065577 4181 slave.cpp:1565] Authenticating with master [email protected]:38707 I1027 22:22:01.065709 4181 slave.cpp:1574] Using default CRAM-MD5 authenticatee I1027 22:22:01.066166 4177 authenticatee.cpp:121] Creating new client SASL connection I1027 22:22:01.066572 4179 master.cpp:9771] Authenticating slave(1249)@172.17.0.2:38707 I1027 22:22:01.066857 4184 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2113)@172.17.0.2:38707 I1027 22:22:01.067315 4173 authenticator.cpp:98] Creating new server SASL connection I1027 22:22:01.067672 4176 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I1027 22:22:01.067737 4176 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I1027 22:22:01.067934 4176 authenticator.cpp:204] Received SASL authentication start I1027 22:22:01.068038 4176 authenticator.cpp:326] Authentication requires more steps I1027 22:22:01.068235 4164 authenticatee.cpp:259] Received SASL authentication step I1027 22:22:01.068429 4165 authenticator.cpp:232] Received SASL authentication step I1027 22:22:01.068487 4165 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '01d434b599ca' server FQDN: '01d434b599ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1027 22:22:01.068531 4165 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I1027 22:22:01.068620 4165 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1027 22:22:01.068671 4165 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '01d434b599ca' server FQDN: '01d434b599ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1027 22:22:01.068709 4165 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1027 22:22:01.068742 4165 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1027 22:22:01.068791 4165 authenticator.cpp:318] Authentication success I1027 22:22:01.068945 4172 authenticatee.cpp:299] Authentication success I1027 22:22:01.069141 4166 master.cpp:9803] Successfully authenticated principal 'test-principal' at slave(1249)@172.17.0.2:38707 I1027 22:22:01.069217 4171 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2113)@172.17.0.2:38707 I1027 22:22:01.069698 4182 slave.cpp:1665] Successfully authenticated with master [email protected]:38707 I1027 22:22:01.070506 4182 slave.cpp:2131] Will retry registration in 5.880334ms if necessary I1027 22:22:01.070739 4162 master.cpp:6264] Received register agent message from slave(1249)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:01.071344 4162 master.cpp:3795] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I1027 22:22:01.072221 4185 master.cpp:6331] Authorized registration of agent at slave(1249)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:01.072376 4185 master.cpp:6443] Registering agent at slave(1249)@172.17.0.2:38707 (01d434b599ca) with id 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 I1027 22:22:01.073371 4181 registrar.cpp:487] Applied 1 operations in 371983ns; attempting to update the registry I1027 22:22:01.074404 4181 registrar.cpp:544] Successfully updated the registry in 928768ns I1027 22:22:01.074668 4173 master.cpp:6491] Admitted agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:01.075825 4173 master.cpp:6536] Registered agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I1027 22:22:01.075963 4176 slave.cpp:1698] Registered with master [email protected]:38707; given agent ID 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 I1027 22:22:01.076045 4164 hierarchical.cpp:1059] Added agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 (01d434b599ca) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I1027 22:22:01.076154 4166 task_status_update_manager.cpp:188] Resuming sending task status updates I1027 22:22:01.076472 4164 hierarchical.cpp:1953] Performed allocation for 1 agents in 179682ns I1027 22:22:01.076660 4176 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/meta/slaves/2e0ec788-b347-4e29-8371-3a9f359e84ac-S0/slave.info' I1027 22:22:01.076781 4165 status_update_manager_process.hpp:385] Resuming operation status update manager I1027 22:22:01.078475 4176 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"APCn5LmaRuOhn44j4f1BBg=="},"slave_id":{"value":"2e0ec788-b347-4e29-8371-3a9f359e84ac-S0"},"update_oversubscribed_resources":false} I1027 22:22:01.079442 4182 master.cpp:7679] Ignoring update on agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca) as it reports no changes I1027 22:22:01.085672 4184 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1' I1027 22:22:01.087497 4164 http.cpp:1436] HTTP POST for /slave(1249)/api/v1 from 172.17.0.2:44054 I1027 22:22:01.088093 4164 http.cpp:2828] Processing GET_CONTAINERS call I1027 22:22:01.095993 4169 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:01.099715 4174 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1' I1027 22:22:01.101327 4176 http.cpp:1436] HTTP POST for /slave(1249)/api/v1 from 172.17.0.2:44056 I1027 22:22:01.102375 4176 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:01.103921 4172 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:01.105260 4163 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:01.106206 4182 hierarchical.cpp:1953] Performed allocation for 1 agents in 220712ns I1027 22:22:01.106266 4163 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 438272ns I1027 22:22:01.107491 4163 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_BianTL/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I1027 22:22:01.107594 4163 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.32992ms I1027 22:22:01.112208 4169 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_3k6nmt","--available_capacity=0B","--volumes=","--forward=unix:///tmp/zb8n9j/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/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-iZj3Cw/endpoint.sock"},{"name":"MESOS_AGENT_ID","type":"VALUE","value":"2e0ec788-b347-4e29-8371-3a9f359e84ac-S0"}]},"task_environment":{},"working _directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hm8RCC/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="111" --pipe_write="112" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_BianTL/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I1027 22:22:01.128119 4169 launcher.cpp:145] Forked child with pid '18792' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:01.129097 4169 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 21.516032ms I1027 22:22:01.130980 4176 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 1.76384ms I1027 22:22:01.131527 4183 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_hm8RCC/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:01.133123 4172 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 2.192896ms I1027 22:22:01.136818 4171 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' I1027 22:22:01.137077 4178 service_manager.cpp:795] Connecting to endpoint 'unix:///tmp/mesos-csi-iZj3Cw/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:01.158336 4174 hierarchical.cpp:1953] Performed allocation for 1 agents in 348297ns I1027 22:22:01.209789 4180 hierarchical.cpp:1953] Performed allocation for 1 agents in 166699ns I1027 22:22:01.261633 4167 hierarchical.cpp:1953] Performed allocation for 1 agents in 176268ns I1027 22:22:01.312912 4168 hierarchical.cpp:1953] Performed allocation for 1 agents in 158790ns I1027 22:22:01.364362 4164 hierarchical.cpp:1953] Performed allocation for 1 agents in 194514ns I1027 22:22:01.416148 4182 hierarchical.cpp:1953] Performed allocation for 1 agents in 240635ns I1027 22:22:01.467301 4179 hierarchical.cpp:1953] Performed allocation for 1 agents in 230869ns I1027 22:22:01.519119 4173 hierarchical.cpp:1953] Performed allocation for 1 agents in 268694ns I1027 22:22:01.570282 4176 hierarchical.cpp:1953] Performed allocation for 1 agents in 204993ns I1027 22:22:01.585103 4162 service_manager.cpp:622] Probing endpoint 'unix:///tmp/mesos-csi-iZj3Cw/endpoint.sock' with CSI v1 I1027 22:22:01.588333 4185 service_manager.cpp:609] Probing endpoint 'unix:///tmp/mesos-csi-iZj3Cw/endpoint.sock' with CSI v0 I1027 22:22:01.589629 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Identity/Probe call I1027 22:22:01.592864 4171 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:01.596361 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Identity/GetPluginCapabilities call I1027 22:22:01.597700 4166 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1' I1027 22:22:01.599530 4162 http.cpp:1436] HTTP POST for /slave(1249)/api/v1 from 172.17.0.2:44058 I1027 22:22:01.600229 4162 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:01.601894 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Identity/GetPluginInfo call I1027 22:22:01.602250 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Identity/GetPluginInfo call I1027 22:22:01.604629 4181 v0_volume_manager.cpp:656] NODE_SERVICE loaded: {} I1027 22:22:01.605506 4181 v0_volume_manager.cpp:656] CONTROLLER_SERVICE loaded: {} I1027 22:22:01.608222 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/ControllerGetCapabilities call I1027 22:22:01.613160 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Node/NodeGetCapabilities call I1027 22:22:01.617990 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Node/NodeGetId call I1027 22:22:01.621397 4168 provider.cpp:677] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I1027 22:22:01.621649 4184 status_update_manager_process.hpp:379] Pausing operation status update manager I1027 22:22:01.622139 4163 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider I1027 22:22:01.622280 4179 hierarchical.cpp:1953] Performed allocation for 1 agents in 260614ns I1027 22:22:01.627043 4170 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider I1027 22:22:01.628113 4172 provider.cpp:476] Connected to resource provider manager I1027 22:22:01.629168 4182 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider I1027 22:22:01.630913 4169 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I1027 22:22:01.633514 4179 http.cpp:1436] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:44062 I1027 22:22:01.634582 4178 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_3k6nmt","--available_capacity=0B","--volumes=","--forward=unix:///tmp/zb8n9j/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.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"} I1027 22:22:01.673678 4176 hierarchical.cpp:1953] Performed allocation for 1 agents in 198885ns I1027 22:22:01.692338 4183 slave.cpp:8733] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"5d0f7f0a-5571-436c-ad32-00c6b25cef81"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_3k6nmt","--available_capacity=0B","--volumes=","--forward=unix:///tmp/zb8n9j/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.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"}' I1027 22:22:01.694782 4171 provider.cpp:498] Received SUBSCRIBED event I1027 22:22:01.694847 4171 provider.cpp:1310] Subscribed with ID 5d0f7f0a-5571-436c-ad32-00c6b25cef81 I1027 22:22:01.696148 4179 status_update_manager_process.hpp:314] Recovering operation status update manager I1027 22:22:01.725701 4163 hierarchical.cpp:1953] Performed allocation for 1 agents in 196029ns I1027 22:22:01.777526 4173 hierarchical.cpp:1953] Performed allocation for 1 agents in 179426ns I1027 22:22:01.825809 4178 provider.cpp:791] Reconciling storage pools and volumes I1027 22:22:01.828955 4175 hierarchical.cpp:1953] Performed allocation for 1 agents in 236966ns I1027 22:22:01.829205 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/ListVolumes call I1027 22:22:01.833452 4168 provider.cpp:2218] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 I1027 22:22:01.833904 4179 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider I1027 22:22:01.833992 4168 provider.cpp:749] Resource provider 5d0f7f0a-5571-436c-ad32-00c6b25cef81 is in READY state I1027 22:22:01.834097 4163 status_update_manager_process.hpp:385] Resuming operation status update manager I1027 22:22:01.835078 4166 provider.cpp:1236] Updating profiles { test } for resource provider 5d0f7f0a-5571-436c-ad32-00c6b25cef81 I1027 22:22:01.835590 4176 process.cpp:3671] Handling HTTP event for process 'slave(1249)' with path: '/slave(1249)/api/v1/resource_provider' I1027 22:22:01.837074 4182 provider.cpp:791] Reconciling storage pools and volumes I1027 22:22:01.838527 4171 http.cpp:1436] HTTP POST for /slave(1249)/api/v1/resource_provider from 172.17.0.2:44060 I1027 22:22:01.839448 4179 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 5d0f7f0a-5571-436c-ad32-00c6b25cef81 I1027 22:22:01.839846 4164 slave.cpp:8733] Handling resource provider message 'UPDATE_STATE: 5d0f7f0a-5571-436c-ad32-00c6b25cef81 {}' I1027 22:22:01.839951 4164 slave.cpp:8853] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I1027 22:22:01.840185 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/ListVolumes call I1027 22:22:01.840570 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/GetCapacity call I1027 22:22:01.841958 4167 hierarchical.cpp:1210] Grew agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 by {} (total), { } (used) I1027 22:22:01.842475 4167 hierarchical.cpp:1167] Agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 (01d434b599ca) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I1027 22:22:01.848054 4164 hierarchical.cpp:1953] Performed allocation for 1 agents in 174315ns I1027 22:22:01.848747 4176 provider.cpp:791] Reconciling storage pools and volumes I1027 22:22:01.851475 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/ListVolumes call I1027 22:22:01.851958 18796 test_csi_plugin.cpp:1968] Forwarding /csi.v0.Controller/GetCapacity call I1027 22:22:01.862438 4165 slave.cpp:1002] Agent terminating I1027 22:22:01.863360 4165 manager.cpp:127] Terminating resource provider 5d0f7f0a-5571-436c-ad32-00c6b25cef81 I1027 22:22:01.864092 4185 master.cpp:1301] Agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca) disconnected I1027 22:22:01.864130 4185 master.cpp:3463] Disconnecting agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:01.864209 4185 master.cpp:3482] Deactivating agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 at slave(1249)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:01.864398 4163 hierarchical.cpp:1256] Agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 deactivated E1027 22:22:01.864652 4173 http_connection.hpp:449] End-Of-File received I1027 22:22:01.865160 4173 http_connection.hpp:217] Re-detecting endpoint I1027 22:22:01.865659 4173 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I1027 22:22:01.865710 4173 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I1027 22:22:01.865777 4167 provider.cpp:488] Disconnected from resource provider manager I1027 22:22:01.865810 4173 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider I1027 22:22:01.865887 4167 status_update_manager_process.hpp:379] Pausing operation status update manager I1027 22:22:01.867311 4166 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I1027 22:22:01.867383 4166 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.73433728secs I1027 22:22:01.867969 4166 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:01.869261 4175 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider I1027 22:22:01.870036 4162 provider.cpp:476] Connected to resource provider manager I1027 22:22:01.870910 4167 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1249)/api/v1/resource_provider I1027 22:22:01.872042 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1/resource_provider' E1027 22:22:01.873749 4182 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I1027 22:22:01.893637 4165 hierarchical.cpp:1953] Performed allocation for 1 agents in 138328ns I1027 22:22:01.944320 4181 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I1027 22:22:01.944399 4178 hierarchical.cpp:1953] Performed allocation for 1 agents in 135464ns I1027 22:22:01.946596 4183 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 I1027 22:22:01.950111 4185 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' I1027 22:22:01.950392 4168 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-iZj3Cw/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:01.950759 4180 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:01.955013 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1249)/api/v1' I1027 22:22:01.968307 4161 master.cpp:1149] Master terminating I1027 22:22:01.968688 4177 hierarchical.cpp:1232] Removed all filters for agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 I1027 22:22:01.968716 4177 hierarchical.cpp:1108] Removed agent 2e0ec788-b347-4e29-8371-3a9f359e84ac-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v0 (965 ms) [ RUN ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 I1027 22:22:01.985546 4161 cluster.cpp:195] Creating default 'local' authorizer I1027 22:22:01.991154 4173 master.cpp:448] Master 7980836c-504b-4b03-80d6-019861211e08 (01d434b599ca) started on 172.17.0.2:38707 I1027 22:22:01.991185 4173 master.cpp:451] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --allocator_agent_recovery_factor="0.8" --allocator_recovery_timeout="10mins" --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/yNXvzu/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_allocatable_resources="cpus:0.01|mem:32" --offer_constraints_re2_max_mem="4KB" --offer_constraints_re2_max_program_size="100" --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.12.0/_inst/share/mesos/webui" --work_dir="/tmp/yNXvzu/master" --zk_session_timeout="10secs" I1027 22:22:01.991639 4173 master.cpp:500] Master only allowing authenticated frameworks to register I1027 22:22:01.991674 4173 master.cpp:506] Master only allowing authenticated agents to register I1027 22:22:01.991694 4173 master.cpp:512] Master only allowing authenticated HTTP frameworks to register I1027 22:22:01.991715 4173 credentials.hpp:37] Loading credentials for authentication from '/tmp/yNXvzu/credentials' I1027 22:22:01.992008 4173 master.cpp:556] Using default 'crammd5' authenticator I1027 22:22:01.992236 4173 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly' I1027 22:22:01.992502 4173 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' I1027 22:22:01.992700 4173 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' I1027 22:22:01.992904 4173 master.cpp:637] Authorization enabled I1027 22:22:01.993363 4180 whitelist_watcher.cpp:77] No whitelist given I1027 22:22:01.993505 4181 hierarchical.cpp:656] Initialized hierarchical allocator process I1027 22:22:01.997114 4174 master.cpp:2174] Elected as the leading master! I1027 22:22:01.997156 4174 master.cpp:1670] Recovering from registrar I1027 22:22:01.997406 4166 registrar.cpp:339] Recovering registrar I1027 22:22:01.998350 4166 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns I1027 22:22:01.998517 4166 registrar.cpp:487] Applied 1 operations in 61322ns; attempting to update the registry I1027 22:22:01.999295 4166 registrar.cpp:544] Successfully updated the registry in 0ns I1027 22:22:01.999446 4166 registrar.cpp:416] Successfully recovered registrar I1027 22:22:01.999967 4162 master.cpp:1823] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister I1027 22:22:02.000012 4179 hierarchical.cpp:695] Skipping recovery of hierarchical allocator: nothing to recover W1027 22:22:02.006747 4161 process.cpp:2877] Attempted to spawn already running process [email protected]:38707 I1027 22:22:02.007606 4161 resolver.cpp:69] Creating default secret resolver I1027 22:22:02.008528 4161 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } W1027 22:22:02.009246 4161 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges W1027 22:22:02.009277 4161 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges W1027 22:22:02.009297 4161 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges I1027 22:22:02.009335 4161 provisioner.cpp:294] Using default backend 'copy' I1027 22:22:02.012606 4161 cluster.cpp:620] Creating default 'local' authorizer I1027 22:22:02.015388 4178 slave.cpp:281] Mesos agent started on (1250)@172.17.0.2:38707 I1027 22:22:02.015417 4178 slave.cpp:282] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/yNXvzu/Y0jDpe/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/yNXvzu/Y0jDpe/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/yNXvzu/Y0jDpe/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/yNXvzu/Y0jDpe/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/yNXvzu/Y0jDpe/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/yNXvzu/Y0jDpe/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.12.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/yNXvzu/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_FVuhW2" --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_67cWsR" --zk_session_timeout="10secs" I1027 22:22:02.016022 4178 credentials.hpp:73] Loading credential for authentication from '/tmp/yNXvzu/Y0jDpe/credential' I1027 22:22:02.016188 4178 slave.cpp:314] Agent using credential for: test-principal I1027 22:22:02.016214 4178 credentials.hpp:37] Loading credentials for authentication from '/tmp/yNXvzu/Y0jDpe/http_credentials' I1027 22:22:02.016470 4178 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' I1027 22:22:02.016880 4178 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' I1027 22:22:02.018610 4173 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles I1027 22:22:02.018667 4178 slave.cpp:629] 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"}] I1027 22:22:02.018916 4178 slave.cpp:637] Agent attributes: [ ] I1027 22:22:02.018935 4178 slave.cpp:646] Agent hostname: 01d434b599ca I1027 22:22:02.019130 4174 status_update_manager_process.hpp:379] Pausing operation status update manager I1027 22:22:02.019167 4170 task_status_update_manager.cpp:181] Pausing sending task status updates I1027 22:22:02.021096 4177 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/meta' I1027 22:22:02.021324 4183 slave.cpp:7742] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/meta', beginning agent recovery I1027 22:22:02.021661 4176 hierarchical.cpp:1953] Performed allocation for 0 agents in 91869ns I1027 22:22:02.021955 4185 task_status_update_manager.cpp:207] Recovering task status update manager I1027 22:22:02.022380 4162 containerizer.cpp:830] Recovering Mesos containers I1027 22:22:02.022800 4162 containerizer.cpp:1170] Recovering isolators I1027 22:22:02.023695 4174 containerizer.cpp:1209] Recovering provisioner I1027 22:22:02.024824 4175 provisioner.cpp:518] Provisioner recovery complete I1027 22:22:02.026113 4185 composing.cpp:343] Finished recovering all containerizers I1027 22:22:02.026557 4172 slave.cpp:8224] Recovering executors I1027 22:22:02.026684 4172 slave.cpp:8377] Finished recovery I1027 22:22:02.027788 4182 task_status_update_manager.cpp:181] Pausing sending task status updates I1027 22:22:02.027827 4164 status_update_manager_process.hpp:379] Pausing operation status update manager I1027 22:22:02.027873 4172 slave.cpp:1473] New master detected at [email protected]:38707 I1027 22:22:02.028046 4172 slave.cpp:1538] Detecting new master I1027 22:22:02.030474 4165 slave.cpp:1565] Authenticating with master [email protected]:38707 I1027 22:22:02.030625 4165 slave.cpp:1574] Using default CRAM-MD5 authenticatee I1027 22:22:02.031085 4162 authenticatee.cpp:121] Creating new client SASL connection I1027 22:22:02.031492 4174 master.cpp:9771] Authenticating slave(1250)@172.17.0.2:38707 I1027 22:22:02.031723 4173 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2114)@172.17.0.2:38707 I1027 22:22:02.032177 4169 authenticator.cpp:98] Creating new server SASL connection I1027 22:22:02.032495 4170 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I1027 22:22:02.032541 4170 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I1027 22:22:02.032714 4177 authenticator.cpp:204] Received SASL authentication start I1027 22:22:02.032822 4177 authenticator.cpp:326] Authentication requires more steps I1027 22:22:02.033025 4184 authenticatee.cpp:259] Received SASL authentication step I1027 22:22:02.033241 4167 authenticator.cpp:232] Received SASL authentication step I1027 22:22:02.033313 4167 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '01d434b599ca' server FQDN: '01d434b599ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1027 22:22:02.033347 4167 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I1027 22:22:02.033416 4167 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1027 22:22:02.033455 4167 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '01d434b599ca' server FQDN: '01d434b599ca' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1027 22:22:02.033486 4167 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1027 22:22:02.033519 4167 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1027 22:22:02.033561 4167 authenticator.cpp:318] Authentication success I1027 22:22:02.033717 4183 authenticatee.cpp:299] Authentication success I1027 22:22:02.033879 4176 master.cpp:9803] Successfully authenticated principal 'test-principal' at slave(1250)@172.17.0.2:38707 I1027 22:22:02.033972 4171 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2114)@172.17.0.2:38707 I1027 22:22:02.034361 4178 slave.cpp:1665] Successfully authenticated with master [email protected]:38707 I1027 22:22:02.034981 4178 slave.cpp:2131] Will retry registration in 13.979823ms if necessary I1027 22:22:02.035200 4181 master.cpp:6264] Received register agent message from slave(1250)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:02.035804 4181 master.cpp:3795] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object I1027 22:22:02.036586 4163 master.cpp:6331] Authorized registration of agent at slave(1250)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:02.036767 4163 master.cpp:6443] Registering agent at slave(1250)@172.17.0.2:38707 (01d434b599ca) with id 7980836c-504b-4b03-80d6-019861211e08-S0 I1027 22:22:02.037776 4165 registrar.cpp:487] Applied 1 operations in 381365ns; attempting to update the registry I1027 22:22:02.038763 4165 registrar.cpp:544] Successfully updated the registry in 894976ns I1027 22:22:02.039031 4170 master.cpp:6491] Admitted agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:02.040088 4170 master.cpp:6536] Registered agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I1027 22:22:02.040189 4184 slave.cpp:1698] Registered with master [email protected]:38707; given agent ID 7980836c-504b-4b03-80d6-019861211e08-S0 I1027 22:22:02.040355 4166 task_status_update_manager.cpp:188] Resuming sending task status updates I1027 22:22:02.040374 4177 hierarchical.cpp:1059] Added agent 7980836c-504b-4b03-80d6-019861211e08-S0 (01d434b599ca) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I1027 22:22:02.040910 4184 slave.cpp:1733] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/meta/slaves/7980836c-504b-4b03-80d6-019861211e08-S0/slave.info' I1027 22:22:02.040915 4177 hierarchical.cpp:1953] Performed allocation for 1 agents in 219053ns I1027 22:22:02.041025 4175 status_update_manager_process.hpp:385] Resuming operation status update manager I1027 22:22:02.042515 4184 slave.cpp:1793] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"sTRibVCRRhecKfpiWEy43A=="},"slave_id":{"value":"7980836c-504b-4b03-80d6-019861211e08-S0"},"update_oversubscribed_resources":false} I1027 22:22:02.043542 4164 master.cpp:7679] Ignoring update on agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca) as it reports no changes I1027 22:22:02.049405 4165 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1' I1027 22:22:02.051185 4175 http.cpp:1436] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:44074 I1027 22:22:02.052012 4175 http.cpp:2828] Processing GET_CONTAINERS call I1027 22:22:02.060914 4162 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:02.064894 4170 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1' I1027 22:22:02.066435 4168 http.cpp:1436] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:44076 I1027 22:22:02.067682 4168 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:02.069453 4180 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:02.070626 4179 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:02.071810 4179 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 516096ns I1027 22:22:02.073230 4179 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_FVuhW2/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I1027 22:22:02.073323 4179 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.517824ms I1027 22:22:02.073562 4181 hierarchical.cpp:1953] Performed allocation for 1 agents in 255936ns I1027 22:22:02.078480 4162 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_xeWBZF","--available_capacity=0B","--volumes=","--forward=unix:///tmp/yNXvzu/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/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-Z9PGHY/endpoint.sock"},{"name":"MESOS_AGENT_ID","type":"VALUE","value":"7980836c-504b-4b03-80d6-019861211e08-S0"}]},"task_environment":{},"working _directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_67cWsR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="111" --pipe_write="112" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_FVuhW2/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I1027 22:22:02.093708 4162 launcher.cpp:145] Forked child with pid '18806' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:02.094727 4162 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 21.398272ms I1027 22:22:02.096310 4162 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 1.583872ms I1027 22:22:02.096722 4184 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_67cWsR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:02.097929 4172 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 1.554944ms I1027 22:22:02.101649 4173 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' I1027 22:22:02.101938 4163 service_manager.cpp:795] Connecting to endpoint 'unix:///tmp/mesos-csi-Z9PGHY/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:02.125177 4183 hierarchical.cpp:1953] Performed allocation for 1 agents in 266487ns I1027 22:22:02.176331 4184 hierarchical.cpp:1953] Performed allocation for 1 agents in 218030ns I1027 22:22:02.227741 4180 hierarchical.cpp:1953] Performed allocation for 1 agents in 286968ns I1027 22:22:02.278831 4167 hierarchical.cpp:1953] Performed allocation for 1 agents in 200796ns I1027 22:22:02.330262 4170 hierarchical.cpp:1953] Performed allocation for 1 agents in 155470ns I1027 22:22:02.381809 4181 hierarchical.cpp:1953] Performed allocation for 1 agents in 156314ns I1027 22:22:02.433491 4169 hierarchical.cpp:1953] Performed allocation for 1 agents in 143854ns I1027 22:22:02.484535 4175 hierarchical.cpp:1953] Performed allocation for 1 agents in 214503ns I1027 22:22:02.535359 4162 hierarchical.cpp:1953] Performed allocation for 1 agents in 154978ns I1027 22:22:02.558447 4164 service_manager.cpp:622] Probing endpoint 'unix:///tmp/mesos-csi-Z9PGHY/endpoint.sock' with CSI v1 I1027 22:22:02.561594 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Identity/Probe call I1027 22:22:02.566174 4173 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:02.570391 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Identity/GetPluginCapabilities call I1027 22:22:02.571681 4175 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1' I1027 22:22:02.573675 4182 http.cpp:1436] HTTP POST for /slave(1250)/api/v1 from 172.17.0.2:44088 I1027 22:22:02.574520 4182 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:02.576895 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Identity/GetPluginInfo call I1027 22:22:02.577453 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Identity/GetPluginInfo call I1027 22:22:02.580444 4165 v1_volume_manager.cpp:677] NODE_SERVICE loaded: {} I1027 22:22:02.581347 4165 v1_volume_manager.cpp:677] CONTROLLER_SERVICE loaded: {} I1027 22:22:02.584501 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/ControllerGetCapabilities call I1027 22:22:02.587445 4162 hierarchical.cpp:1953] Performed allocation for 1 agents in 225965ns I1027 22:22:02.589948 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Node/NodeGetCapabilities call I1027 22:22:02.595288 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Node/NodeGetInfo call I1027 22:22:02.598826 4173 provider.cpp:677] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I1027 22:22:02.599056 4180 status_update_manager_process.hpp:379] Pausing operation status update manager I1027 22:22:02.599706 4167 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider I1027 22:22:02.604614 4175 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider I1027 22:22:02.605742 4185 provider.cpp:476] Connected to resource provider manager I1027 22:22:02.606871 4181 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider I1027 22:22:02.608769 4164 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider' I1027 22:22:02.611454 4173 http.cpp:1436] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:44092 I1027 22:22:02.612654 4165 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_xeWBZF","--available_capacity=0B","--volumes=","--forward=unix:///tmp/yNXvzu/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.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"} I1027 22:22:02.638798 4177 hierarchical.cpp:1953] Performed allocation for 1 agents in 247814ns I1027 22:22:02.659528 4172 slave.cpp:8733] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"71d208e3-4cc5-480b-b45a-37abbb1c4ab3"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/mesos-1.12.0/_build/sub/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_xeWBZF","--available_capacity=0B","--volumes=","--forward=unix:///tmp/yNXvzu/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/mesos-1.12.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"}' I1027 22:22:02.661659 4179 provider.cpp:498] Received SUBSCRIBED event I1027 22:22:02.661722 4179 provider.cpp:1310] Subscribed with ID 71d208e3-4cc5-480b-b45a-37abbb1c4ab3 I1027 22:22:02.662734 4173 status_update_manager_process.hpp:314] Recovering operation status update manager I1027 22:22:02.689925 4167 hierarchical.cpp:1953] Performed allocation for 1 agents in 154682ns I1027 22:22:02.741641 4162 hierarchical.cpp:1953] Performed allocation for 1 agents in 178510ns I1027 22:22:02.767518 4165 provider.cpp:791] Reconciling storage pools and volumes I1027 22:22:02.771236 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/ListVolumes call I1027 22:22:02.775377 4180 provider.cpp:2218] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 7980836c-504b-4b03-80d6-019861211e08-S0 I1027 22:22:02.775825 4179 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider I1027 22:22:02.776005 4180 provider.cpp:749] Resource provider 71d208e3-4cc5-480b-b45a-37abbb1c4ab3 is in READY state I1027 22:22:02.776073 4173 status_update_manager_process.hpp:385] Resuming operation status update manager I1027 22:22:02.777132 4162 provider.cpp:1236] Updating profiles { test } for resource provider 71d208e3-4cc5-480b-b45a-37abbb1c4ab3 I1027 22:22:02.777516 4176 process.cpp:3671] Handling HTTP event for process 'slave(1250)' with path: '/slave(1250)/api/v1/resource_provider' I1027 22:22:02.778800 4171 provider.cpp:791] Reconciling storage pools and volumes I1027 22:22:02.780418 4174 http.cpp:1436] HTTP POST for /slave(1250)/api/v1/resource_provider from 172.17.0.2:44090 I1027 22:22:02.781188 4173 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 71d208e3-4cc5-480b-b45a-37abbb1c4ab3 I1027 22:22:02.781527 4183 slave.cpp:8733] Handling resource provider message 'UPDATE_STATE: 71d208e3-4cc5-480b-b45a-37abbb1c4ab3 {}' I1027 22:22:02.781685 4183 slave.cpp:8853] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I1027 22:22:02.782261 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/ListVolumes call I1027 22:22:02.783010 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/GetCapacity call I1027 22:22:02.784294 4172 hierarchical.cpp:1210] Grew agent 7980836c-504b-4b03-80d6-019861211e08-S0 by {} (total), { } (used) I1027 22:22:02.785245 4172 hierarchical.cpp:1167] Agent 7980836c-504b-4b03-80d6-019861211e08-S0 (01d434b599ca) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I1027 22:22:02.792011 4162 hierarchical.cpp:1953] Performed allocation for 1 agents in 305662ns I1027 22:22:02.792286 4175 provider.cpp:791] Reconciling storage pools and volumes I1027 22:22:02.795267 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/ListVolumes call I1027 22:22:02.795876 18810 test_csi_plugin.cpp:1968] Forwarding /csi.v1.Controller/GetCapacity call I1027 22:22:02.806404 4162 slave.cpp:1002] Agent terminating I1027 22:22:02.807566 4162 manager.cpp:127] Terminating resource provider 71d208e3-4cc5-480b-b45a-37abbb1c4ab3 I1027 22:22:02.808166 4164 master.cpp:1301] Agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca) disconnected I1027 22:22:02.808228 4164 master.cpp:3463] Disconnecting agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:02.808346 4164 master.cpp:3482] Deactivating agent 7980836c-504b-4b03-80d6-019861211e08-S0 at slave(1250)@172.17.0.2:38707 (01d434b599ca) I1027 22:22:02.808507 4166 hierarchical.cpp:1256] Agent 7980836c-504b-4b03-80d6-019861211e08-S0 deactivated E1027 22:22:02.808842 4167 http_connection.hpp:449] End-Of-File received I1027 22:22:02.809526 4167 http_connection.hpp:217] Re-detecting endpoint I1027 22:22:02.810217 4167 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I1027 22:22:02.810338 4167 http_connection.hpp:338] Ignoring disconnection attempt from stale connection I1027 22:22:02.810395 4175 provider.cpp:488] Disconnected from resource provider manager I1027 22:22:02.810467 4167 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider I1027 22:22:02.810632 4184 status_update_manager_process.hpp:379] Pausing operation status update manager I1027 22:22:02.812739 4173 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state I1027 22:22:02.812830 4173 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.714965248secs I1027 22:22:02.813417 4173 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:02.814663 4181 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider I1027 22:22:02.815485 4182 provider.cpp:476] Connected to resource provider manager I1027 22:22:02.816428 4177 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:38707/slave(1250)/api/v1/resource_provider I1027 22:22:02.817514 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1/resource_provider' E1027 22:22:02.819304 4172 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () I1027 22:22:02.836248 4180 hierarchical.cpp:1953] Performed allocation for 1 agents in 144413ns I1027 22:22:02.887215 4179 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited I1027 22:22:02.887240 4174 hierarchical.cpp:1953] Performed allocation for 1 agents in 183328ns I1027 22:22:02.889788 4175 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 I1027 22:22:02.893399 4164 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' I1027 22:22:02.893715 4162 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-Z9PGHY/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1027 22:22:02.894418 4174 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1027 22:22:02.897889 4186 process.cpp:2781] Returning '404 Not Found' for '/slave(1250)/api/v1' I1027 22:22:02.909773 4161 master.cpp:1149] Master terminating I1027 22:22:02.910137 4176 hierarchical.cpp:1232] Removed all filters for agent 7980836c-504b-4b03-80d6-019861211e08-S0 I1027 22:22:02.910166 4176 hierarchical.cpp:1108] Removed agent 7980836c-504b-4b03-80d6-019861211e08-S0 [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (940 ms) [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (130890 ms total) [----------] Global test environment tear-down [==========] 2340 tests from 224 test cases ran. (1435624 ms total) [ PASSED ] 2339 tests. [ FAILED ] 1 test, listed below: [ FAILED ] OversubscriptionTest.FixedResourceEstimator 1 FAILED TEST YOU HAVE 34 DISABLED TESTS I1027 22:22:03.027797 4186 process.cpp:935] Stopped the socket accept loop Makefile:16043: recipe for target 'check-local' failed make[4]: *** [check-local] Error 1 make[4]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' Makefile:15151: recipe for target 'check-am' failed make[3]: *** [check-am] Error 2 make[3]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' Makefile:15155: recipe for target 'check' failed make[2]: *** [check] Error 2 make[2]: Leaving directory '/tmp/SRC/build/mesos-1.12.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.12.0/_build/sub' Makefile:991: recipe for target 'distcheck' failed make: *** [distcheck] Error 1 Error response from daemon: conflict: unable to delete e895c0531b9a (cannot be forced) - image is being used by running container e54d9f77b396 Full log: https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot/1559/console - Mesos Reviewbot On Oct. 14, 2020, 6:18 p.m., Andrei Sekretenko wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/72956/ > ----------------------------------------------------------- > > (Updated Oct. 14, 2020, 6:18 p.m.) > > > Review request for mesos and Benjamin Mahler. > > > Bugs: MESOS-10176 > https://issues.apache.org/jira/browse/MESOS-10176 > > > Repository: mesos > > > Description > ------- > > This patch makes SUBSCRIBE/UPDATE_FRAMEWORK calls validate that > the framework does not specify offer constraints for roles to which > it is not going to be subscribed. > > > Diffs > ----- > > src/master/master.cpp d6d3ea7e27539a65b601783eca2ac4e3b688f188 > src/master/validation.hpp 7fe8f087b322f8e77218f4dd9f9f75707afa3208 > src/master/validation.cpp 5b1bcb5207aac0553bf9c1a0d89525c835393ccb > src/tests/master/update_framework_tests.cpp > 3f86573e8dfeea63fe99064f2137c61d901f4fc7 > > > Diff: https://reviews.apache.org/r/72956/diff/3/ > > > Testing > ------- > > `make check` > `src/mesos-tests > --gtest_filter='*UpdateFrameworkTest.OfferConstraintsForUnsubscribedRole*' > --gtest_break_on_failure --gtest_repeat=1000` > > > Thanks, > > Andrei Sekretenko > >
