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 71275: Fixed agent draining when returning from unreachable state.
Date Tue, 13 Aug 2019 04:34:27 GMT

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



Bad patch!

Reviews applied: [71275]

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_71275"]

Error:
...<truncated>...
ent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.243963 18630 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 670785ed-72f2-4489-8fb7-18158c3e9339) for operation UUID b211a4e0-d0da-458e-acf5-064b21305ef2 on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.244907 18625 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.246160 18636 process.cpp:3671] Handling HTTP event for process 'slave(1222)' with path: '/slave(1222)/api/v1/resource_provider'
I0813 04:34:17.249538 18631 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:17.251186 18634 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57282
I0813 04:34:17.251458 18634 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0813 04:34:17.252104 18634 master.cpp:3888] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd","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":"b814e382-322a-4e6a-b9ec-69384e0b7818"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0813 04:34:17.254338 18647 master.cpp:12706] Removing offer 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-O5
I0813 04:34:17.254495 18637 sched.cpp:960] Rescinded offer 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-O5
I0813 04:34:17.254575 18637 sched.cpp:971] Scheduler::offerRescinded took 23100ns
I0813 04:34:17.255210 18632 hierarchical.cpp:1218] 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_v0_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd,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_v0_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd,test)]:2048, allocated: {}) on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 from framework 83a2b4de-3aa8-40
 cf-a9bf-5c17535ba026-0000
I0813 04:34:17.255329 18632 hierarchical.cpp:1264] Framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 filtered agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 for 5secs
I0813 04:34:17.257719 18628 master.cpp:12597] Sending operation '' (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) to agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 at slave(1222)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.258285 18625 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:17.261219 18631 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:17.261263 18631 provider.cpp:1295] Received UNRESERVE operation '' (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d)
I0813 04:34:17.270252 18633 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.193565ms
I0813 04:34:17.271003 18626 master.cpp:10414] Sending offers [ 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-O6 ] to framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.271628 18634 sched.cpp:934] Scheduler::resourceOffers took 88629ns
I0813 04:34:17.284301 18640 http.cpp:1115] HTTP POST for /slave(1222)/api/v1/resource_provider from 172.17.0.2:57272
I0813 04:34:17.285513 18628 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: b211a4e0-d0da-458e-acf5-064b21305ef2) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:17.285693 18628 slave.cpp:8870] Updating the state of operation with no ID (uuid: b211a4e0-d0da-458e-acf5-064b21305ef2) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:17.285740 18628 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: b211a4e0-d0da-458e-acf5-064b21305ef2) for an operator API call
I0813 04:34:17.286113 18630 master.cpp:12253] Updating the state of operation '' (uuid: b211a4e0-d0da-458e-acf5-064b21305ef2) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:17.286736 18627 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:17.345436 18634 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for operation UUID 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.345499 18634 status_update_manager_process.hpp:414] Creating operation status update stream 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d checkpoint=true
I0813 04:34:17.345533 18631 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:17.345993 18634 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for operation UUID 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.395702 18634 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for operation UUID 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.396023 18634 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 670785ed-72f2-4489-8fb7-18158c3e9339) for stream b211a4e0-d0da-458e-acf5-064b21305ef2
I0813 04:34:17.396098 18634 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 670785ed-72f2-4489-8fb7-18158c3e9339) for operation UUID b211a4e0-d0da-458e-acf5-064b21305ef2 on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.396472 18645 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.397353 18632 process.cpp:3671] Handling HTTP event for process 'slave(1222)' with path: '/slave(1222)/api/v1/resource_provider'
I0813 04:34:17.436173 18643 http.cpp:1115] HTTP POST for /slave(1222)/api/v1/resource_provider from 172.17.0.2:57272
I0813 04:34:17.437034 18627 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:17.437201 18627 slave.cpp:8870] Updating the state of operation with no ID (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:17.437249 18627 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) for an operator API call
I0813 04:34:17.437570 18635 master.cpp:12253] Updating the state of operation '' (uuid: 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:17.438050 18629 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:17.439328 18637 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:17.462616 18634 status_update_manager_process.hpp:490] Cleaning up operation status update stream b211a4e0-d0da-458e-acf5-064b21305ef2
I0813 04:34:17.462844 18634 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for stream 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d
I0813 04:34:17.462909 18634 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 7a29e81d-ab8a-4d43-900e-9ce3c15d4862) for operation UUID 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.529805 18634 status_update_manager_process.hpp:490] Cleaning up operation status update stream 37ad7baf-b1a0-4f60-b02a-06f5de64ca0d
I0813 04:34:17.598443 18638 master.cpp:1410] Framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253 disconnected
I0813 04:34:17.598490 18638 master.cpp:3360] Deactivating framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.598876 18630 hierarchical.cpp:475] Deactivated framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000
I0813 04:34:17.599515 18638 master.cpp:12706] Removing offer 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-O6
I0813 04:34:17.599597 18638 master.cpp:3337] Disconnecting framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.599653 18638 master.cpp:1425] Giving framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253 0ns to failover
I0813 04:34:17.599969 18639 slave.cpp:924] Agent terminating
I0813 04:34:17.600468 18630 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v0_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd,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_v0_sSnqSg/2GB-8c3d0180-f55f-4527-af97-b8a1990fabdd,test)]:2048, allocated: {}) on agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 from framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000
I0813 04:34:17.600837 18639 manager.cpp:163] Terminating resource provider b814e382-322a-4e6a-b9ec-69384e0b7818
I0813 04:34:17.601088 18634 master.cpp:10206] Framework failover timeout, removing framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.601126 18634 master.cpp:11205] Removing framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000 (default) at scheduler-a9b0dcf2-839a-45d9-994e-b507dd594a86@172.17.0.2:39253
I0813 04:34:17.601575 18627 hierarchical.cpp:1432] Allocation paused
E0813 04:34:17.601603 18625 http_connection.hpp:452] End-Of-File received
I0813 04:34:17.601725 18634 master.cpp:1295] Agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 at slave(1222)@172.17.0.2:39253 (21cdb951747c) disconnected
I0813 04:34:17.601763 18634 master.cpp:3397] Disconnecting agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 at slave(1222)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.601904 18634 master.cpp:3416] Deactivating agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 at slave(1222)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.602069 18627 hierarchical.cpp:417] Removed framework 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-0000
I0813 04:34:17.602169 18627 hierarchical.cpp:1442] Allocation resumed
I0813 04:34:17.602218 18627 hierarchical.cpp:799] Agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0 deactivated
I0813 04:34:17.602424 18625 http_connection.hpp:217] Re-detecting endpoint
I0813 04:34:17.602895 18625 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0813 04:34:17.602969 18625 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0813 04:34:17.603003 18631 provider.cpp:471] Disconnected from resource provider manager
I0813 04:34:17.603142 18625 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.603157 18630 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:17.604630 18643 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
I0813 04:34:17.604670 18643 containerizer.cpp:3318] 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
I0813 04:34:17.605134 18643 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.606487 18634 hierarchical.cpp:1508] Performed allocation for 1 agents in 153345ns
I0813 04:34:17.606748 18629 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.607357 18647 provider.cpp:459] Connected to resource provider manager
I0813 04:34:17.607986 18630 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:39253/slave(1222)/api/v1/resource_provider
I0813 04:34:17.608707 18648 process.cpp:2781] Returning '404 Not Found' for '/slave(1222)/api/v1/resource_provider'
E0813 04:34:17.609805 18637 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0813 04:34:17.657891 18641 hierarchical.cpp:1508] Performed allocation for 1 agents in 221037ns
I0813 04:34:17.709182 18646 containerizer.cpp:3157] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0813 04:34:17.709287 18634 hierarchical.cpp:1508] Performed allocation for 1 agents in 120529ns
I0813 04:34:17.711176 18631 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
I0813 04:34:17.714207 18627 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'
I0813 04:34:17.714516 18638 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-6dA8Ns/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.714792 18634 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:17.718684 18648 process.cpp:2781] Returning '404 Not Found' for '/slave(1222)/api/v1'
I0813 04:34:17.729594 18623 master.cpp:1135] Master terminating
I0813 04:34:17.730307 18633 hierarchical.cpp:775] Removed all filters for agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
I0813 04:34:17.730338 18633 hierarchical.cpp:650] Removed agent 83a2b4de-3aa8-40cf-a9bf-5c17535ba026-S0
[       OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v0 (2478 ms)
[ RUN      ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1
I0813 04:34:17.748692 18623 cluster.cpp:177] Creating default 'local' authorizer
I0813 04:34:17.753526 18636 master.cpp:440] Master f24ab1c4-6a4c-4059-930e-6d4f0fb7294e (21cdb951747c) started on 172.17.0.2:39253
I0813 04:34:17.753553 18636 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/khWP0G/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/khWP0G/master" --zk_session_timeout="10secs"
I0813 04:34:17.753979 18636 master.cpp:492] Master only allowing authenticated frameworks to register
I0813 04:34:17.753995 18636 master.cpp:498] Master only allowing authenticated agents to register
I0813 04:34:17.754004 18636 master.cpp:504] Master only allowing authenticated HTTP frameworks to register
I0813 04:34:17.754014 18636 credentials.hpp:37] Loading credentials for authentication from '/tmp/khWP0G/credentials'
I0813 04:34:17.754364 18636 master.cpp:548] Using default 'crammd5' authenticator
I0813 04:34:17.754592 18636 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0813 04:34:17.754869 18636 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0813 04:34:17.755071 18636 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0813 04:34:17.755246 18636 master.cpp:629] Authorization enabled
I0813 04:34:17.755671 18647 whitelist_watcher.cpp:77] No whitelist given
I0813 04:34:17.755728 18646 hierarchical.cpp:241] Initialized hierarchical allocator process
I0813 04:34:17.758810 18630 master.cpp:2168] Elected as the leading master!
I0813 04:34:17.758848 18630 master.cpp:1664] Recovering from registrar
I0813 04:34:17.759054 18639 registrar.cpp:339] Recovering registrar
I0813 04:34:17.759925 18639 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
I0813 04:34:17.760076 18639 registrar.cpp:487] Applied 1 operations in 48580ns; attempting to update the registry
I0813 04:34:17.761001 18639 registrar.cpp:544] Successfully updated the registry in 0ns
I0813 04:34:17.761178 18639 registrar.cpp:416] Successfully recovered registrar
I0813 04:34:17.761688 18638 master.cpp:1817] Recovered 0 agents from the registry (143B); allowing 10mins for agents to reregister
I0813 04:34:17.761711 18643 hierarchical.cpp:280] Skipping recovery of hierarchical allocator: nothing to recover
W0813 04:34:17.767647 18623 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:39253
I0813 04:34:17.769137 18623 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0813 04:34:17.769773 18623 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0813 04:34:17.769804 18623 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
W0813 04:34:17.769955 18623 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0813 04:34:17.769997 18623 provisioner.cpp:300] Using default backend 'copy'
I0813 04:34:17.772680 18623 cluster.cpp:518] Creating default 'local' authorizer
I0813 04:34:17.775111 18626 slave.cpp:267] Mesos agent started on (1223)@172.17.0.2:39253
I0813 04:34:17.775142 18626 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/khWP0G/0gv59i/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/khWP0G/0gv59i/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/khWP0G/0gv59i/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/khWP0G/0gv59i/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/khWP0G/0gv59i/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/khWP0G/0gv59i/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/khWP0G/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_OperatorOperationsWithResourceProviderResources_v1_uqx36T" --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_StorageLocalResourcePr
 oviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u" --zk_session_timeout="10secs"
I0813 04:34:17.775565 18626 credentials.hpp:86] Loading credential for authentication from '/tmp/khWP0G/0gv59i/credential'
I0813 04:34:17.775749 18626 slave.cpp:300] Agent using credential for: test-principal
I0813 04:34:17.775774 18626 credentials.hpp:37] Loading credentials for authentication from '/tmp/khWP0G/0gv59i/http_credentials'
I0813 04:34:17.775985 18626 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0813 04:34:17.776424 18626 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0813 04:34:17.778231 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"}]
I0813 04:34:17.778447 18626 slave.cpp:623] Agent attributes: [  ]
I0813 04:34:17.778463 18626 slave.cpp:632] Agent hostname: 21cdb951747c
I0813 04:34:17.778661 18636 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:17.778698 18624 task_status_update_manager.cpp:181] Pausing sending task status updates
I0813 04:34:17.780036 18628 process.cpp:3671] Handling HTTP event for process 'test-disk-profile-server' with path: '/test-disk-profile-server/profiles'
I0813 04:34:17.780474 18640 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u/meta'
I0813 04:34:17.780761 18644 slave.cpp:7444] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u/meta', beginning agent recovery
I0813 04:34:17.781504 18629 task_status_update_manager.cpp:207] Recovering task status update manager
I0813 04:34:17.782061 18647 containerizer.cpp:821] Recovering Mesos containers
I0813 04:34:17.782502 18647 containerizer.cpp:1157] Recovering isolators
I0813 04:34:17.783591 18639 containerizer.cpp:1196] Recovering provisioner
I0813 04:34:17.784366 18632 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
I0813 04:34:17.784379 18638 provisioner.cpp:500] Provisioner recovery complete
I0813 04:34:17.785223 18641 composing.cpp:339] Finished recovering all containerizers
I0813 04:34:17.785554 18631 slave.cpp:7908] Recovering executors
I0813 04:34:17.785679 18631 slave.cpp:8061] Finished recovery
I0813 04:34:17.786571 18628 task_status_update_manager.cpp:181] Pausing sending task status updates
I0813 04:34:17.786592 18631 slave.cpp:1351] New master detected at master@172.17.0.2:39253
I0813 04:34:17.786628 18645 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:17.786744 18631 slave.cpp:1416] Detecting new master
I0813 04:34:17.788069 18625 slave.cpp:1443] Authenticating with master master@172.17.0.2:39253
I0813 04:34:17.788190 18625 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I0813 04:34:17.788596 18647 authenticatee.cpp:121] Creating new client SASL connection
I0813 04:34:17.788967 18639 master.cpp:10599] Authenticating slave(1223)@172.17.0.2:39253
I0813 04:34:17.789136 18644 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2078)@172.17.0.2:39253
I0813 04:34:17.789467 18643 authenticator.cpp:98] Creating new server SASL connection
I0813 04:34:17.789785 18632 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0813 04:34:17.789826 18632 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0813 04:34:17.790019 18634 authenticator.cpp:204] Received SASL authentication start
I0813 04:34:17.790110 18634 authenticator.cpp:326] Authentication requires more steps
I0813 04:34:17.790261 18638 authenticatee.cpp:259] Received SASL authentication step
I0813 04:34:17.790410 18642 authenticator.cpp:232] Received SASL authentication step
I0813 04:34:17.790452 18642 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '21cdb951747c' server FQDN: '21cdb951747c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0813 04:34:17.790477 18642 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0813 04:34:17.790520 18642 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0813 04:34:17.790552 18642 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '21cdb951747c' server FQDN: '21cdb951747c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0813 04:34:17.790567 18642 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0813 04:34:17.790577 18642 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0813 04:34:17.790593 18642 authenticator.cpp:318] Authentication success
I0813 04:34:17.790745 18629 authenticatee.cpp:299] Authentication success
I0813 04:34:17.790853 18636 master.cpp:10631] Successfully authenticated principal 'test-principal' at slave(1223)@172.17.0.2:39253
I0813 04:34:17.790884 18630 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2078)@172.17.0.2:39253
I0813 04:34:17.791323 18642 slave.cpp:1543] Successfully authenticated with master master@172.17.0.2:39253
I0813 04:34:17.791723 18642 slave.cpp:1993] Will retry registration in 3.382499ms if necessary
I0813 04:34:17.791899 18624 master.cpp:7086] Received register agent message from slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.792188 18624 master.cpp:4202] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal'
I0813 04:34:17.792904 18631 master.cpp:7153] Authorized registration of agent at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.793010 18631 master.cpp:7265] Registering agent at slave(1223)@172.17.0.2:39253 (21cdb951747c) with id f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:17.793686 18626 registrar.cpp:487] Applied 1 operations in 225083ns; attempting to update the registry
I0813 04:34:17.794433 18626 registrar.cpp:544] Successfully updated the registry in 0ns
I0813 04:34:17.794641 18643 master.cpp:7313] Admitted agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:17.795509 18643 master.cpp:7358] Registered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0813 04:34:17.795743 18634 slave.cpp:1576] Registered with master master@172.17.0.2:39253; given agent ID f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:17.795738 18638 hierarchical.cpp:617] Added agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 (21cdb951747c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
I0813 04:34:17.795879 18636 task_status_update_manager.cpp:188] Resuming sending task status updates
I0813 04:34:17.796193 18638 hierarchical.cpp:1508] Performed allocation for 1 agents in 218362ns
I0813 04:34:17.796393 18634 slave.cpp:1611] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u/meta/slaves/f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0/slave.info'
I0813 04:34:17.796461 18633 status_update_manager_process.hpp:385] Resuming operation status update manager
I0813 04:34:17.797752 18634 slave.cpp:1663] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"e3fG3GOvQ1GnR6gd1CbNIA=="},"slave_id":{"value":"f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0"},"update_oversubscribed_resources":false}
I0813 04:34:17.798491 18634 master.cpp:8478] Ignoring update on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c) as it reports no changes
I0813 04:34:17.802696 18644 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1'
I0813 04:34:17.803879 18638 http.cpp:1115] HTTP POST for /slave(1223)/api/v1 from 172.17.0.2:57292
I0813 04:34:17.804428 18638 http.cpp:2146] Processing GET_CONTAINERS call
I0813 04:34:17.810011 18625 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:17.812438 18644 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1'
I0813 04:34:17.813477 18638 http.cpp:1115] HTTP POST for /slave(1223)/api/v1 from 172.17.0.2:57294
I0813 04:34:17.814363 18638 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'
I0813 04:34:17.815304 18638 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_Aro23u/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:17.816012 18642 containerizer.cpp:1392] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.817294 18642 containerizer.cpp:1570] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_uqx36T/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0813 04:34:17.817338 18642 containerizer.cpp:3318] 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
I0813 04:34:17.820214 18645 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_OperatorOperationsWithResourceProviderResources_v1_6zr205","--available_capacity=2GB","--volumes=","","--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_OperatorOperationsWithResourceProviderResources_v1_Aro23u/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-BIGnGV/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperat
 ionsWithResourceProviderResources_v1_Aro23u/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="90" --pipe_write="91" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_uqx36T/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
I0813 04:34:17.829296 18645 launcher.cpp:145] Forked child with pid '32722' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:17.830283 18645 containerizer.cpp:3318] 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
I0813 04:34:17.831810 18645 containerizer.cpp:3318] 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
I0813 04:34:17.832181 18641 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_OperatorOperationsWithResourceProviderResources_v1_Aro23u/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.833590 18627 containerizer.cpp:3318] 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
I0813 04:34:17.836459 18624 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'
I0813 04:34:17.836720 18630 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-BIGnGV/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:17.948248 18636 hierarchical.cpp:1508] Performed allocation for 1 agents in 223770ns
I0813 04:34:17.999405 18646 hierarchical.cpp:1508] Performed allocation for 1 agents in 204141ns
I0813 04:34:18.051379 18631 hierarchical.cpp:1508] Performed allocation for 1 agents in 208377ns
I0813 04:34:18.102716 18639 hierarchical.cpp:1508] Performed allocation for 1 agents in 211120ns
I0813 04:34:18.154326 18633 hierarchical.cpp:1508] Performed allocation for 1 agents in 214549ns
I0813 04:34:18.205924 18628 hierarchical.cpp:1508] Performed allocation for 1 agents in 217216ns
I0813 04:34:18.221554 18640 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-BIGnGV/endpoint.sock' with CSI v1
I0813 04:34:18.238724 32726 test_csi_plugin.cpp:909] ProbeRequest '{}'
I0813 04:34:18.240700 18625 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:18.243366 32726 test_csi_plugin.cpp:895] GetPluginCapabilitiesRequest '{}'
I0813 04:34:18.243993 18629 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1'
I0813 04:34:18.245250 18638 http.cpp:1115] HTTP POST for /slave(1223)/api/v1 from 172.17.0.2:57296
I0813 04:34:18.246078 18638 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'
I0813 04:34:18.247340 32727 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0813 04:34:18.247717 32726 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0813 04:34:18.249001 18626 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0813 04:34:18.250159 18626 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {"name":".","vendorVersion":"1.9.0"}
I0813 04:34:18.252321 32728 test_csi_plugin.cpp:1105] ControllerGetCapabilitiesRequest '{}'
I0813 04:34:18.255445 32727 test_csi_plugin.cpp:1241] NodeGetCapabilitiesRequest '{}'
I0813 04:34:18.257421 18640 hierarchical.cpp:1508] Performed allocation for 1 agents in 213788ns
I0813 04:34:18.258231 32727 test_csi_plugin.cpp:1255] NodeGetInfoRequest '{}'
I0813 04:34:18.260118 18630 provider.cpp:659] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
I0813 04:34:18.260254 18639 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:18.260746 18632 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.264117 18641 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.264796 18634 provider.cpp:459] Connected to resource provider manager
I0813 04:34:18.265545 18642 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.266813 18637 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.268532 18630 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57300
I0813 04:34:18.269197 18643 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_OperatorOperationsWithResourceProviderResources_v1_6zr205","--available_capacity=2GB","--volumes=","","--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"}},"type":"org.apache.mesos.rp.local.storage"}
I0813 04:34:18.304049 18641 slave.cpp:8417] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"0e40be87-7324-473f-a67a-3f3738b71e68"},"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_OperatorOperationsWithResourceProviderResources_v1_6zr205","--available_capacity=2GB","--volumes=","","--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"}},"type":"org.apache.mesos.rp.local.storage"}'
I0813 04:34:18.305979 18637 provider.cpp:481] Received SUBSCRIBED event
I0813 04:34:18.306016 18637 provider.cpp:1255] Subscribed with ID 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:18.306955 18639 status_update_manager_process.hpp:314] Recovering operation status update manager
I0813 04:34:18.309096 18630 hierarchical.cpp:1508] Performed allocation for 1 agents in 211322ns
I0813 04:34:18.348292 32727 test_csi_plugin.cpp:1050] ListVolumesRequest '{}'
I0813 04:34:18.350456 18628 provider.cpp:2145] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.350715 18628 provider.cpp:745] Resource provider 0e40be87-7324-473f-a67a-3f3738b71e68 is in READY state
I0813 04:34:18.350785 18634 status_update_manager_process.hpp:385] Resuming operation status update manager
I0813 04:34:18.350818 18627 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.351613 18642 provider.cpp:1181] Updating profiles { test } for resource provider 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:18.352520 18632 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.354053 18628 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:18.354535 18631 manager.cpp:1039] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:18.354792 18645 slave.cpp:8417] Handling resource provider message 'UPDATE_STATE: 0e40be87-7324-473f-a67a-3f3738b71e68 {}'
I0813 04:34:18.354899 18645 slave.cpp:8537] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0813 04:34:18.356658 18647 hierarchical.cpp:753] Grew agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 by {} (total), {  } (used)
I0813 04:34:18.357072 18647 hierarchical.cpp:710] Agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 (21cdb951747c) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0813 04:34:18.357012 32728 test_csi_plugin.cpp:1078] GetCapacityRequest '{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
W0813 04:34:18.358176 18623 process.cpp:2877] Attempted to spawn already running process version@172.17.0.2:39253
I0813 04:34:18.359503 18623 sched.cpp:239] Version: 1.9.0
I0813 04:34:18.360389 18635 sched.cpp:343] New master detected at master@172.17.0.2:39253
I0813 04:34:18.360538 18635 sched.cpp:408] Authenticating with master master@172.17.0.2:39253
I0813 04:34:18.360563 18635 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0813 04:34:18.360975 18641 authenticatee.cpp:121] Creating new client SASL connection
I0813 04:34:18.361431 18642 master.cpp:10599] Authenticating scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.361483 18636 hierarchical.cpp:1508] Performed allocation for 1 agents in 204392ns
I0813 04:34:18.361532 18631 provider.cpp:933] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to the total resources
I0813 04:34:18.361640 18639 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2079)@172.17.0.2:39253
I0813 04:34:18.361970 18637 authenticator.cpp:98] Creating new server SASL connection
I0813 04:34:18.362267 18630 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0813 04:34:18.362303 18630 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0813 04:34:18.362458 18624 authenticator.cpp:204] Received SASL authentication start
I0813 04:34:18.362537 18624 authenticator.cpp:326] Authentication requires more steps
I0813 04:34:18.362684 18625 authenticatee.cpp:259] Received SASL authentication step
I0813 04:34:18.362877 18645 authenticator.cpp:232] Received SASL authentication step
I0813 04:34:18.362926 18645 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '21cdb951747c' server FQDN: '21cdb951747c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I0813 04:34:18.362944 18645 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0813 04:34:18.362998 18645 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0813 04:34:18.363026 18645 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '21cdb951747c' server FQDN: '21cdb951747c' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I0813 04:34:18.363039 18645 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0813 04:34:18.363049 18645 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0813 04:34:18.363068 18645 authenticator.cpp:318] Authentication success
I0813 04:34:18.363180 18640 authenticatee.cpp:299] Authentication success
I0813 04:34:18.363329 18647 master.cpp:10631] Successfully authenticated principal 'test-principal' at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.363374 18646 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2079)@172.17.0.2:39253
I0813 04:34:18.363592 18632 sched.cpp:520] Successfully authenticated with master master@172.17.0.2:39253
I0813 04:34:18.363624 18632 sched.cpp:835] Sending SUBSCRIBE call to master@172.17.0.2:39253
I0813 04:34:18.363804 18632 sched.cpp:870] Will retry registration in 763.266716ms if necessary
I0813 04:34:18.364063 18628 master.cpp:2908] Received SUBSCRIBE call for framework 'default' at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.364104 18628 master.cpp:2240] Authorizing framework principal 'test-principal' to receive offers for roles '{ storage/default-role }'
I0813 04:34:18.364770 18633 master.cpp:2995] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0813 04:34:18.367379 18633 master.cpp:10829] Adding framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 with roles {  } suppressed
I0813 04:34:18.367918 18634 sched.cpp:751] Framework registered with f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.367981 18634 sched.cpp:770] Scheduler::registered took 32301ns
I0813 04:34:18.368413 18638 hierarchical.cpp:368] Added framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.369690 18638 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.098467ms
I0813 04:34:18.370221 18639 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O0 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.371130 18639 sched.cpp:934] Scheduler::resourceOffers took 120882ns
I0813 04:34:18.371498 18630 master.cpp:6222] Processing DECLINE call for offers: [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O0 ] for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 with 5 seconds filter
I0813 04:34:18.372113 18630 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O0
I0813 04:34:18.372779 18624 hierarchical.cpp:1218] Recovered 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], allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.372856 18624 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:18.404388 18631 provider.cpp:2145] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' and 0 operations to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.404840 18625 http_connection.hpp:131] Sending 3 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.405937 18643 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.444804 18628 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:18.445397 18635 manager.cpp:1039] Received UPDATE_STATE call with resources '[{"disk":{"source":{"profile":"test","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"0e40be87-7324-473f-a67a-3f3738b71e68"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]' and 0 operations from resource provider 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:18.446030 18641 slave.cpp:8417] Handling resource provider message 'UPDATE_STATE: 0e40be87-7324-473f-a67a-3f3738b71e68 disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0813 04:34:18.446211 18641 slave.cpp:8537] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048
I0813 04:34:18.448508 18636 hierarchical.cpp:710] Agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 (21cdb951747c) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048
I0813 04:34:18.449787 18636 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.083167ms
I0813 04:34:18.450403 18638 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O1 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.451004 18637 sched.cpp:934] Scheduler::resourceOffers took 78886ns
I0813 04:34:18.458451 18624 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O1
I0813 04:34:18.458873 18624 master.cpp:4739] Processing ACCEPT call for offers: [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O1 ] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.458974 18624 master.cpp:4112] Authorizing principal 'test-principal' to create a MOUNT disk from 'disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048'
I0813 04:34:18.459141 18647 hierarchical.cpp:1508] Performed allocation for 1 agents in 391078ns
I0813 04:34:18.460032 18626 master.cpp:6014] Processing CREATE_DISK operation with source disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:18.460613 18626 master.cpp:12597] Sending operation '' (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:18.460922 18644 hierarchical.cpp:1432] Allocation paused
I0813 04:34:18.461131 18646 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:18.461973 18644 hierarchical.cpp:1218] Recovered ports(allocated: storage/default-role):[31000-32000]; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048, allocated: disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.462069 18644 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:18.462307 18644 hierarchical.cpp:1442] Allocation resumed
I0813 04:34:18.463635 18636 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:18.463680 18636 provider.cpp:1295] Received CREATE_DISK operation '' (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1)
I0813 04:34:18.510624 18637 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.510836 18637 hierarchical.cpp:1508] Performed allocation for 1 agents in 723596ns
I0813 04:34:18.514060 18630 v1_volume_manager.cpp:293] Creating volume with name '47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1'
I0813 04:34:18.517231 32728 test_csi_plugin.cpp:922] CreateVolumeRequest '{"name":"47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1","capacityRange":{"requiredBytes":"2147483648","limitBytes":"2147483648"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0813 04:34:18.562494 18643 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.562656 18643 hierarchical.cpp:1508] Performed allocation for 1 agents in 771110ns
I0813 04:34:18.599231 18640 provider.cpp:1597] Applying conversion from 'disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to 'disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048' for operation (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1)
I0813 04:34:18.613935 18626 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.614044 18626 hierarchical.cpp:1508] Performed allocation for 1 agents in 432431ns
I0813 04:34:18.649343 18646 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: c360435f-4183-4365-8d7c-59dc46868af2) for operation UUID 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 of framework 'f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000' on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.649418 18646 status_update_manager_process.hpp:414] Creating operation status update stream 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 checkpoint=true
I0813 04:34:18.649960 18646 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: c360435f-4183-4365-8d7c-59dc46868af2) for operation UUID 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 of framework 'f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000' on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.665710 18628 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.665820 18628 hierarchical.cpp:1508] Performed allocation for 1 agents in 430888ns
I0813 04:34:18.699678 18646 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: c360435f-4183-4365-8d7c-59dc46868af2) for operation UUID 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 of framework 'f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000' on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.700685 18635 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.702090 18642 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.717278 18633 hierarchical.cpp:2358] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for role storage/default-role of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.717399 18633 hierarchical.cpp:1508] Performed allocation for 1 agents in 514989ns
I0813 04:34:18.740574 18625 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:18.741647 18631 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:18.741855 18631 slave.cpp:8870] Updating the state of operation with no ID (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:18.742300 18631 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.742691 18647 master.cpp:12253] Updating the state of operation '' (uuid: 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1) for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:18.743880 18626 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:18.744619 18643 hierarchical.cpp:956] Updated allocation of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048 to disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048
I0813 04:34:18.745296 18643 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048 (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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.745900 18642 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:18.746098 18627 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: c360435f-4183-4365-8d7c-59dc46868af2) for stream 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1
I0813 04:34:18.746178 18627 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: c360435f-4183-4365-8d7c-59dc46868af2) for operation UUID 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1 of framework 'f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000' on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.769824 18637 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.207385ms
I0813 04:34:18.770484 18636 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O2 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.771304 18639 sched.cpp:934] Scheduler::resourceOffers took 125286ns
I0813 04:34:18.775043 18645 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:18.777855 18644 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57302
I0813 04:34:18.778266 18644 http.cpp:263] Processing call RESERVE_RESOURCES
I0813 04:34:18.779333 18644 master.cpp:3824] Authorizing principal 'test-principal' to reserve resources 'disk(reservations: [(DYNAMIC,storage),(DYNAMIC,storage/default-role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048'
I0813 04:34:18.781965 18642 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O2
I0813 04:34:18.782205 18636 sched.cpp:960] Rescinded offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O2
I0813 04:34:18.782299 18636 sched.cpp:971] Scheduler::offerRescinded took 26180ns
I0813 04:34:18.782961 18637 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:18.783083 18637 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:18.785688 18630 master.cpp:12597] Sending operation '' (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:18.786293 18624 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:18.789042 18645 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:18.789088 18645 provider.cpp:1295] Received RESERVE operation '' (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3)
I0813 04:34:18.791811 18627 status_update_manager_process.hpp:490] Cleaning up operation status update stream 47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1
I0813 04:34:18.876521 18644 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for operation UUID 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.876596 18644 status_update_manager_process.hpp:414] Creating operation status update stream 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 checkpoint=true
I0813 04:34:18.877171 18644 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for operation UUID 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.960275 18644 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for operation UUID 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:18.978217 18643 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:18.979097 18636 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:18.982515 18642 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.498403ms
I0813 04:34:18.983301 18637 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O3 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:18.984042 18639 sched.cpp:934] Scheduler::resourceOffers took 90479ns
I0813 04:34:18.987092 18647 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:18.989111 18646 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57304
I0813 04:34:18.989389 18646 http.cpp:263] Processing call CREATE_VOLUMES
I0813 04:34:18.990239 18646 master.cpp:3951] Authorizing principal 'test-principal' to create volumes '[{"disk":{"persistence":{"id":"0038cadf-7d10-4293-ad12-8c411e2977fe","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1","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":"0e40be87-7324-473f-a67a-3f3738b71e68"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0813 04:34:18.992439 18635 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O3
I0813 04:34:18.992592 18644 sched.cpp:960] Rescinded offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O3
I0813 04:34:18.992686 18644 sched.cpp:971] Scheduler::offerRescinded took 35689ns
I0813 04:34:18.993207 18627 hierarchical.cpp:1218] 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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-40
 59-930e-6d4f0fb7294e-0000
I0813 04:34:18.993324 18627 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:18.996218 18645 master.cpp:12597] Sending operation '' (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:18.996809 18633 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:18.999714 18640 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:18.999758 18640 provider.cpp:1295] Received CREATE operation '' (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62)
I0813 04:34:19.005604 18628 master.cpp:6415] Processing REVIVE call for framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:19.006007 18646 hierarchical.cpp:1365] Unsuppressed offers for roles { storage/default-role } of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:19.006036 18646 hierarchical.cpp:1387] Revived roles { storage/default-role } of framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:19.007249 18646 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.087091ms
I0813 04:34:19.007642 18646 hierarchical.cpp:1508] Performed allocation for 1 agents in 196434ns
I0813 04:34:19.007895 18634 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O4 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:19.008472 18644 sched.cpp:934] Scheduler::resourceOffers took 77198ns
I0813 04:34:19.016407 18642 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:19.017457 18637 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:19.017637 18637 slave.cpp:8870] Updating the state of operation with no ID (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:19.017685 18637 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) for an operator API call
I0813 04:34:19.018080 18630 master.cpp:12253] Updating the state of operation '' (uuid: 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:19.018678 18625 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.087033 18644 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for operation UUID a97086da-ebda-4eee-9c47-5d1c93c7ef62 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.087096 18644 status_update_manager_process.hpp:414] Creating operation status update stream a97086da-ebda-4eee-9c47-5d1c93c7ef62 checkpoint=true
I0813 04:34:19.087167 18640 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:19.087543 18644 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for operation UUID a97086da-ebda-4eee-9c47-5d1c93c7ef62 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.137336 18644 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for operation UUID a97086da-ebda-4eee-9c47-5d1c93c7ef62 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.137708 18644 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for stream 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3
I0813 04:34:19.137774 18644 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 7e1edff0-fcc3-4209-80c6-592284442f28) for operation UUID 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.138382 18627 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:19.139437 18636 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:19.180692 18647 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:19.181620 18631 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:19.181824 18631 slave.cpp:8870] Updating the state of operation with no ID (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:19.181875 18631 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) for an operator API call
I0813 04:34:19.182258 18625 master.cpp:12253] Updating the state of operation '' (uuid: a97086da-ebda-4eee-9c47-5d1c93c7ef62) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:19.182818 18624 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.184587 18645 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:19.204213 18644 status_update_manager_process.hpp:490] Cleaning up operation status update stream 6e082d0a-3111-4ab6-8c18-3ad277b1f8e3
I0813 04:34:19.204457 18644 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for stream a97086da-ebda-4eee-9c47-5d1c93c7ef62
I0813 04:34:19.204531 18644 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 0d441b1b-e523-4262-8b66-7686f28d2a9e) for operation UUID a97086da-ebda-4eee-9c47-5d1c93c7ef62 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.288046 18644 status_update_manager_process.hpp:490] Cleaning up operation status update stream a97086da-ebda-4eee-9c47-5d1c93c7ef62
I0813 04:34:19.351306 18638 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:19.352680 18628 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57306
I0813 04:34:19.352941 18628 http.cpp:263] Processing call DESTROY_VOLUMES
I0813 04:34:19.353834 18628 master.cpp:3996] Authorizing principal 'test-principal' to destroy volumes '[{"disk":{"persistence":{"id":"0038cadf-7d10-4293-ad12-8c411e2977fe","principal":"test-principal"},"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1","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":"0e40be87-7324-473f-a67a-3f3738b71e68"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0813 04:34:19.356122 18626 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O4
I0813 04:34:19.356324 18646 sched.cpp:960] Rescinded offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O4
I0813 04:34:19.356423 18646 sched.cpp:971] Scheduler::offerRescinded took 31188ns
I0813 04:34:19.357362 18634 hierarchical.cpp:1218] 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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test),0038cadf-7d10-4293-ad12-8c411e2977fe: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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test),0038cadf-7d10-4293-ad12-8c411e2977fe:volume]:2048, allocat
 ed: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:19.357498 18634 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:19.360716 18635 master.cpp:12597] Sending operation '' (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:19.361254 18636 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.364428 18630 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:19.364470 18630 provider.cpp:1295] Received DESTROY operation '' (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29)
I0813 04:34:19.372229 18625 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.348466ms
I0813 04:34:19.372895 18641 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O5 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:19.373582 18628 sched.cpp:934] Scheduler::resourceOffers took 81611ns
I0813 04:34:19.465837 18632 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for operation UUID ea7a307a-fe22-4390-9de4-8211e4d6cd29 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.465900 18632 status_update_manager_process.hpp:414] Creating operation status update stream ea7a307a-fe22-4390-9de4-8211e4d6cd29 checkpoint=true
I0813 04:34:19.466353 18632 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for operation UUID ea7a307a-fe22-4390-9de4-8211e4d6cd29 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.516028 18632 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for operation UUID ea7a307a-fe22-4390-9de4-8211e4d6cd29 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.516904 18646 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:19.517889 18627 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:19.520985 18640 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0813 04:34:19.523831 18637 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:57308
I0813 04:34:19.524152 18637 http.cpp:263] Processing call UNRESERVE_RESOURCES
I0813 04:34:19.524909 18637 master.cpp:3888] Authorizing principal 'test-principal' to unreserve resources '[{"disk":{"source":{"id":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1","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":"0e40be87-7324-473f-a67a-3f3738b71e68"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/default-role","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]'
I0813 04:34:19.527194 18638 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O5
I0813 04:34:19.527559 18625 sched.cpp:960] Rescinded offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O5
I0813 04:34:19.527642 18625 sched.cpp:971] Scheduler::offerRescinded took 25788ns
I0813 04:34:19.527976 18629 hierarchical.cpp:1218] 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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-40
 59-930e-6d4f0fb7294e-0000
I0813 04:34:19.528108 18629 hierarchical.cpp:1264] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 filtered agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 for 5secs
I0813 04:34:19.530511 18641 master.cpp:12597] Sending operation '' (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) to agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:19.531071 18632 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.533725 18640 provider.cpp:481] Received APPLY_OPERATION event
I0813 04:34:19.533771 18640 provider.cpp:1295] Received UNRESERVE operation '' (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b)
I0813 04:34:19.542205 18631 hierarchical.cpp:1508] Performed allocation for 1 agents in 1.281993ms
I0813 04:34:19.542845 18637 master.cpp:10414] Sending offers [ f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O6 ] to framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:19.543473 18647 sched.cpp:934] Scheduler::resourceOffers took 86871ns
I0813 04:34:19.556469 18624 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:19.557502 18630 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:19.557672 18630 slave.cpp:8870] Updating the state of operation with no ID (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:19.557720 18630 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) for an operator API call
I0813 04:34:19.558008 18632 master.cpp:12253] Updating the state of operation '' (uuid: ea7a307a-fe22-4390-9de4-8211e4d6cd29) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:19.558583 18627 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.634044 18647 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for operation UUID 832dfe96-bab8-4da6-b7ab-7ffa8f41666b on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.634109 18647 status_update_manager_process.hpp:414] Creating operation status update stream 832dfe96-bab8-4da6-b7ab-7ffa8f41666b checkpoint=true
I0813 04:34:19.634131 18640 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:19.634572 18647 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for operation UUID 832dfe96-bab8-4da6-b7ab-7ffa8f41666b on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.684286 18647 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for operation UUID 832dfe96-bab8-4da6-b7ab-7ffa8f41666b on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.684617 18647 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for stream ea7a307a-fe22-4390-9de4-8211e4d6cd29
I0813 04:34:19.684684 18647 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: e67d66e5-ffb2-4d55-899c-c05ee24de272) for operation UUID ea7a307a-fe22-4390-9de4-8211e4d6cd29 on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.685215 18625 http_connection.hpp:131] Sending 2 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:19.686074 18641 process.cpp:3671] Handling HTTP event for process 'slave(1223)' with path: '/slave(1223)/api/v1/resource_provider'
I0813 04:34:19.724195 18635 http.cpp:1115] HTTP POST for /slave(1223)/api/v1/resource_provider from 172.17.0.2:57298
I0813 04:34:19.725098 18627 slave.cpp:8417] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) for framework  (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0813 04:34:19.725311 18627 slave.cpp:8870] Updating the state of operation with no ID (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0813 04:34:19.725380 18627 slave.cpp:8624] Forwarding status update of operation with no ID (operation_uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) for an operator API call
I0813 04:34:19.725754 18644 master.cpp:12253] Updating the state of operation '' (uuid: 832dfe96-bab8-4da6-b7ab-7ffa8f41666b) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0813 04:34:19.726296 18642 slave.cpp:4346] Ignoring new checkpointed resources and operations identical to the current version
I0813 04:34:19.727577 18638 provider.cpp:481] Received ACKNOWLEDGE_OPERATION_STATUS event
I0813 04:34:19.734469 18647 status_update_manager_process.hpp:490] Cleaning up operation status update stream ea7a307a-fe22-4390-9de4-8211e4d6cd29
I0813 04:34:19.734683 18647 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for stream 832dfe96-bab8-4da6-b7ab-7ffa8f41666b
I0813 04:34:19.734748 18647 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: e45fef70-8b92-49ae-8256-e4f3b716448b) for operation UUID 832dfe96-bab8-4da6-b7ab-7ffa8f41666b on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:19.810040 18647 status_update_manager_process.hpp:490] Cleaning up operation status update stream 832dfe96-bab8-4da6-b7ab-7ffa8f41666b
I0813 04:34:20.253628 18630 master.cpp:1410] Framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 disconnected
I0813 04:34:20.253667 18630 master.cpp:3360] Deactivating framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:20.254077 18632 hierarchical.cpp:475] Deactivated framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:20.254431 18636 slave.cpp:924] Agent terminating
I0813 04:34:20.255311 18636 manager.cpp:163] Terminating resource provider 0e40be87-7324-473f-a67a-3f3738b71e68
I0813 04:34:20.255450 18632 hierarchical.cpp:1218] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,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_6zr205/2GB-47fc2809-a9ec-4e66-9a85-4d10e9f4cbd1,test)]:2048, allocated: {}) on agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 from framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:20.255693 18630 master.cpp:12706] Removing offer f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-O6
I0813 04:34:20.255789 18630 master.cpp:3337] Disconnecting framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:20.255848 18630 master.cpp:1425] Giving framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253 0ns to failover
I0813 04:34:20.256047 18630 master.cpp:1295] Agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c) disconnected
I0813 04:34:20.256072 18630 master.cpp:3397] Disconnecting agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
I0813 04:34:20.256148 18630 master.cpp:3416] Deactivating agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 at slave(1223)@172.17.0.2:39253 (21cdb951747c)
E0813 04:34:20.256196 18646 http_connection.hpp:452] End-Of-File received
I0813 04:34:20.256253 18635 hierarchical.cpp:799] Agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0 deactivated
I0813 04:34:20.256557 18627 master.cpp:10206] Framework failover timeout, removing framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:20.256587 18627 master.cpp:11205] Removing framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000 (default) at scheduler-2937b135-38d1-45df-a64b-4bafddc775d0@172.17.0.2:39253
I0813 04:34:20.256640 18646 http_connection.hpp:217] Re-detecting endpoint
I0813 04:34:20.257026 18639 hierarchical.cpp:1432] Allocation paused
I0813 04:34:20.257095 18646 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0813 04:34:20.257148 18646 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
I0813 04:34:20.257180 18640 provider.cpp:471] Disconnected from resource provider manager
I0813 04:34:20.257217 18646 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:20.257352 18641 status_update_manager_process.hpp:379] Pausing operation status update manager
I0813 04:34:20.257491 18639 hierarchical.cpp:417] Removed framework f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-0000
I0813 04:34:20.257544 18639 hierarchical.cpp:1442] Allocation resumed
I0813 04:34:20.258575 18624 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
I0813 04:34:20.258621 18624 containerizer.cpp:3318] 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
I0813 04:34:20.259114 18624 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:20.260483 18643 hierarchical.cpp:1508] Performed allocation for 1 agents in 133988ns
I0813 04:34:20.260932 18644 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:20.261404 18639 provider.cpp:459] Connected to resource provider manager
I0813 04:34:20.261981 18629 http_connection.hpp:131] Sending 1 call to http://172.17.0.2:39253/slave(1223)/api/v1/resource_provider
I0813 04:34:20.262692 18648 process.cpp:2781] Returning '404 Not Found' for '/slave(1223)/api/v1/resource_provider'
E0813 04:34:20.263932 18626 provider.cpp:702] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
I0813 04:34:20.311816 18645 hierarchical.cpp:1508] Performed allocation for 1 agents in 193337ns
I0813 04:34:20.363159 18643 hierarchical.cpp:1508] Performed allocation for 1 agents in 117863ns
I0813 04:34:20.363723 18631 containerizer.cpp:3157] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
I0813 04:34:20.365234 18647 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
I0813 04:34:20.367848 18637 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'
I0813 04:34:20.368058 18630 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-BIGnGV/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0813 04:34:20.368281 18633 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0813 04:34:20.371042 18648 process.cpp:2781] Returning '404 Not Found' for '/slave(1223)/api/v1'
I0813 04:34:20.381745 18623 master.cpp:1135] Master terminating
I0813 04:34:20.382470 18643 hierarchical.cpp:775] Removed all filters for agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
I0813 04:34:20.382498 18643 hierarchical.cpp:650] Removed agent f24ab1c4-6a4c-4059-930e-6d4f0fb7294e-S0
[       OK ] CSIVersion/StorageLocalResourceProviderTest.OperatorOperationsWithResourceProviderResources/v1 (2647 ms)
[----------] 50 tests from CSIVersion/StorageLocalResourceProviderTest (91038 ms total)

[----------] Global test environment tear-down
[==========] 2299 tests from 218 test cases ran. (1106641 ms total)
[  PASSED  ] 2297 tests.
[  FAILED  ] 2 tests, listed below:
[  FAILED  ] ContentType/MasterAPITest.DrainAgentUnreachable/0, where GetParam() = application/x-protobuf
[  FAILED  ] ContentType/MasterAPITest.DrainAgentUnreachable/1, where GetParam() = application/json

 2 FAILED TESTS
  YOU HAVE 32 DISABLED TESTS

I0813 04:34:20.478269 18648 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-1565665126-12204
Untagged: mesos-1565665126-12204:latest
Deleted: sha256:59a6a63322f9fadc34fcdcff17187ece3d5db6f2ebc62d8afe96d5d84c6353fe
Deleted: sha256:6353e75916fd1aba963515a12c8578c4c2ea581e3486306cf60241e2219a7875
Deleted: sha256:a9f64911d726e01b29d04f3cbc3709e63015a1718e7d5d9e4729f375d22b9560
Deleted: sha256:bf273c548ece74eea01b2bda00a50b6d64903d4cde37bf98140b4c9cd8a1da20
Deleted: sha256:74b9062ddaa2c13b1086512dbe7c8959d4e9a15858ce4ac8c9ef7419ec5b7473
Deleted: sha256:d8510608752cf4bdf7368e8d045a2909749de012e41b78fb076e51200586b629
Deleted: sha256:b856e9ff11316730929234629562bddf52c04735267a99bee0283c9ebfd81e25
Deleted: sha256:86434bc4db7619f8a5826acd284fd831bc269549d257773967b12294ae9e2fb5
Deleted: sha256:f4931af89aa1c6215e3370aa36f58b7b42fda1765b6b86b4180d9af90dcad520
Deleted: sha256:952fba26ca565a954dac3c04f52a4121f0cb96696479a42e1995164081b33000
Deleted: sha256:4a0277a30402ba57ba23f1785897433161d396da47e00e22c2e9eb74a60c72fe
Deleted: sha256:5463ba01857b88a15400288bc37acff6a045b98172957805db0c72ed70c5e3ba
Deleted: sha256:1ae0764e5cb5abf5e5555ee8666cb7f5704448bd0f521c9f6af1025de9798bd1
Deleted: sha256:765c0b5bae8a8b04c490c988bf27f7d362f064af801d906b3e9d280dc6bb2e03
Deleted: sha256:12b8d56703286efcc38016fdb05b25d8df2bb4062b44c2389c577fdfc23011ce
Deleted: sha256:a6c6ccfda2eba5413f9a902eb939e22abf139c4e73319ef56b585f0c791d9bb6
Deleted: sha256:418a13dc5c03fc44bc8f1a2df629abc974027c2db1fa10bcb4fe11b6fd658cd5
Deleted: sha256:96c4ddafb5b2384b443e1384d3d4f8a8a17872b5b68902917e12ee47aeba6ca4
Deleted: sha256:e3487baa8b2e1e86f1fe9480e0cf329e5e2938123a14bd60a6b1ee275322ebb8
Deleted: sha256:c894c0e3864b23198b9c77c166e2e9bc67526ef03e5c8ccd927eecaedd29ce76
Deleted: sha256:1a6d82161096ecd1bf02720268cb1a47bbae59cd7afb16987231755e02eaff9e
Deleted: sha256:7f87f78750c90dfd9615d73a23b50d62fb80d6be4a75df1a0368581d2a52015d
Deleted: sha256:c2e1276856cb4d5c3187700f933157fc165817262108867b905d320d3cb3734c
Deleted: sha256:372cd4896252d735a49467b0ded35f97fd22289e697c5a8cb915d298bf8a71a5
Deleted: sha256:38fd8d3cbb93f70deb02ad10111edf2c3527c79e814041eb1f6805a03210ccc2
Deleted: sha256:194ccf793826c500b3369f77af6da2591b559eb71baa5de9cbac49919b53871e
Deleted: sha256:fe5264f0d14a383f465695af065b906cb644151a8d00c65ea7e364441d497617
Deleted: sha256:770339a42712a6fb2ac175e635abadb0848ab8e317e7a9458055433d90bfb06c
Deleted: sha256:3f835a937e6b4b20cc3aadef5be17f4a264cf5c650bf85b1b39ff3ccfcaf76c2
Deleted: sha256:67bfbe9ecea2b0aac5d1d7acd752fd16c025732d8dd2fc18e46bd1cd0d7dbd90

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

- Mesos Reviewbot


On Aug. 13, 2019, 2:35 a.m., Joseph Wu wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71275/
> -----------------------------------------------------------
> 
> (Updated Aug. 13, 2019, 2:35 a.m.)
> 
> 
> Review request for mesos, Benjamin Bannier, Benno Evers, and Greg Mann.
> 
> 
> Bugs: MESOS-9934
>     https://issues.apache.org/jira/browse/MESOS-9934
> 
> 
> Repository: mesos
> 
> 
> Description
> -------
> 
> This logic was missing from the initial implementation of agent
> draining.  When an agent became unreachable, and then reregistered
> with the master, the master would not properly deactivate or drain
> the agent.
> 
> 
> Diffs
> -----
> 
>   src/master/master.cpp 31c7c97abecb92591369b417e2ef38a99cc09bac 
>   src/tests/api_tests.cpp c2099674e742eaa08134c5e0a7cdab1734808119 
> 
> 
> Diff: https://reviews.apache.org/r/71275/diff/1/
> 
> 
> Testing
> -------
> 
> make check
> 
> 
> Thanks,
> 
> Joseph Wu
> 
>


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