mesos-reviews mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Mesos Reviewbot <revi...@mesos.apache.org>
Subject Re: Review Request 71343: Fixed out-of-order processing of terminal status updates in agent.
Date Thu, 22 Aug 2019 00:43:05 GMT

-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71343/#review217368
-----------------------------------------------------------



Bad patch!

Reviews applied: [71343]

Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:14.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/docker-build.sh 2>&1 | tee build_71343"]

Error:
...<truncated>...
18624 http.cpp:263] Processing call DESTROY_VOLUMES
I0822 00:42:32.563313 18624 master.cpp:3998] Authorizing principal 'test-principal' to destroy volumes '[{"disk":{"persistence":{"id":"cb13a84f-1888-4f0b-9042-7eb5a3f9632d","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ZX1WjK/2GB-c2382977-f0bf-49c9-9408-fca4f4959fbf","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"},"volume":{"container_path":"volume","mode":"RW"}},"name":"disk","provider_id":{"value":"2acdbcf4-880f-4035-9068-d76c90f7379f"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0822 00:42:32.567185 18631 master.cpp:12724] Removing offer d42d1569-3454-4001-b72e-5dee6d8119c4-O4
I0822 00:42:32.569187 18631 sched.cpp:960] Rescinded offer d42d1569-3454-4001-b72e-5dee6d8119c4-O4
I0822 00:42:32.569320 18631 sched.cpp:971] Scheduler::offerRescinded took 36302ns
I0822 00:42:32.570363 18628 hierarchical.cpp:1454] Recovered 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_ZX1WjK/2GB-c2382977-f0bf-49c9-9408-fca4f4959fbf,test),cb13a84f-1888-4f0b-9042-7eb5a3f9632d:volume]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (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_ZX1WjK/2GB-c2382977-f0bf-49c9-9408-fca4f4959fbf,test),cb13a84f-1888-4f0b-9042-7eb5a3f9632d:volume]:2048, allocat
 ed: {}) on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 from framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000
I0822 00:42:32.570607 18628 hierarchical.cpp:1500] Framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 filtered agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 for 5secs
I0822 00:42:32.575932 18629 master.cpp:12615] Sending operation '' (uuid: 74601dd1-b000-4b50-b647-26ed9934d706) to agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 at slave(1225)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:32.577000 18629 slave.cpp:4352] Ignoring new checkpointed resources and operations identical to the current version
I0822 00:42:32.587234 18629 hierarchical.cpp:1740] Performed allocation for 1 agents in 2.050864ms
I0822 00:42:32.588766 18610 master.cpp:10432] Sending offers [ d42d1569-3454-4001-b72e-5dee6d8119c4-O5 ] to framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 (default) at scheduler-0abc1be1-835e-4f52-8cef-a6e0fb673272@172.17.0.4:35575
I0822 00:42:32.589761 18610 sched.cpp:934] Scheduler::resourceOffers took 110908ns
I0822 00:42:32.591498 18620 provider.cpp:498] Received APPLY_OPERATION event
I0822 00:42:32.591593 18620 provider.cpp:1329] Received DESTROY operation '' (uuid: 74601dd1-b000-4b50-b647-26ed9934d706)
I0822 00:42:32.692255 18620 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: f4365977-c3f4-4564-b94c-4c3cf5fef091) for operation UUID 74601dd1-b000-4b50-b647-26ed9934d706 on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
I0822 00:42:32.692404 18620 status_update_manager_process.hpp:414] Creating operation status update stream 74601dd1-b000-4b50-b647-26ed9934d706 checkpoint=true
I0822 00:42:32.693342 18620 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: f4365977-c3f4-4564-b94c-4c3cf5fef091) for operation UUID 74601dd1-b000-4b50-b647-26ed9934d706 on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
I0822 00:42:32.742231 18620 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: f4365977-c3f4-4564-b94c-4c3cf5fef091) for operation UUID 74601dd1-b000-4b50-b647-26ed9934d706 on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
I0822 00:42:32.743811 18616 http_connection.hpp:131] Sending 2 call to http://172.17.0.4:35575/slave(1225)/api/v1/resource_provider
I0822 00:42:32.745854 18616 process.cpp:3671] Handling HTTP event for process 'slave(1225)' with path: '/slave(1225)/api/v1/resource_provider'
I0822 00:42:32.751256 18608 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0822 00:42:32.754339 18621 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.4:40466
I0822 00:42:32.755708 18621 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0822 00:42:32.757546 18621 master.cpp:3890] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ZX1WjK/2GB-c2382977-f0bf-49c9-9408-fca4f4959fbf","mount":{"root":"./csi/org.apache.mesos.csi.test/local/mounts"},"profile":"test","type":"MOUNT","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"2acdbcf4-880f-4035-9068-d76c90f7379f"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0822 00:42:32.761315 18626 master.cpp:12724] Removing offer d42d1569-3454-4001-b72e-5dee6d8119c4-O5
I0822 00:42:32.762017 18624 hierarchical.cpp:1454] Recovered 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_ZX1WjK/2GB-c2382977-f0bf-49c9-9408-fca4f4959fbf,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (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_ZX1WjK/2GB-c2382977-f0bf-49c9-9408-fca4f4959fbf,test)]:2048, allocated: {}) on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 from framework d42d1569-3454-40
 01-b72e-5dee6d8119c4-0000
I0822 00:42:32.762185 18624 hierarchical.cpp:1500] Framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 filtered agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 for 5secs
I0822 00:42:32.762507 18626 sched.cpp:960] Rescinded offer d42d1569-3454-4001-b72e-5dee6d8119c4-O5
I0822 00:42:32.762603 18626 sched.cpp:971] Scheduler::offerRescinded took 30989ns
I0822 00:42:32.770553 18624 master.cpp:12615] Sending operation '' (uuid: d5d9bf9b-4aaf-4c96-89a3-51006aefba04) to agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 at slave(1225)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:32.773020 18620 slave.cpp:4352] Ignoring new checkpointed resources and operations identical to the current version
I0822 00:42:32.787672 18615 master.cpp:10432] Sending offers [ d42d1569-3454-4001-b72e-5dee6d8119c4-O6 ] to framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 (default) at scheduler-0abc1be1-835e-4f52-8cef-a6e0fb673272@172.17.0.4:35575
I0822 00:42:32.789331 18615 sched.cpp:934] Scheduler::resourceOffers took 107731ns
I0822 00:42:32.788156 18613 provider.cpp:498] Received APPLY_OPERATION event
I0822 00:42:32.791170 18613 provider.cpp:1329] Received UNRESERVE operation '' (uuid: d5d9bf9b-4aaf-4c96-89a3-51006aefba04)
I0822 00:42:32.791824 18623 http.cpp:1115] HTTP POST for /slave(1225)/api/v1/resource_provider from 172.17.0.4:40454
I0822 00:42:32.793799 18623 slave.cpp:8434] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 74601dd1-b000-4b50-b647-26ed9934d706) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0822 00:42:32.794361 18623 slave.cpp:8887] Updating the state of operation with no ID (uuid: 74601dd1-b000-4b50-b647-26ed9934d706) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0822 00:42:32.794425 18623 slave.cpp:8641] Forwarding status update of operation with no ID (operation_uuid: 74601dd1-b000-4b50-b647-26ed9934d706) for an operator API call
I0822 00:42:32.795768 18618 hierarchical.cpp:1740] Performed allocation for 1 agents in 11.573827ms
I0822 00:42:32.796253 18631 master.cpp:12271] Updating the state of operation '' (uuid: 74601dd1-b000-4b50-b647-26ed9934d706) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0822 00:42:32.799393 18628 slave.cpp:4352] Ignoring new checkpointed resources and operations identical to the current version
I0822 00:42:32.876718 18610 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: a13a7cf5-c97c-42fb-add0-b430c70fad12) for operation UUID d5d9bf9b-4aaf-4c96-89a3-51006aefba04 on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
I0822 00:42:32.876873 18610 status_update_manager_process.hpp:414] Creating operation status update stream d5d9bf9b-4aaf-4c96-89a3-51006aefba04 checkpoint=true
I0822 00:42:32.877820 18610 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: a13a7cf5-c97c-42fb-add0-b430c70fad12) for operation UUID d5d9bf9b-4aaf-4c96-89a3-51006aefba04 on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
I0822 00:42:32.879267 18613 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0822 00:42:32.935043 18610 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: a13a7cf5-c97c-42fb-add0-b430c70fad12) for operation UUID d5d9bf9b-4aaf-4c96-89a3-51006aefba04 on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
I0822 00:42:32.936280 18610 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: f4365977-c3f4-4564-b94c-4c3cf5fef091) for stream 74601dd1-b000-4b50-b647-26ed9934d706
I0822 00:42:32.936372 18610 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: f4365977-c3f4-4564-b94c-4c3cf5fef091) for operation UUID 74601dd1-b000-4b50-b647-26ed9934d706 on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
I0822 00:42:32.938063 18615 http_connection.hpp:131] Sending 2 call to http://172.17.0.4:35575/slave(1225)/api/v1/resource_provider
I0822 00:42:32.940727 18630 process.cpp:3671] Handling HTTP event for process 'slave(1225)' with path: '/slave(1225)/api/v1/resource_provider'
I0822 00:42:32.979796 18618 http.cpp:1115] HTTP POST for /slave(1225)/api/v1/resource_provider from 172.17.0.4:40454
I0822 00:42:32.981389 18620 slave.cpp:8434] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: d5d9bf9b-4aaf-4c96-89a3-51006aefba04) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0822 00:42:32.981731 18620 slave.cpp:8887] Updating the state of operation with no ID (uuid: d5d9bf9b-4aaf-4c96-89a3-51006aefba04) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0822 00:42:32.982254 18620 slave.cpp:8641] Forwarding status update of operation with no ID (operation_uuid: d5d9bf9b-4aaf-4c96-89a3-51006aefba04) for an operator API call
I0822 00:42:32.983167 18620 master.cpp:12271] Updating the state of operation '' (uuid: d5d9bf9b-4aaf-4c96-89a3-51006aefba04) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0822 00:42:32.984267 18621 slave.cpp:4352] Ignoring new checkpointed resources and operations identical to the current version
I0822 00:42:32.987406 18626 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event
I0822 00:42:33.001761 18610 status_update_manager_process.hpp:490] Cleaning up operation status update stream 74601dd1-b000-4b50-b647-26ed9934d706
I0822 00:42:33.002898 18610 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: a13a7cf5-c97c-42fb-add0-b430c70fad12) for stream d5d9bf9b-4aaf-4c96-89a3-51006aefba04
I0822 00:42:33.003089 18610 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: a13a7cf5-c97c-42fb-add0-b430c70fad12) for operation UUID d5d9bf9b-4aaf-4c96-89a3-51006aefba04 on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
I0822 00:42:33.085558 18610 status_update_manager_process.hpp:490] Cleaning up operation status update stream d5d9bf9b-4aaf-4c96-89a3-51006aefba04
I0822 00:42:33.146368 18622 master.cpp:1412] Framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 (default) at scheduler-0abc1be1-835e-4f52-8cef-a6e0fb673272@172.17.0.4:35575 disconnected
I0822 00:42:33.146463 18622 master.cpp:3362] Deactivating framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 (default) at scheduler-0abc1be1-835e-4f52-8cef-a6e0fb673272@172.17.0.4:35575
I0822 00:42:33.147482 18624 hierarchical.cpp:707] Deactivated framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000
I0822 00:42:33.147966 18607 slave.cpp:924] Agent terminating
I0822 00:42:33.148317 18622 master.cpp:12724] Removing offer d42d1569-3454-4001-b72e-5dee6d8119c4-O6
I0822 00:42:33.148411 18622 master.cpp:3339] Disconnecting framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 (default) at scheduler-0abc1be1-835e-4f52-8cef-a6e0fb673272@172.17.0.4:35575
I0822 00:42:33.148488 18622 master.cpp:1427] Giving framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 (default) at scheduler-0abc1be1-835e-4f52-8cef-a6e0fb673272@172.17.0.4:35575 0ns to failover
I0822 00:42:33.149451 18607 manager.cpp:163] Terminating resource provider 2acdbcf4-880f-4035-9068-d76c90f7379f
I0822 00:42:33.149520 18624 hierarchical.cpp:1454] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_ZX1WjK/2GB-c2382977-f0bf-49c9-9408-fca4f4959fbf,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024; ports(allocated: storage/default-role):[31000-32000] (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_ZX1WjK/2GB-c2382977-f0bf-49c9-9408-fca4f4959fbf,test)]:2048, allocated: {}) on agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 from framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000
I0822 00:42:33.150064 18615 master.cpp:1297] Agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 at slave(1225)@172.17.0.4:35575 (8c6ce722e607) disconnected
I0822 00:42:33.150179 18615 master.cpp:3399] Disconnecting agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 at slave(1225)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:33.150360 18615 master.cpp:3418] Deactivating agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 at slave(1225)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:33.150693 18615 master.cpp:10224] Framework failover timeout, removing framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 (default) at scheduler-0abc1be1-835e-4f52-8cef-a6e0fb673272@172.17.0.4:35575
I0822 00:42:33.150876 18619 hierarchical.cpp:1035] Agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0 deactivated
E0822 00:42:33.151741 18631 http_connection.hpp:452] End-Of-File received
I0822 00:42:33.151993 18615 master.cpp:11223] Removing framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000 (default) at scheduler-0abc1be1-835e-4f52-8cef-a6e0fb673272@172.17.0.4:35575
I0822 00:42:33.152416 18631 http_connection.hpp:217] Re-detecting endpoint
I0822 00:42:33.153069 18612 hierarchical.cpp:1664] Allocation paused
I0822 00:42:33.154150 18626 provider.cpp:488] Disconnected from resource provider manager
I0822 00:42:33.154402 18608 status_update_manager_process.hpp:379] Pausing operation status update manager
I0822 00:42:33.154819 18612 hierarchical.cpp:649] Removed framework d42d1569-3454-4001-b72e-5dee6d8119c4-0000
I0822 00:42:33.155138 18612 hierarchical.cpp:1674] Allocation resumed
I0822 00:42:33.155416 18631 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0822 00:42:33.155613 18631 http_connection.hpp:227] New endpoint detected at http://172.17.0.4:35575/slave(1225)/api/v1/resource_provider
I0822 00:42:33.155953 18631 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0822 00:42:33.183784 18621 containerizer.cpp:2616] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0822 00:42:33.183998 18621 containerizer.cpp:3319] 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.006513024secs
I0822 00:42:33.184733 18621 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:33.197999 18608 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.4:35575/slave(1225)/api/v1/resource_provider
I0822 00:42:33.198350 18626 hierarchical.cpp:1740] Performed allocation for 1 agents in 316725ns
I0822 00:42:33.198931 18624 provider.cpp:476] Connected to resource provider manager
I0822 00:42:33.199925 18624 http_connection.hpp:131] Sending 1 call to http://172.17.0.4:35575/slave(1225)/api/v1/resource_provider
I0822 00:42:33.203409 18632 process.cpp:2781] Returning '404 Not Found' for '/slave(1225)/api/v1/resource_provider'
E0822 00:42:33.205896 18613 provider.cpp:719] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0822 00:42:33.253381 18618 hierarchical.cpp:1740] Performed allocation for 1 agents in 323556ns
I0822 00:42:33.301558 18627 containerizer.cpp:3157] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0822 00:42:33.307147 18612 hierarchical.cpp:1740] Performed allocation for 1 agents in 323504ns
I0822 00:42:33.307735 18615 provisioner.cpp:612] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:33.312937 18610 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'
I0822 00:42:33.313230 18610 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-uHnPKo/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:33.313781 18610 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:33.359035 18632 process.cpp:2781] Returning '404 Not Found' for '/slave(1225)/api/v1'
I0822 00:42:33.423689 18607 master.cpp:1137] Master terminating
I0822 00:42:33.425899 18618 hierarchical.cpp:1011] Removed all filters for agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
I0822 00:42:33.425936 18618 hierarchical.cpp:886] Removed agent d42d1569-3454-4001-b72e-5dee6d8119c4-S0
[       OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (3034 ms)
[ RUN      ] CSIVersion/StorageLocalResourceProviderTest.Update/v0
I0822 00:42:33.478034 18607 cluster.cpp:177] Creating default 'local' authorizer
I0822 00:42:33.486781 18623 master.cpp:440] Master 04753426-f05c-465a-af9d-d6f9adb4d1de (8c6ce722e607) started on 172.17.0.4:35575
I0822 00:42:33.486831 18623 master.cpp:443] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/trE4Gc/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca
 table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/mesos/mesos-1.9.0/_inst/share/mesos/webui" --work_dir="/tmp/trE4Gc/master" --zk_session_timeout="10secs"
I0822 00:42:33.487833 18623 master.cpp:492] Master only allowing authenticated frameworks to register
I0822 00:42:33.487888 18623 master.cpp:498] Master only allowing authenticated agents to register
I0822 00:42:33.487907 18623 master.cpp:504] Master only allowing authenticated HTTP frameworks to register
I0822 00:42:33.487957 18623 credentials.hpp:37] Loading credentials for authentication from '/tmp/trE4Gc/credentials'
I0822 00:42:33.488689 18623 master.cpp:548] Using default 'crammd5' authenticator
I0822 00:42:33.489238 18623 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0822 00:42:33.489805 18623 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0822 00:42:33.490422 18623 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0822 00:42:33.490859 18623 master.cpp:629] Authorization enabled
I0822 00:42:33.492683 18612 whitelist_watcher.cpp:77] No whitelist given
I0822 00:42:33.492777 18611 hierarchical.cpp:473] Initialized hierarchical allocator process
I0822 00:42:33.496696 18623 master.cpp:2170] Elected as the leading master!
I0822 00:42:33.496743 18623 master.cpp:1666] Recovering from registrar
I0822 00:42:33.508765 18618 registrar.cpp:339] Recovering registrar
I0822 00:42:33.510407 18608 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0822 00:42:33.510604 18608 registrar.cpp:487] Applied 1 operations in 63660ns; attempting to update the registry
I0822 00:42:33.511911 18618 registrar.cpp:544] Successfully updated the registry in 0ns
I0822 00:42:33.512090 18618 registrar.cpp:416] Successfully recovered registrar
I0822 00:42:33.512735 18631 master.cpp:1819] Recovered 0 agents from the registry (143B); allowing 10mins for agents to reregister
I0822 00:42:33.512899 18631 hierarchical.cpp:512] Skipping recovery of hierarchical allocator: nothing to recover
W0822 00:42:33.523360 18607 process.cpp:2877] Attempted to spawn already running process files@172.17.0.4:35575
I0822 00:42:33.525794 18607 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0822 00:42:33.526960 18607 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0822 00:42:33.527021 18607 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0822 00:42:33.527297 18607 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0822 00:42:33.527370 18607 provisioner.cpp:300] Using default backend 'copy'
I0822 00:42:33.531262 18607 cluster.cpp:518] Creating default 'local' authorizer
I0822 00:42:33.536707 18626 slave.cpp:267] Mesos agent started on (1226)@172.17.0.4:35575
I0822 00:42:33.536752 18626 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/trE4Gc/YsBNWR/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/trE4Gc/YsBNWR/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/trE4Gc/YsBNWR/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/trE4Gc/YsBNWR/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/trE4Gc/YsBNWR/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/trE4Gc/YsBNWR/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.9.0/_
 build/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/trE4Gc/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_hC6C6W" --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_StorageLocalResourceProviderTest_Update_v0_u3Ftg2" --zk_session
 _timeout="10secs"
I0822 00:42:33.537829 18626 credentials.hpp:86] Loading credential for authentication from '/tmp/trE4Gc/YsBNWR/credential'
I0822 00:42:33.538192 18626 slave.cpp:300] Agent using credential for: test-principal
I0822 00:42:33.538225 18626 credentials.hpp:37] Loading credentials for authentication from '/tmp/trE4Gc/YsBNWR/http_credentials'
I0822 00:42:33.538573 18626 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0822 00:42:33.539243 18626 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0822 00:42:33.541749 18626 slave.cpp:615] 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"}]
I0822 00:42:33.542090 18626 slave.cpp:623] Agent attributes: [  ]
I0822 00:42:33.542116 18626 slave.cpp:632] Agent hostname: 8c6ce722e607
I0822 00:42:33.544385 18624 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0822 00:42:33.546586 18611 task_status_update_manager.cpp:181] Pausing sending task status updates
I0822 00:42:33.546684 18611 status_update_manager_process.hpp:379] Pausing operation status update manager
I0822 00:42:33.548238 18611 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_u3Ftg2/meta'
I0822 00:42:33.548748 18621 slave.cpp:7461] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_u3Ftg2/meta', beginning agent recovery
I0822 00:42:33.549624 18621 task_status_update_manager.cpp:207] Recovering task status update manager
I0822 00:42:33.550415 18616 containerizer.cpp:821] Recovering Mesos containers
I0822 00:42:33.551118 18616 containerizer.cpp:1157] Recovering isolators
I0822 00:42:33.553488 18609 containerizer.cpp:1196] Recovering provisioner
I0822 00:42:33.554678 18608 provisioner.cpp:500] Provisioner recovery complete
I0822 00:42:33.556012 18610 composing.cpp:339] Finished recovering all containerizers
I0822 00:42:33.556504 18628 slave.cpp:7925] Recovering executors
I0822 00:42:33.557029 18628 slave.cpp:8078] Finished recovery
I0822 00:42:33.559211 18617 task_status_update_manager.cpp:181] Pausing sending task status updates
I0822 00:42:33.559689 18608 status_update_manager_process.hpp:379] Pausing operation status update manager
I0822 00:42:33.560137 18628 slave.cpp:1351] New master detected at master@172.17.0.4:35575
I0822 00:42:33.560710 18628 slave.cpp:1416] Detecting new master
I0822 00:42:33.568783 18619 slave.cpp:1443] Authenticating with master master@172.17.0.4:35575
I0822 00:42:33.568970 18619 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I0822 00:42:33.569703 18627 authenticatee.cpp:121] Creating new client SASL connection
I0822 00:42:33.570264 18627 master.cpp:10617] Authenticating slave(1226)@172.17.0.4:35575
I0822 00:42:33.570569 18627 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2086)@172.17.0.4:35575
I0822 00:42:33.570924 18615 authenticator.cpp:98] Creating new server SASL connection
I0822 00:42:33.571471 18610 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0822 00:42:33.571594 18610 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0822 00:42:33.571888 18615 authenticator.cpp:204] Received SASL authentication start
I0822 00:42:33.572057 18615 authenticator.cpp:326] Authentication requires more steps
I0822 00:42:33.572363 18614 authenticatee.cpp:259] Received SASL authentication step
I0822 00:42:33.572594 18615 authenticator.cpp:232] Received SASL authentication step
I0822 00:42:33.572718 18615 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8c6ce722e607' server FQDN: '8c6ce722e607' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0822 00:42:33.572808 18615 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0822 00:42:33.572923 18615 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0822 00:42:33.573035 18615 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8c6ce722e607' server FQDN: '8c6ce722e607' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0822 00:42:33.573127 18615 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0822 00:42:33.573204 18615 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0822 00:42:33.573284 18615 authenticator.cpp:318] Authentication success
I0822 00:42:33.573488 18631 authenticatee.cpp:299] Authentication success
I0822 00:42:33.574282 18615 master.cpp:10649] Successfully authenticated principal 'test-principal' at slave(1226)@172.17.0.4:35575
I0822 00:42:33.574689 18631 slave.cpp:1543] Successfully authenticated with master master@172.17.0.4:35575
I0822 00:42:33.575522 18631 slave.cpp:1993] Will retry registration in 2.900218ms if necessary
I0822 00:42:33.575865 18609 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2086)@172.17.0.4:35575
I0822 00:42:33.585024 18629 master.cpp:7088] Received register agent message from slave(1226)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:33.585628 18629 master.cpp:4204] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
I0822 00:42:33.587379 18624 master.cpp:7155] Authorized registration of agent at slave(1226)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:33.587522 18624 master.cpp:7267] Registering agent at slave(1226)@172.17.0.4:35575 (8c6ce722e607) with id 04753426-f05c-465a-af9d-d6f9adb4d1de-S0
I0822 00:42:33.588611 18624 registrar.cpp:487] Applied 1 operations in 317215ns; attempting to update the registry
I0822 00:42:33.590148 18613 registrar.cpp:544] Successfully updated the registry in 0ns
I0822 00:42:33.590584 18613 master.cpp:7315] Admitted agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 at slave(1226)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:33.591795 18613 master.cpp:7360] Registered agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 at slave(1226)@172.17.0.4:35575 (8c6ce722e607) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0822 00:42:33.592044 18613 slave.cpp:1576] Registered with master master@172.17.0.4:35575; given agent ID 04753426-f05c-465a-af9d-d6f9adb4d1de-S0
I0822 00:42:33.592219 18614 hierarchical.cpp:853] Added agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 (8c6ce722e607) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0822 00:42:33.592692 18614 hierarchical.cpp:1740] Performed allocation for 1 agents in 213609ns
I0822 00:42:33.592730 18630 task_status_update_manager.cpp:188] Resuming sending task status updates
I0822 00:42:33.592777 18613 slave.cpp:1611] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_u3Ftg2/meta/slaves/04753426-f05c-465a-af9d-d6f9adb4d1de-S0/slave.info'
I0822 00:42:33.592890 18614 status_update_manager_process.hpp:385] Resuming operation status update manager
I0822 00:42:33.594583 18613 slave.cpp:1663] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"BW7Odz/HS7y9e+WDZftqyA=="},"slave_id":{"value":"04753426-f05c-465a-af9d-d6f9adb4d1de-S0"},"update_oversubscribed_resources":false}
I0822 00:42:33.605309 18626 master.cpp:8487] Ignoring update on agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 at slave(1226)@172.17.0.4:35575 (8c6ce722e607) as it reports no changes
I0822 00:42:33.616905 18614 process.cpp:3671] Handling HTTP event for process 'slave(1226)' with path: '/slave(1226)/api/v1'
I0822 00:42:33.619436 18623 http.cpp:1115] HTTP POST for /slave(1226)/api/v1 from 172.17.0.4:40474
I0822 00:42:33.620532 18623 http.cpp:2146] Processing GET_CONTAINERS call
I0822 00:42:33.638438 18608 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:33.652887 18614 process.cpp:3671] Handling HTTP event for process 'slave(1226)' with path: '/slave(1226)/api/v1'
I0822 00:42:33.655129 18621 http.cpp:1115] HTTP POST for /slave(1226)/api/v1 from 172.17.0.4:40476
I0822 00:42:33.656738 18621 http.cpp:2606] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:33.658668 18609 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_u3Ftg2/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:33.659786 18611 containerizer.cpp:1392] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:33.660655 18611 containerizer.cpp:3319] 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 0ns
I0822 00:42:33.661787 18611 containerizer.cpp:1570] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hC6C6W/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0822 00:42:33.661849 18611 containerizer.cpp:3319] 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 0ns
I0822 00:42:33.667778 18619 containerizer.cpp:2096] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_MGwmq7","--available_capacity=0B","--volumes=","--forward=unix:///tmp/trE4Gc/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_u3Ftg2/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-HNx06x/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_u3Ftg2/containers/org-apache-mesos-rp-local-s
 torage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="77" --pipe_write="80" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_hC6C6W/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0822 00:42:33.684952 18619 launcher.cpp:145] Forked child with pid '32761' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:33.686311 18619 containerizer.cpp:3319] 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 0ns
I0822 00:42:33.688555 18625 containerizer.cpp:3319] 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 0ns
I0822 00:42:33.689278 18625 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_u3Ftg2/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:33.691130 18618 containerizer.cpp:3319] 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 0ns
I0822 00:42:33.704942 18628 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'
I0822 00:42:33.705241 18628 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-HNx06x/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:33.781363 18623 hierarchical.cpp:1740] Performed allocation for 1 agents in 303185ns
I0822 00:42:33.837369 18627 hierarchical.cpp:1740] Performed allocation for 1 agents in 305194ns
I0822 00:42:33.889488 18611 hierarchical.cpp:1740] Performed allocation for 1 agents in 303630ns
I0822 00:42:33.941602 18610 hierarchical.cpp:1740] Performed allocation for 1 agents in 270509ns
I0822 00:42:33.994369 18622 hierarchical.cpp:1740] Performed allocation for 1 agents in 271671ns
I0822 00:42:34.053375 18620 hierarchical.cpp:1740] Performed allocation for 1 agents in 309287ns
I0822 00:42:34.113463 18617 hierarchical.cpp:1740] Performed allocation for 1 agents in 302440ns
I0822 00:42:34.165441 18630 hierarchical.cpp:1740] Performed allocation for 1 agents in 298787ns
I0822 00:42:34.193172 18614 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-HNx06x/endpoint.sock' with CSI v1
I0822 00:42:34.208036 18631 service_manager.cpp:532] Probing endpoint 'unix:///tmp/mesos-csi-HNx06x/endpoint.sock' with CSI v0
I0822 00:42:34.211060 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/Probe call
I0822 00:42:34.218076 18621 hierarchical.cpp:1740] Performed allocation for 1 agents in 296031ns
I0822 00:42:34.219445 18627 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:34.223345 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginCapabilities call
I0822 00:42:34.224845 18626 process.cpp:3671] Handling HTTP event for process 'slave(1226)' with path: '/slave(1226)/api/v1'
I0822 00:42:34.226617 18626 http.cpp:1115] HTTP POST for /slave(1226)/api/v1 from 172.17.0.4:40478
I0822 00:42:34.227324 18626 http.cpp:2824] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:34.241391 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call
I0822 00:42:34.241816 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Identity/GetPluginInfo call
I0822 00:42:34.259570 18613 v0_volume_manager.cpp:628] NODE_SERVICE loaded: {}
I0822 00:42:34.260291 18613 v0_volume_manager.cpp:628] CONTROLLER_SERVICE loaded: {}
I0822 00:42:34.264108 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ControllerGetCapabilities call
I0822 00:42:34.272097 18630 hierarchical.cpp:1740] Performed allocation for 1 agents in 297400ns
I0822 00:42:34.274868 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetCapabilities call
I0822 00:42:34.293256 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Node/NodeGetId call
I0822 00:42:34.314869 18611 provider.cpp:676] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0822 00:42:34.315424 18611 status_update_manager_process.hpp:379] Pausing operation status update manager
I0822 00:42:34.315721 18611 http_connection.hpp:227] New endpoint detected at http://172.17.0.4:35575/slave(1226)/api/v1/resource_provider
I0822 00:42:34.321369 18617 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.4:35575/slave(1226)/api/v1/resource_provider
I0822 00:42:34.322332 18614 provider.cpp:476] Connected to resource provider manager
I0822 00:42:34.323734 18614 http_connection.hpp:131] Sending 1 call to http://172.17.0.4:35575/slave(1226)/api/v1/resource_provider
I0822 00:42:34.329499 18624 hierarchical.cpp:1740] Performed allocation for 1 agents in 281334ns
I0822 00:42:34.331076 18627 process.cpp:3671] Handling HTTP event for process 'slave(1226)' with path: '/slave(1226)/api/v1/resource_provider'
I0822 00:42:34.333752 18621 http.cpp:1115] HTTP POST for /slave(1226)/api/v1/resource_provider from 172.17.0.4:40482
I0822 00:42:34.334772 18616 manager.cpp:807] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_MGwmq7","--available_capacity=0B","--volumes=","--forward=unix:///tmp/trE4Gc/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/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"}
I0822 00:42:34.385388 18619 hierarchical.cpp:1740] Performed allocation for 1 agents in 269772ns
I0822 00:42:34.437227 18626 hierarchical.cpp:1740] Performed allocation for 1 agents in 306262ns
I0822 00:42:34.488852 18614 hierarchical.cpp:1740] Performed allocation for 1 agents in 316772ns
I0822 00:42:34.540974 18617 hierarchical.cpp:1740] Performed allocation for 1 agents in 299493ns
I0822 00:42:34.593396 18608 hierarchical.cpp:1740] Performed allocation for 1 agents in 307151ns
I0822 00:42:34.645730 18623 hierarchical.cpp:1740] Performed allocation for 1 agents in 302078ns
I0822 00:42:34.697778 18611 hierarchical.cpp:1740] Performed allocation for 1 agents in 304475ns
I0822 00:42:34.749912 18631 hierarchical.cpp:1740] Performed allocation for 1 agents in 297315ns
I0822 00:42:34.765902 18618 slave.cpp:8434] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"8bb459e0-c9fc-460e-9ceb-cc94b5eb442d"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v0","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v0_MGwmq7","--available_capacity=0B","--volumes=","--forward=unix:///tmp/trE4Gc/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/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"}'
I0822 00:42:34.769431 18612 provider.cpp:498] Received SUBSCRIBED event
I0822 00:42:34.769510 18612 provider.cpp:1287] Subscribed with ID 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d
I0822 00:42:34.770812 18628 status_update_manager_process.hpp:314] Recovering operation status update manager
I0822 00:42:34.802253 18614 hierarchical.cpp:1740] Performed allocation for 1 agents in 294806ns
I0822 00:42:34.820953 18628 provider.cpp:788] Reconciling storage pools and volumes
I0822 00:42:34.825076 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call
I0822 00:42:34.829610 18629 provider.cpp:2195] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0
I0822 00:42:34.830621 18629 provider.cpp:746] Resource provider 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d is in READY state
I0822 00:42:34.831030 18610 http_connection.hpp:131] Sending 3 call to http://172.17.0.4:35575/slave(1226)/api/v1/resource_provider
I0822 00:42:34.831928 18621 status_update_manager_process.hpp:385] Resuming operation status update manager
I0822 00:42:34.833182 18625 provider.cpp:1213] Updating profiles { test } for resource provider 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d
I0822 00:42:34.833811 18612 process.cpp:3671] Handling HTTP event for process 'slave(1226)' with path: '/slave(1226)/api/v1/resource_provider'
I0822 00:42:34.835279 18626 provider.cpp:788] Reconciling storage pools and volumes
I0822 00:42:34.836359 18627 http.cpp:1115] HTTP POST for /slave(1226)/api/v1/resource_provider from 172.17.0.4:40480
I0822 00:42:34.837010 18627 manager.cpp:1039] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d
I0822 00:42:34.837347 18609 slave.cpp:8434] Handling resource provider message 'UPDATE_STATE: 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d {}'
I0822 00:42:34.837779 18609 slave.cpp:8554] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0822 00:42:34.838814 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call
I0822 00:42:34.840734 18611 hierarchical.cpp:989] Grew agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 by {} (total), {  } (used)
I0822 00:42:34.841442 18611 hierarchical.cpp:946] Agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 (8c6ce722e607) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0822 00:42:34.843926 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call
I0822 00:42:34.853505 18627 hierarchical.cpp:1740] Performed allocation for 1 agents in 280793ns
I0822 00:42:34.860190 18626 provider.cpp:806] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001' to the total resources
I0822 00:42:34.908905 18626 provider.cpp:2195] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001' and 0 operations to agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0
I0822 00:42:34.911088 18611 http_connection.hpp:131] Sending 3 call to http://172.17.0.4:35575/slave(1226)/api/v1/resource_provider
I0822 00:42:34.916735 18623 process.cpp:3671] Handling HTTP event for process 'slave(1226)' with path: '/slave(1226)/api/v1/resource_provider'
I0822 00:42:34.929240 18612 hierarchical.cpp:1740] Performed allocation for 1 agents in 245211ns
I0822 00:42:34.936982 18627 provider.cpp:788] Reconciling storage pools and volumes
I0822 00:42:34.942374 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/ListVolumes call
I0822 00:42:34.943023 32765 test_csi_plugin.cpp:1915] Forwarding /csi.v0.Controller/GetCapacity call
I0822 00:42:34.961431 18628 hierarchical.cpp:1740] Performed allocation for 1 agents in 281465ns
I0822 00:42:34.963732 18616 provider.cpp:806] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:0.001' to the total resources
I0822 00:42:34.965077 18615 http.cpp:1115] HTTP POST for /slave(1226)/api/v1/resource_provider from 172.17.0.4:40480
I0822 00:42:34.965931 18615 manager.cpp:1039] Received UPDATE_STATE call with resources '[{"disk":{"source":{"id":"volume1","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"8bb459e0-c9fc-460e-9ceb-cc94b5eb442d"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":0.0009765625},"type":"SCALAR"}]' and 0 operations from resource provider 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d
I0822 00:42:34.966711 18615 slave.cpp:8434] Handling resource provider message 'UPDATE_STATE: 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001'
I0822 00:42:34.966883 18615 slave.cpp:8554] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001
I0822 00:42:34.970979 18630 hierarchical.cpp:946] Agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 (8c6ce722e607) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001
I0822 00:42:34.972918 18630 hierarchical.cpp:1740] Performed allocation for 1 agents in 254914ns
I0822 00:42:35.016325 18616 provider.cpp:2195] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:0.001' and 0 operations to agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0
I0822 00:42:35.018144 18616 http_connection.hpp:131] Sending 3 call to http://172.17.0.4:35575/slave(1226)/api/v1/resource_provider
I0822 00:42:35.021533 18623 process.cpp:3671] Handling HTTP event for process 'slave(1226)' with path: '/slave(1226)/api/v1/resource_provider'
I0822 00:42:35.062736 18617 http.cpp:1115] HTTP POST for /slave(1226)/api/v1/resource_provider from 172.17.0.4:40480
I0822 00:42:35.064193 18617 manager.cpp:1039] Received UPDATE_STATE call with resources '[{"disk":{"source":{"id":"volume1","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"8bb459e0-c9fc-460e-9ceb-cc94b5eb442d"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":0.0009765625},"type":"SCALAR"},{"disk":{"source":{"profile":"test","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"8bb459e0-c9fc-460e-9ceb-cc94b5eb442d"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":0.0009765625},"type":"SCALAR"}]' and 0 operations from resource provider 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d
I0822 00:42:35.065665 18608 slave.cpp:8434] Handling resource provider message 'UPDATE_STATE: 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:0.001'
I0822 00:42:35.066391 18608 slave.cpp:8554] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:0.001
I0822 00:42:35.072177 18608 hierarchical.cpp:946] Agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 (8c6ce722e607) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:0.001
I0822 00:42:35.073206 18608 hierarchical.cpp:1740] Performed allocation for 1 agents in 276458ns
../../src/tests/storage_local_resource_provider_tests.cpp:6887: Failure
Failed to wait 15secs for getCapacity3
I0822 00:42:50.028681 18619 slave.cpp:924] Agent terminating
I0822 00:42:50.029577 18619 manager.cpp:163] Terminating resource provider 8bb459e0-c9fc-460e-9ceb-cc94b5eb442d
I0822 00:42:50.048796 18619 master.cpp:1297] Agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 at slave(1226)@172.17.0.4:35575 (8c6ce722e607) disconnected
E0822 00:42:50.049484 18626 http_connection.hpp:452] End-Of-File received
I0822 00:42:50.049785 18619 master.cpp:3399] Disconnecting agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 at slave(1226)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:50.049899 18619 master.cpp:3418] Deactivating agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 at slave(1226)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:50.050099 18624 hierarchical.cpp:1035] Agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0 deactivated
I0822 00:42:50.050349 18626 http_connection.hpp:217] Re-detecting endpoint
I0822 00:42:50.051143 18608 provider.cpp:488] Disconnected from resource provider manager
I0822 00:42:50.051379 18608 status_update_manager_process.hpp:379] Pausing operation status update manager
I0822 00:42:50.068876 18626 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0822 00:42:50.069005 18626 http_connection.hpp:227] New endpoint detected at http://172.17.0.4:35575/slave(1226)/api/v1/resource_provider
I0822 00:42:50.069269 18626 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0822 00:42:50.077172 18620 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.4:35575/slave(1226)/api/v1/resource_provider
I0822 00:42:50.078003 18620 provider.cpp:476] Connected to resource provider manager
I0822 00:42:50.078948 18622 http_connection.hpp:131] Sending 1 call to http://172.17.0.4:35575/slave(1226)/api/v1/resource_provider
I0822 00:42:50.081020 18632 process.cpp:2781] Returning '404 Not Found' for '/slave(1226)/api/v1/resource_provider'
I0822 00:42:50.081328 18627 containerizer.cpp:2616] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0822 00:42:50.081480 18627 containerizer.cpp:3319] 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 46.611260928secs
I0822 00:42:50.082056 18627 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:50.083401 18608 hierarchical.cpp:1740] Performed allocation for 1 agents in 303363ns
E0822 00:42:50.084033 18630 provider.cpp:719] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Cannot process 'SUBSCRIBE' call as the driver is in state SUBSCRIBING
I0822 00:42:50.084610 18623 provider.cpp:788] Reconciling storage pools and volumes
E0822 00:42:50.093519 18630 provider.cpp:719] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0822 00:42:50.137543 18613 hierarchical.cpp:1740] Performed allocation for 1 agents in 264380ns
I0822 00:42:50.186604 18621 containerizer.cpp:3157] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0822 00:42:50.189277 18626 provisioner.cpp:612] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:50.191620 18622 hierarchical.cpp:1740] Performed allocation for 1 agents in 314509ns
I0822 00:42:50.196257 18618 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'
I0822 00:42:50.196475 18628 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-HNx06x/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:50.197368 18618 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:50.201189 18632 process.cpp:2781] Returning '404 Not Found' for '/slave(1226)/api/v1'
E0822 00:42:50.206473 18615 container_daemon.cpp:150] Failed to launch container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE': Failed to launch container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE': Unexpected response '404 Not Found' (404 Not Found.)
E0822 00:42:50.207031 18615 service_manager.cpp:751] Container daemon for 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' failed: Failed to launch container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE': Unexpected response '404 Not Found' (404 Not Found.)
I0822 00:42:50.278010 18607 master.cpp:1137] Master terminating
I0822 00:42:50.279713 18619 hierarchical.cpp:1011] Removed all filters for agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0
I0822 00:42:50.280123 18619 hierarchical.cpp:886] Removed agent 04753426-f05c-465a-af9d-d6f9adb4d1de-S0
[  FAILED  ] CSIVersion/StorageLocalResourceProviderTest.Update/v0, where GetParam() = "v0" (16836 ms)
[ RUN      ] CSIVersion/StorageLocalResourceProviderTest.Update/v1
I0822 00:42:50.325872 18607 cluster.cpp:177] Creating default 'local' authorizer
I0822 00:42:50.340708 18621 master.cpp:440] Master 35a28557-26d8-43de-b449-a10bb9d11f1f (8c6ce722e607) started on 172.17.0.4:35575
I0822 00:42:50.342219 18621 master.cpp:443] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/MAnXRF/credentials" --filter_gpu_resources="true" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_alloca
 table_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/mesos/mesos-1.9.0/_inst/share/mesos/webui" --work_dir="/tmp/MAnXRF/master" --zk_session_timeout="10secs"
I0822 00:42:50.344092 18621 master.cpp:492] Master only allowing authenticated frameworks to register
I0822 00:42:50.345268 18621 master.cpp:498] Master only allowing authenticated agents to register
I0822 00:42:50.346276 18621 master.cpp:504] Master only allowing authenticated HTTP frameworks to register
I0822 00:42:50.347262 18621 credentials.hpp:37] Loading credentials for authentication from '/tmp/MAnXRF/credentials'
I0822 00:42:50.348775 18621 master.cpp:548] Using default 'crammd5' authenticator
I0822 00:42:50.350179 18621 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0822 00:42:50.351572 18621 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0822 00:42:50.352792 18621 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0822 00:42:50.354022 18621 master.cpp:629] Authorization enabled
I0822 00:42:50.355612 18629 whitelist_watcher.cpp:77] No whitelist given
I0822 00:42:50.355964 18627 hierarchical.cpp:473] Initialized hierarchical allocator process
I0822 00:42:50.365144 18625 master.cpp:2170] Elected as the leading master!
I0822 00:42:50.365221 18625 master.cpp:1666] Recovering from registrar
I0822 00:42:50.365584 18626 registrar.cpp:339] Recovering registrar
I0822 00:42:50.368034 18626 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0822 00:42:50.368670 18626 registrar.cpp:487] Applied 1 operations in 68367ns; attempting to update the registry
I0822 00:42:50.393265 18626 registrar.cpp:544] Successfully updated the registry in 0ns
I0822 00:42:50.394127 18626 registrar.cpp:416] Successfully recovered registrar
I0822 00:42:50.395220 18623 master.cpp:1819] Recovered 0 agents from the registry (143B); allowing 10mins for agents to reregister
I0822 00:42:50.395738 18623 hierarchical.cpp:512] Skipping recovery of hierarchical allocator: nothing to recover
W0822 00:42:50.408218 18607 process.cpp:2877] Attempted to spawn already running process files@172.17.0.4:35575
I0822 00:42:50.410861 18607 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0822 00:42:50.412165 18607 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0822 00:42:50.412523 18607 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0822 00:42:50.413038 18607 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0822 00:42:50.413398 18607 provisioner.cpp:300] Using default backend 'copy'
I0822 00:42:50.417250 18607 cluster.cpp:518] Creating default 'local' authorizer
I0822 00:42:50.423926 18616 slave.cpp:267] Mesos agent started on (1227)@172.17.0.4:35575
I0822 00:42:50.423980 18616 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/MAnXRF/thlWtP/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/MAnXRF/thlWtP/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/MAnXRF/thlWtP/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/MAnXRF/thlWtP/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/MAnXRF/thlWtP/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/MAnXRF/thlWtP/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/mesos/mesos-1.9.0/_
 build/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/MAnXRF/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_R4dU1h" --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_StorageLocalResourceProviderTest_Update_v1_ThcTzK" --zk_session
 _timeout="10secs"
I0822 00:42:50.424796 18616 credentials.hpp:86] Loading credential for authentication from '/tmp/MAnXRF/thlWtP/credential'
I0822 00:42:50.425148 18616 slave.cpp:300] Agent using credential for: test-principal
I0822 00:42:50.425182 18616 credentials.hpp:37] Loading credentials for authentication from '/tmp/MAnXRF/thlWtP/http_credentials'
I0822 00:42:50.425537 18616 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0822 00:42:50.426185 18616 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0822 00:42:50.428421 18622 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0822 00:42:50.430773 18616 slave.cpp:615] 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"}]
I0822 00:42:50.431537 18616 slave.cpp:623] Agent attributes: [  ]
I0822 00:42:50.431762 18616 slave.cpp:632] Agent hostname: 8c6ce722e607
I0822 00:42:50.432780 18624 task_status_update_manager.cpp:181] Pausing sending task status updates
I0822 00:42:50.432860 18624 status_update_manager_process.hpp:379] Pausing operation status update manager
I0822 00:42:50.434914 18612 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ThcTzK/meta'
I0822 00:42:50.435237 18625 slave.cpp:7461] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ThcTzK/meta', beginning agent recovery
I0822 00:42:50.436103 18625 task_status_update_manager.cpp:207] Recovering task status update manager
I0822 00:42:50.437041 18625 containerizer.cpp:821] Recovering Mesos containers
I0822 00:42:50.437531 18625 containerizer.cpp:1157] Recovering isolators
I0822 00:42:50.449457 18629 containerizer.cpp:1196] Recovering provisioner
I0822 00:42:50.450879 18629 provisioner.cpp:500] Provisioner recovery complete
I0822 00:42:50.452486 18629 composing.cpp:339] Finished recovering all containerizers
I0822 00:42:50.453445 18619 slave.cpp:7925] Recovering executors
I0822 00:42:50.454061 18619 slave.cpp:8078] Finished recovery
I0822 00:42:50.460904 18626 slave.cpp:1351] New master detected at master@172.17.0.4:35575
I0822 00:42:50.461562 18626 slave.cpp:1416] Detecting new master
I0822 00:42:50.462076 18626 status_update_manager_process.hpp:379] Pausing operation status update manager
I0822 00:42:50.461104 18628 task_status_update_manager.cpp:181] Pausing sending task status updates
I0822 00:42:50.472793 18631 slave.cpp:1443] Authenticating with master master@172.17.0.4:35575
I0822 00:42:50.473354 18631 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I0822 00:42:50.474527 18631 authenticatee.cpp:121] Creating new client SASL connection
I0822 00:42:50.475378 18631 master.cpp:10617] Authenticating slave(1227)@172.17.0.4:35575
I0822 00:42:50.475953 18631 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2087)@172.17.0.4:35575
I0822 00:42:50.476948 18631 authenticator.cpp:98] Creating new server SASL connection
I0822 00:42:50.477625 18631 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0822 00:42:50.477960 18631 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0822 00:42:50.478408 18631 authenticator.cpp:204] Received SASL authentication start
I0822 00:42:50.478785 18631 authenticator.cpp:326] Authentication requires more steps
I0822 00:42:50.479326 18623 authenticatee.cpp:259] Received SASL authentication step
I0822 00:42:50.479575 18623 authenticator.cpp:232] Received SASL authentication step
I0822 00:42:50.479626 18623 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8c6ce722e607' server FQDN: '8c6ce722e607' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0822 00:42:50.479657 18623 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0822 00:42:50.479727 18623 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0822 00:42:50.479773 18623 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '8c6ce722e607' server FQDN: '8c6ce722e607' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0822 00:42:50.479797 18623 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0822 00:42:50.479815 18623 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0822 00:42:50.479842 18623 authenticator.cpp:318] Authentication success
I0822 00:42:50.480218 18623 authenticatee.cpp:299] Authentication success
I0822 00:42:50.481704 18623 slave.cpp:1543] Successfully authenticated with master master@172.17.0.4:35575
I0822 00:42:50.482635 18623 slave.cpp:1993] Will retry registration in 15.701254ms if necessary
I0822 00:42:50.480603 18610 master.cpp:10649] Successfully authenticated principal 'test-principal' at slave(1227)@172.17.0.4:35575
I0822 00:42:50.483749 18610 master.cpp:7088] Received register agent message from slave(1227)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:50.484539 18610 master.cpp:4204] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
I0822 00:42:50.486515 18610 master.cpp:7155] Authorized registration of agent at slave(1227)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:50.486961 18610 master.cpp:7267] Registering agent at slave(1227)@172.17.0.4:35575 (8c6ce722e607) with id 35a28557-26d8-43de-b449-a10bb9d11f1f-S0
I0822 00:42:50.488334 18610 registrar.cpp:487] Applied 1 operations in 339816ns; attempting to update the registry
I0822 00:42:50.480718 18620 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2087)@172.17.0.4:35575
I0822 00:42:50.489964 18610 registrar.cpp:544] Successfully updated the registry in 0ns
I0822 00:42:50.490556 18610 master.cpp:7315] Admitted agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 at slave(1227)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:50.492023 18610 master.cpp:7360] Registered agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 at slave(1227)@172.17.0.4:35575 (8c6ce722e607) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0822 00:42:50.492174 18624 slave.cpp:1576] Registered with master master@172.17.0.4:35575; given agent ID 35a28557-26d8-43de-b449-a10bb9d11f1f-S0
I0822 00:42:50.492869 18627 task_status_update_manager.cpp:188] Resuming sending task status updates
I0822 00:42:50.493651 18624 slave.cpp:1611] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ThcTzK/meta/slaves/35a28557-26d8-43de-b449-a10bb9d11f1f-S0/slave.info'
I0822 00:42:50.495774 18624 slave.cpp:1663] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"1jDPeabVRjWRMKL7XCTrDA=="},"slave_id":{"value":"35a28557-26d8-43de-b449-a10bb9d11f1f-S0"},"update_oversubscribed_resources":false}
I0822 00:42:50.492671 18623 hierarchical.cpp:853] Added agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 (8c6ce722e607) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0822 00:42:50.497949 18623 hierarchical.cpp:1740] Performed allocation for 1 agents in 265196ns
I0822 00:42:50.496119 18628 status_update_manager_process.hpp:385] Resuming operation status update manager
I0822 00:42:50.499665 18610 master.cpp:8487] Ignoring update on agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 at slave(1227)@172.17.0.4:35575 (8c6ce722e607) as it reports no changes
I0822 00:42:50.517802 18609 process.cpp:3671] Handling HTTP event for process 'slave(1227)' with path: '/slave(1227)/api/v1'
I0822 00:42:50.519672 18618 http.cpp:1115] HTTP POST for /slave(1227)/api/v1 from 172.17.0.4:40528
I0822 00:42:50.520397 18618 http.cpp:2146] Processing GET_CONTAINERS call
I0822 00:42:50.538357 18613 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:50.546986 18631 process.cpp:3671] Handling HTTP event for process 'slave(1227)' with path: '/slave(1227)/api/v1'
I0822 00:42:50.550186 18614 http.cpp:1115] HTTP POST for /slave(1227)/api/v1 from 172.17.0.4:40530
I0822 00:42:50.551559 18614 http.cpp:2606] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:50.553606 18614 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ThcTzK/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:50.554702 18621 containerizer.cpp:1392] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:50.555619 18621 containerizer.cpp:3319] 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 0ns
I0822 00:42:50.557085 18621 containerizer.cpp:1570] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_R4dU1h/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0822 00:42:50.557492 18621 containerizer.cpp:3319] 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 0ns
I0822 00:42:50.563196 18626 containerizer.cpp:2096] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qSbU7c","--available_capacity=0B","--volumes=","--forward=unix:///tmp/MAnXRF/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ThcTzK/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-rdbYd0/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_ThcTzK/containers/org-apache-mesos-rp-local-s
 torage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="79" --pipe_write="80" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_R4dU1h/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0822 00:42:50.582491 18626 launcher.cpp:145] Forked child with pid '32774' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:50.584288 18626 containerizer.cpp:3319] 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 0ns
I0822 00:42:50.587286 18619 containerizer.cpp:3319] 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 0ns
I0822 00:42:50.587728 18628 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_ThcTzK/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:50.589555 18628 containerizer.cpp:3319] 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 0ns
I0822 00:42:50.602576 18625 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'
I0822 00:42:50.602879 18625 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-rdbYd0/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:50.677572 18627 hierarchical.cpp:1740] Performed allocation for 1 agents in 312233ns
I0822 00:42:50.729591 18628 hierarchical.cpp:1740] Performed allocation for 1 agents in 259269ns
I0822 00:42:50.781258 18623 hierarchical.cpp:1740] Performed allocation for 1 agents in 267382ns
I0822 00:42:50.833225 18613 hierarchical.cpp:1740] Performed allocation for 1 agents in 289964ns
I0822 00:42:50.884999 18619 hierarchical.cpp:1740] Performed allocation for 1 agents in 268742ns
I0822 00:42:50.937794 18629 hierarchical.cpp:1740] Performed allocation for 1 agents in 273061ns
I0822 00:42:50.989141 18621 hierarchical.cpp:1740] Performed allocation for 1 agents in 233372ns
I0822 00:42:51.040930 18613 hierarchical.cpp:1740] Performed allocation for 1 agents in 302924ns
I0822 00:42:51.092240 18618 hierarchical.cpp:1740] Performed allocation for 1 agents in 272942ns
I0822 00:42:51.105368 18626 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-rdbYd0/endpoint.sock' with CSI v1
I0822 00:42:51.109958 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call
I0822 00:42:51.118546 18629 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:51.125214 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call
I0822 00:42:51.126518 18608 process.cpp:3671] Handling HTTP event for process 'slave(1227)' with path: '/slave(1227)/api/v1'
I0822 00:42:51.128474 18609 http.cpp:1115] HTTP POST for /slave(1227)/api/v1 from 172.17.0.4:40532
I0822 00:42:51.129714 18609 http.cpp:2824] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:51.141463 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
I0822 00:42:51.142814 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
I0822 00:42:51.143929 18611 hierarchical.cpp:1740] Performed allocation for 1 agents in 277142ns
I0822 00:42:51.146086 18615 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {}
I0822 00:42:51.147454 18625 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {}
I0822 00:42:51.153254 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
I0822 00:42:51.174248 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call
I0822 00:42:51.189203 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call
I0822 00:42:51.196040 18621 hierarchical.cpp:1740] Performed allocation for 1 agents in 269388ns
I0822 00:42:51.197690 18623 provider.cpp:676] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0822 00:42:51.198233 18623 status_update_manager_process.hpp:379] Pausing operation status update manager
I0822 00:42:51.198575 18623 http_connection.hpp:227] New endpoint detected at http://172.17.0.4:35575/slave(1227)/api/v1/resource_provider
I0822 00:42:51.208753 18616 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.4:35575/slave(1227)/api/v1/resource_provider
I0822 00:42:51.237099 18626 provider.cpp:476] Connected to resource provider manager
I0822 00:42:51.238698 18626 http_connection.hpp:131] Sending 1 call to http://172.17.0.4:35575/slave(1227)/api/v1/resource_provider
I0822 00:42:51.242754 18619 process.cpp:3671] Handling HTTP event for process 'slave(1227)' with path: '/slave(1227)/api/v1/resource_provider'
I0822 00:42:51.245615 18619 http.cpp:1115] HTTP POST for /slave(1227)/api/v1/resource_provider from 172.17.0.4:40536
I0822 00:42:51.246992 18630 manager.cpp:807] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qSbU7c","--available_capacity=0B","--volumes=","--forward=unix:///tmp/MAnXRF/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/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"}
I0822 00:42:51.250977 18619 hierarchical.cpp:1740] Performed allocation for 1 agents in 282373ns
I0822 00:42:51.275116 18616 slave.cpp:8434] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"05cc812b-14b8-43b7-95b0-be5f827182d4"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.9.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_qSbU7c","--available_capacity=0B","--volumes=","--forward=unix:///tmp/MAnXRF/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.9.0/_build/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"}'
I0822 00:42:51.283699 18612 provider.cpp:498] Received SUBSCRIBED event
I0822 00:42:51.283762 18612 provider.cpp:1287] Subscribed with ID 05cc812b-14b8-43b7-95b0-be5f827182d4
I0822 00:42:51.285099 18611 status_update_manager_process.hpp:314] Recovering operation status update manager
I0822 00:42:51.305563 18623 hierarchical.cpp:1740] Performed allocation for 1 agents in 259472ns
I0822 00:42:51.332959 18612 provider.cpp:788] Reconciling storage pools and volumes
I0822 00:42:51.336568 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0822 00:42:51.341011 18616 provider.cpp:2195] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0
I0822 00:42:51.341531 18616 provider.cpp:746] Resource provider 05cc812b-14b8-43b7-95b0-be5f827182d4 is in READY state
I0822 00:42:51.342370 18616 http_connection.hpp:131] Sending 3 call to http://172.17.0.4:35575/slave(1227)/api/v1/resource_provider
I0822 00:42:51.342712 18630 status_update_manager_process.hpp:385] Resuming operation status update manager
I0822 00:42:51.343101 18622 provider.cpp:1213] Updating profiles { test } for resource provider 05cc812b-14b8-43b7-95b0-be5f827182d4
I0822 00:42:51.349937 18622 process.cpp:3671] Handling HTTP event for process 'slave(1227)' with path: '/slave(1227)/api/v1/resource_provider'
I0822 00:42:51.350708 18631 provider.cpp:788] Reconciling storage pools and volumes
I0822 00:42:51.352957 18631 http.cpp:1115] HTTP POST for /slave(1227)/api/v1/resource_provider from 172.17.0.4:40534
I0822 00:42:51.356348 18627 manager.cpp:1039] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 05cc812b-14b8-43b7-95b0-be5f827182d4
I0822 00:42:51.356671 18614 slave.cpp:8434] Handling resource provider message 'UPDATE_STATE: 05cc812b-14b8-43b7-95b0-be5f827182d4 {}'
I0822 00:42:51.356801 18614 slave.cpp:8554] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0822 00:42:51.357415 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0822 00:42:51.357964 18614 hierarchical.cpp:1740] Performed allocation for 1 agents in 268388ns
I0822 00:42:51.358206 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
I0822 00:42:51.359596 18620 hierarchical.cpp:989] Grew agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 by {} (total), {  } (used)
I0822 00:42:51.360595 18611 hierarchical.cpp:946] Agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 (8c6ce722e607) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0822 00:42:51.375540 18620 provider.cpp:806] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001' to the total resources
I0822 00:42:51.424933 18620 provider.cpp:2195] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001' and 0 operations to agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0
I0822 00:42:51.426620 18620 http_connection.hpp:131] Sending 3 call to http://172.17.0.4:35575/slave(1227)/api/v1/resource_provider
I0822 00:42:51.433995 18613 process.cpp:3671] Handling HTTP event for process 'slave(1227)' with path: '/slave(1227)/api/v1/resource_provider'
I0822 00:42:51.441973 18617 hierarchical.cpp:1740] Performed allocation for 1 agents in 291647ns
I0822 00:42:51.443490 18610 provider.cpp:788] Reconciling storage pools and volumes
I0822 00:42:51.447847 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0822 00:42:51.448474 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
I0822 00:42:51.467690 18609 provider.cpp:806] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:0.001' to the total resources
I0822 00:42:51.471207 18629 http.cpp:1115] HTTP POST for /slave(1227)/api/v1/resource_provider from 172.17.0.4:40534
I0822 00:42:51.472085 18629 manager.cpp:1039] Received UPDATE_STATE call with resources '[{"disk":{"source":{"id":"volume1","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"05cc812b-14b8-43b7-95b0-be5f827182d4"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":0.0009765625},"type":"SCALAR"}]' and 0 operations from resource provider 05cc812b-14b8-43b7-95b0-be5f827182d4
I0822 00:42:51.472666 18625 slave.cpp:8434] Handling resource provider message 'UPDATE_STATE: 05cc812b-14b8-43b7-95b0-be5f827182d4 disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001'
I0822 00:42:51.472846 18625 slave.cpp:8554] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001
I0822 00:42:51.476658 18621 hierarchical.cpp:946] Agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 (8c6ce722e607) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001
I0822 00:42:51.477224 18621 hierarchical.cpp:1740] Performed allocation for 1 agents in 275389ns
I0822 00:42:51.516878 18609 provider.cpp:2195] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,volume1,)]:0.001; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:0.001' and 0 operations to agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0
I0822 00:42:51.518294 18609 http_connection.hpp:131] Sending 3 call to http://172.17.0.4:35575/slave(1227)/api/v1/resource_provider
I0822 00:42:51.521769 18627 process.cpp:3671] Handling HTTP event for process 'slave(1227)' with path: '/slave(1227)/api/v1/resource_provider'
I0822 00:42:51.524538 18628 provider.cpp:788] Reconciling storage pools and volumes
I0822 00:42:51.525123 18620 hierarchical.cpp:1740] Performed allocation for 1 agents in 387286ns
I0822 00:42:51.537520 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
I0822 00:42:51.538192 32778 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
I0822 00:42:51.553575 18631 slave.cpp:924] Agent terminating
I0822 00:42:51.555299 18631 manager.cpp:163] Terminating resource provider 05cc812b-14b8-43b7-95b0-be5f827182d4
E0822 00:42:51.561372 18614 http_connection.hpp:452] End-Of-File received
I0822 00:42:51.573149 18631 master.cpp:1297] Agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 at slave(1227)@172.17.0.4:35575 (8c6ce722e607) disconnected
I0822 00:42:51.573237 18631 master.cpp:3399] Disconnecting agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 at slave(1227)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:51.580969 18614 http_connection.hpp:217] Re-detecting endpoint
E0822 00:42:51.581643 18625 provider.cpp:2203] Failed to update state for resource provider 05cc812b-14b8-43b7-95b0-be5f827182d4: Disconnected
I0822 00:42:51.582316 18631 master.cpp:3418] Deactivating agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 at slave(1227)@172.17.0.4:35575 (8c6ce722e607)
I0822 00:42:51.583034 18611 hierarchical.cpp:1035] Agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0 deactivated
I0822 00:42:51.609606 18629 containerizer.cpp:2616] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
I0822 00:42:51.609714 18629 containerizer.cpp:3319] 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 31.291442944secs
I0822 00:42:51.610651 18629 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:51.617489 18618 hierarchical.cpp:1740] Performed allocation for 1 agents in 314935ns
I0822 00:42:51.673377 18622 hierarchical.cpp:1740] Performed allocation for 1 agents in 310328ns
I0822 00:42:51.722703 18612 containerizer.cpp:3157] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0822 00:42:51.724711 18627 hierarchical.cpp:1740] Performed allocation for 1 agents in 299028ns
I0822 00:42:51.726059 18623 provisioner.cpp:612] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:51.731464 18622 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'
I0822 00:42:51.731724 18609 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-rdbYd0/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0822 00:42:51.732087 18609 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0822 00:42:51.770287 18632 process.cpp:2781] Returning '404 Not Found' for '/slave(1227)/api/v1'
I0822 00:42:51.800887 18607 master.cpp:1137] Master terminating
I0822 00:42:51.803223 18615 hierarchical.cpp:1011] Removed all filters for agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0
I0822 00:42:51.803275 18615 hierarchical.cpp:886] Removed agent 35a28557-26d8-43de-b449-a10bb9d11f1f-S0
[       OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1519 ms)
[----------] 52 tests from CSIVersion/StorageLocalResourceProviderTest (163692 ms total)

[----------] Global test environment tear-down
[==========] 2304 tests from 219 test cases ran. (1272348 ms total)
[  PASSED  ] 2302 tests.
[  FAILED  ] 2 tests, listed below:
[  FAILED  ] CSIVersion/StorageLocalResourceProviderTest.OperationUpdate/v0, where GetParam() = "v0"
[  FAILED  ] CSIVersion/StorageLocalResourceProviderTest.Update/v0, where GetParam() = "v0"

 2 FAILED TESTS
  YOU HAVE 32 DISABLED TESTS

I0822 00:42:52.004549 18632 process.cpp:935] Stopped the socket accept loop
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-1.9.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-1.9.0/_build'
make: *** [distcheck] Error 1
+ docker rmi --force mesos-1566427965-8383
Untagged: mesos-1566427965-8383:latest
Deleted: sha256:cdd1a636b70086ba24729b75cd4c5a9c7fa641d7aff24ed1b6e40de3caea45cd
Deleted: sha256:3640430c4c795f31cac9eefc4f7e35e69584d4bf134ab12790c796839f823065
Deleted: sha256:f1881d081f36c17afc565157b5dbfeae1b497daefaf3602bbeb70fbd893bfb60
Deleted: sha256:ec0aaa6f10ffd52e813be1e9c2d2e8f2c70fce0feda85afeb2f9d974be153ab6
Deleted: sha256:66ee671dcbf66dba49915ecf352024e157cff4b733f05d7276af783fefa642a5
Deleted: sha256:896834aebd3f7b40de52511be709426a39fde5fd6153bad83b05acdc482318b3
Deleted: sha256:435a0bebb1f869376aa5473b6f02a62997125a653795f8a8cadac0c88f200315
Deleted: sha256:f19cc51950c23f935ddd7c31380e39bf3f15f1b8e754b1fc0738ad5b1103cb6a
Deleted: sha256:88da24a7a430219f7879e883ef4aa871cc33546bf6ae9881a061cdd9474f9188
Deleted: sha256:0d7388c77c7a0ea84fd7846f2d88e0c25d0695ed35780b7c93566bae2c4cea50
Deleted: sha256:f4d874c07aa0eecc6a521a6c6e353d5e309856aa12e3cd36010b4a5605fc5fa8
Deleted: sha256:a19b795884dca4ad1ac407effce642b023a3040ef2cb00bf7aa4f21a68da1a2b
Deleted: sha256:9cf47f0bda1961000462e924b26e2bb3ec468eac15683cea4c9d5fe86eb9ca06
Deleted: sha256:aca901ba93a3209faef39371aca500a5bed356878fbece25d7274182e73c2b65
Deleted: sha256:bf3a79573e438b46b6fade337b096e8838e1b24d0d3a2c2417b2167de9cb8c49
Deleted: sha256:fd86ce4ecdaf5ca59b1205e9d9cc1571a3ccf352813a2ad6104c151dd3ad4713
Deleted: sha256:75307be365627f2ee8c6d68d5862084c5000bbf7b09e1738a61812a07b2ed4b3
Deleted: sha256:d71035bf032f1fe1d2d1bde30c7d72027fc6ffd64b4816b28761eacf5ab9d063
Deleted: sha256:5a4c25ad5a6e86f512d60ccbae1dffe43134e0903cf278a68ebf289b58a10ef3
Deleted: sha256:7caecdad8311e8504b6a055ac0db8fff8061d51fee4219a499780642fc84f0bc
Deleted: sha256:830b551930ec0921f4dee7d97ee58fa218c1fb2c7cc913fdbba8d229e92f7d59
Deleted: sha256:c8560c41e8619ee5dc1d3f9766873874e66a6e5adea898190cdfda854c28b05d
Deleted: sha256:124ea76ab965b43b4ca331f2bc1e75c7bc5be0832c86700e9469ac1af296acca
Deleted: sha256:2a2cd8a8c7668fba33810e80a06a30f39e2b5e9487016fb059ce510eb35246d2
Deleted: sha256:9e0d4965f8c1a5f117878c02c00267026aa1105921d488fdb77ae2f62c0219cc
Deleted: sha256:0bf0d039b3f1f83985d6b52b4bc3bc603b33b7f5dc829bc8bad26324cf41763d
Deleted: sha256:c90717a02dc201654b9ce5a0a0adf01adb1c6c2bd34686072665a05975ad824b
Deleted: sha256:a73e6f9bfbd380af1323c20733432f574603d55aee385bd25b9362df4c0a31fe
Deleted: sha256:2c4f9b25663dfbeccbca2e280ea337639a4555176a68690d4445e445e786f9fa
Deleted: sha256:af810f24a1ab82fa8a1d48ce884e8ece4f5d8f6f750d7968e206c6f4509eae13

Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/3272/console

- Mesos Reviewbot


On Aug. 21, 2019, 5:53 p.m., Andrei Budnik wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71343/
> -----------------------------------------------------------
> 
> (Updated Aug. 21, 2019, 5:53 p.m.)
> 
> 
> Review request for mesos, Gilbert Song, Greg Mann, and Qian Zhang.
> 
> 
> Bugs: MESOS-9887
>     https://issues.apache.org/jira/browse/MESOS-9887
> 
> 
> Repository: mesos
> 
> 
> Description
> -------
> 
> Previously, Mesos agent could send TASK_FAILED status update on
> executor termination while processing of TASK_FINISHED status update
> was in progress. Processing of task status updates involves sending
> requests to the containerizer, which might finish processing of these
> requests out-of-order, e.g. `MesosContainerizer::status`. Also,
> the agent does not overwrite status of the terminal status update once
> it's stored in the `terminatedTasks`. Hence, there was a race condition
> between two terminal status updates.
> 
> Note that V1 Executors are not affected by this problem because they
> wait for an acknowledgement of the terminal status update by the agent
> before terminating.
> 
> This patch introduces a new data structure `pendingStatusUpdates`,
> which holds a list of status updates that are being processed. This
> data structure allows validating the order of processing of status
> updates by the agent.
> 
> 
> Diffs
> -----
> 
>   src/slave/slave.hpp a17bbee13cb8291ad694f1520b613764b57b046b 
>   src/slave/slave.cpp 1d0ec9d2428c3ffa28ad3e960b74f171013cf0c2 
> 
> 
> Diff: https://reviews.apache.org/r/71343/diff/1/
> 
> 
> Testing
> -------
> 
> 1. manual testing described in MESOS-9887
> 2. internal CI
> 
> 
> Thanks,
> 
> Andrei Budnik
> 
>


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message