See <https://builds.apache.org/job/Mesos-Reviewbot-Linux/4515/display/redirect>
Changes: ------------------------------------------ [...truncated 52.65 MB...] I1024 20:55:09.787360 18961 authenticator.cpp:232] Received SASL authentication step I1024 20:55:09.787444 18961 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4672c8696740' server FQDN: '4672c8696740' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1024 20:55:09.787473 18961 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I1024 20:55:09.787559 18961 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1024 20:55:09.787600 18961 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4672c8696740' server FQDN: '4672c8696740' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1024 20:55:09.787622 18961 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1024 20:55:09.787640 18961 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1024 20:55:09.787719 18961 authenticator.cpp:318] Authentication success I1024 20:55:09.787998 18974 authenticatee.cpp:299] Authentication success I1024 20:55:09.788146 18982 master.cpp:10626] Successfully authenticated principal 'test-principal' at slave(1247)@172.17.0.2:40021 I1024 20:55:09.788309 18962 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2104)@172.17.0.2:40021 I1024 20:55:09.788851 18969 slave.cpp:1543] Successfully authenticated with master [email protected]:40021 I1024 20:55:09.789966 18969 slave.cpp:1993] Will retry registration in 10.655932ms if necessary I1024 20:55:09.790315 18960 master.cpp:7083] Received register agent message from slave(1247)@172.17.0.2:40021 (4672c8696740) I1024 20:55:09.790870 18960 master.cpp:4189] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal' I1024 20:55:09.792083 18967 master.cpp:7150] Authorized registration of agent at slave(1247)@172.17.0.2:40021 (4672c8696740) I1024 20:55:09.792244 18967 master.cpp:7262] Registering agent at slave(1247)@172.17.0.2:40021 (4672c8696740) with id 30860a38-364e-4415-bc91-e246909d5899-S0 I1024 20:55:09.793364 18977 registrar.cpp:487] Applied 1 operations in 390138ns; attempting to update the registry I1024 20:55:09.794556 18977 registrar.cpp:544] Successfully updated the registry in 0ns I1024 20:55:09.794961 18980 master.cpp:7310] Admitted agent 30860a38-364e-4415-bc91-e246909d5899-S0 at slave(1247)@172.17.0.2:40021 (4672c8696740) I1024 20:55:09.796471 18980 master.cpp:7355] Registered agent 30860a38-364e-4415-bc91-e246909d5899-S0 at slave(1247)@172.17.0.2:40021 (4672c8696740) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] I1024 20:55:09.796722 18975 hierarchical.cpp:959] Added agent 30860a38-364e-4415-bc91-e246909d5899-S0 (4672c8696740) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) I1024 20:55:09.796787 18976 slave.cpp:1576] Registered with master [email protected]:40021; given agent ID 30860a38-364e-4415-bc91-e246909d5899-S0 I1024 20:55:09.797098 18982 task_status_update_manager.cpp:188] Resuming sending task status updates I1024 20:55:09.797397 18975 hierarchical.cpp:1853] Performed allocation for 1 agents in 277043ns I1024 20:55:09.797582 18976 slave.cpp:1611] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_DJB3hU/meta/slaves/30860a38-364e-4415-bc91-e246909d5899-S0/slave.info' I1024 20:55:09.797809 18981 status_update_manager_process.hpp:385] Resuming operation status update manager I1024 20:55:09.799525 18976 slave.cpp:1663] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"/KuW1q2uT3uNSYQCa2DNMg=="},"slave_id":{"value":"30860a38-364e-4415-bc91-e246909d5899-S0"},"update_oversubscribed_resources":false} I1024 20:55:09.800901 18969 master.cpp:8474] Ignoring update on agent 30860a38-364e-4415-bc91-e246909d5899-S0 at slave(1247)@172.17.0.2:40021 (4672c8696740) as it reports no changes I1024 20:55:09.806628 18965 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1' I1024 20:55:09.808526 18963 http.cpp:1115] HTTP POST for /slave(1247)/api/v1 from 172.17.0.2:47852 I1024 20:55:09.809170 18963 http.cpp:2146] Processing GET_CONTAINERS call I1024 20:55:09.818123 18971 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1024 20:55:09.822124 18961 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1' I1024 20:55:09.823964 18963 http.cpp:1115] HTTP POST for /slave(1247)/api/v1 from 172.17.0.2:47854 I1024 20:55:09.825199 18963 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' I1024 20:55:09.826761 18962 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_DJB3hU/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1024 20:55:09.827953 18969 containerizer.cpp:1396] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1024 20:55:09.829357 18969 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 STARTING to PROVISIONING after 0ns I1024 20:55:09.831183 18969 containerizer.cpp:1574] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_wfaepD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' I1024 20:55:09.831296 18969 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 after 0ns I1024 20:55:09.836331 18964 containerizer.cpp:2100] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_WnYUab","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_DJB3hU/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-MVTevh/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_DJB3hU/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="89" --pipe_write="90" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_wfaepD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' I1024 20:55:09.851122 18964 launcher.cpp:145] Forked child with pid '851' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1024 20:55:09.852311 18964 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 after 0ns I1024 20:55:09.853947 18964 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 after 0ns I1024 20:55:09.854374 18963 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_DJB3hU/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1024 20:55:09.855902 18979 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 after 0ns I1024 20:55:09.860882 18972 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' I1024 20:55:09.861146 18972 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-MVTevh/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE I1024 20:55:10.422204 18974 hierarchical.cpp:1853] Performed allocation for 1 agents in 294733ns I1024 20:55:10.453951 18963 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-MVTevh/endpoint.sock' with CSI v1 I1024 20:55:10.473441 18979 hierarchical.cpp:1853] Performed allocation for 1 agents in 238155ns I1024 20:55:10.476179 855 test_csi_plugin.cpp:909] ProbeRequest '{}' I1024 20:55:10.479161 18969 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' I1024 20:55:10.483289 856 test_csi_plugin.cpp:895] GetPluginCapabilitiesRequest '{}' I1024 20:55:10.483997 18965 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1' I1024 20:55:10.485893 18976 http.cpp:1115] HTTP POST for /slave(1247)/api/v1 from 172.17.0.2:47900 I1024 20:55:10.486707 18976 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' I1024 20:55:10.489558 856 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}' I1024 20:55:10.490068 855 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}' I1024 20:55:10.491931 18973 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {"name":".","vendorVersion":"1.10.0"} I1024 20:55:10.492620 18973 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {"name":".","vendorVersion":"1.10.0"} I1024 20:55:10.495755 856 test_csi_plugin.cpp:1105] ControllerGetCapabilitiesRequest '{}' I1024 20:55:10.500097 855 test_csi_plugin.cpp:1241] NodeGetCapabilitiesRequest '{}' I1024 20:55:10.504297 856 test_csi_plugin.cpp:1255] NodeGetInfoRequest '{}' I1024 20:55:10.507292 18975 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' I1024 20:55:10.507519 18969 status_update_manager_process.hpp:379] Pausing operation status update manager I1024 20:55:10.508198 18968 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:40021/slave(1247)/api/v1/resource_provider I1024 20:55:10.512682 18965 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:40021/slave(1247)/api/v1/resource_provider I1024 20:55:10.513643 18964 provider.cpp:476] Connected to resource provider manager I1024 20:55:10.514523 18976 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:40021/slave(1247)/api/v1/resource_provider I1024 20:55:10.516144 18960 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1/resource_provider' I1024 20:55:10.518939 18967 http.cpp:1115] HTTP POST for /slave(1247)/api/v1/resource_provider from 172.17.0.2:47904 I1024 20:55:10.520145 18975 manager.cpp:813] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_WnYUab","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":0.0},"type":"org.apache.mesos.rp.local.storage"} I1024 20:55:10.524889 18981 hierarchical.cpp:1853] Performed allocation for 1 agents in 265410ns I1024 20:55:10.577105 18974 hierarchical.cpp:1853] Performed allocation for 1 agents in 276188ns I1024 20:55:10.578735 18962 slave.cpp:8483] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"3acedc9c-9db0-4261-aa2a-296dd6ceddab"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_WnYUab","--available_capacity=2GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":0.0},"type":"org.apache.mesos.rp.local.storage"}' I1024 20:55:10.581455 18979 provider.cpp:498] Received SUBSCRIBED event I1024 20:55:10.581565 18979 provider.cpp:1309] Subscribed with ID 3acedc9c-9db0-4261-aa2a-296dd6ceddab I1024 20:55:10.583191 18975 status_update_manager_process.hpp:314] Recovering operation status update manager I1024 20:55:10.629182 18973 hierarchical.cpp:1853] Performed allocation for 1 agents in 397415ns I1024 20:55:10.678938 18977 provider.cpp:790] Reconciling storage pools and volumes I1024 20:55:10.680932 18968 hierarchical.cpp:1853] Performed allocation for 1 agents in 264247ns I1024 20:55:10.683195 856 test_csi_plugin.cpp:1050] ListVolumesRequest '{}' I1024 20:55:10.686404 18970 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 30860a38-364e-4415-bc91-e246909d5899-S0 I1024 20:55:10.686945 18970 provider.cpp:748] Resource provider 3acedc9c-9db0-4261-aa2a-296dd6ceddab is in READY state I1024 20:55:10.686947 18960 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:40021/slave(1247)/api/v1/resource_provider I1024 20:55:10.687058 18978 status_update_manager_process.hpp:385] Resuming operation status update manager I1024 20:55:10.687948 18969 provider.cpp:1235] Updating profiles { test } for resource provider 3acedc9c-9db0-4261-aa2a-296dd6ceddab I1024 20:55:10.688925 18973 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1/resource_provider' I1024 20:55:10.689620 18961 provider.cpp:790] Reconciling storage pools and volumes I1024 20:55:10.691928 18970 http.cpp:1115] HTTP POST for /slave(1247)/api/v1/resource_provider from 172.17.0.2:47902 I1024 20:55:10.692898 18960 manager.cpp:1045] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 3acedc9c-9db0-4261-aa2a-296dd6ceddab I1024 20:55:10.693217 18969 slave.cpp:8483] Handling resource provider message 'UPDATE_STATE: 3acedc9c-9db0-4261-aa2a-296dd6ceddab {}' I1024 20:55:10.693367 18969 slave.cpp:8603] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] I1024 20:55:10.693307 856 test_csi_plugin.cpp:1050] ListVolumesRequest '{}' I1024 20:55:10.694214 855 test_csi_plugin.cpp:1078] GetCapacityRequest '{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}' I1024 20:55:10.696472 18982 hierarchical.cpp:1110] Grew agent 30860a38-364e-4415-bc91-e246909d5899-S0 by {} (total), { } (used) I1024 20:55:10.697093 18982 hierarchical.cpp:1067] Agent 30860a38-364e-4415-bc91-e246909d5899-S0 (4672c8696740) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] W1024 20:55:10.698320 18959 process.cpp:2877] Attempted to spawn already running process [email protected]:40021 I1024 20:55:10.700568 18959 sched.cpp:239] Version: 1.10.0 I1024 20:55:10.700789 18978 provider.cpp:808] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' to the total resources I1024 20:55:10.702138 18971 sched.cpp:343] New master detected at [email protected]:40021 I1024 20:55:10.702425 18971 sched.cpp:408] Authenticating with master [email protected]:40021 I1024 20:55:10.702466 18971 sched.cpp:415] Using default CRAM-MD5 authenticatee I1024 20:55:10.703107 18980 hierarchical.cpp:1853] Performed allocation for 1 agents in 338535ns I1024 20:55:10.703222 18973 authenticatee.cpp:121] Creating new client SASL connection I1024 20:55:10.703987 18963 master.cpp:10594] Authenticating [email protected]:40021 I1024 20:55:10.704252 18981 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2105)@172.17.0.2:40021 I1024 20:55:10.704799 18965 authenticator.cpp:98] Creating new server SASL connection I1024 20:55:10.705314 18983 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 I1024 20:55:10.705382 18983 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' I1024 20:55:10.705651 18982 authenticator.cpp:204] Received SASL authentication start I1024 20:55:10.705760 18982 authenticator.cpp:326] Authentication requires more steps I1024 20:55:10.706045 18961 authenticatee.cpp:259] Received SASL authentication step I1024 20:55:10.706333 18962 authenticator.cpp:232] Received SASL authentication step I1024 20:55:10.706396 18962 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4672c8696740' server FQDN: '4672c8696740' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false I1024 20:55:10.706424 18962 auxprop.cpp:181] Looking up auxiliary property '*userPassword' I1024 20:55:10.706502 18962 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' I1024 20:55:10.706547 18962 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4672c8696740' server FQDN: '4672c8696740' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true I1024 20:55:10.706571 18962 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true I1024 20:55:10.706588 18962 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true I1024 20:55:10.706620 18962 authenticator.cpp:318] Authentication success I1024 20:55:10.706816 18964 authenticatee.cpp:299] Authentication success I1024 20:55:10.706969 18968 master.cpp:10626] Successfully authenticated principal 'test-principal' at [email protected]:40021 I1024 20:55:10.707031 18960 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2105)@172.17.0.2:40021 I1024 20:55:10.707664 18970 sched.cpp:520] Successfully authenticated with master [email protected]:40021 I1024 20:55:10.707762 18970 sched.cpp:835] Sending SUBSCRIBE call to [email protected]:40021 I1024 20:55:10.707929 18970 sched.cpp:870] Will retry registration in 926.337301ms if necessary I1024 20:55:10.708243 18979 master.cpp:2909] Received SUBSCRIBE call for framework 'default' at [email protected]:40021 I1024 20:55:10.708297 18979 master.cpp:2241] Authorizing framework principal 'test-principal' to receive offers for roles '{ storage/default-role }' I1024 20:55:10.709060 18974 master.cpp:2996] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ] I1024 20:55:10.710942 18974 master.cpp:10824] Adding framework 30860a38-364e-4415-bc91-e246909d5899-0000 (default) at [email protected]:40021 with roles { } suppressed I1024 20:55:10.711458 18977 sched.cpp:751] Framework registered with 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:10.711525 18977 sched.cpp:770] Scheduler::registered took 33027ns I1024 20:55:10.712205 18980 hierarchical.cpp:700] Added framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:10.713423 18980 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.036377ms I1024 20:55:10.714030 18973 master.cpp:10409] Sending offers [ 30860a38-364e-4415-bc91-e246909d5899-O0 ] to framework 30860a38-364e-4415-bc91-e246909d5899-0000 (default) at [email protected]:40021 I1024 20:55:10.714952 18963 sched.cpp:934] Scheduler::resourceOffers took 190771ns I1024 20:55:10.715526 18981 master.cpp:6227] Processing DECLINE call for offers: [ 30860a38-364e-4415-bc91-e246909d5899-O0 ] for framework 30860a38-364e-4415-bc91-e246909d5899-0000 (default) at [email protected]:40021 with 5 seconds filter I1024 20:55:10.716428 18965 hierarchical.cpp:1576] 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], offered or allocated: {}) on agent 30860a38-364e-4415-bc91-e246909d5899-S0 from framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:10.716503 18981 master.cpp:12706] Removing offer 30860a38-364e-4415-bc91-e246909d5899-O0 I1024 20:55:10.718071 18965 hierarchical.cpp:1625] Framework 30860a38-364e-4415-bc91-e246909d5899-0000 filtered agent 30860a38-364e-4415-bc91-e246909d5899-S0 for 5secs I1024 20:55:10.821286 18978 provider.cpp:2217] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' and 0 operations to agent 30860a38-364e-4415-bc91-e246909d5899-S0 I1024 20:55:10.822278 18983 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:40021/slave(1247)/api/v1/resource_provider I1024 20:55:10.824492 18968 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1/resource_provider' I1024 20:55:10.866834 18969 http.cpp:1115] HTTP POST for /slave(1247)/api/v1/resource_provider from 172.17.0.2:47902 I1024 20:55:10.868288 18960 manager.cpp:1045] Received UPDATE_STATE call with resources '[{"disk":{"source":{"profile":"test","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"3acedc9c-9db0-4261-aa2a-296dd6ceddab"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]' and 0 operations from resource provider 3acedc9c-9db0-4261-aa2a-296dd6ceddab I1024 20:55:10.869045 18970 slave.cpp:8483] Handling resource provider message 'UPDATE_STATE: 3acedc9c-9db0-4261-aa2a-296dd6ceddab disk(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048' I1024 20:55:10.869279 18970 slave.cpp:8603] 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 I1024 20:55:10.873262 18971 hierarchical.cpp:1067] Agent 30860a38-364e-4415-bc91-e246909d5899-S0 (4672c8696740) 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 I1024 20:55:10.875288 18971 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.667444ms I1024 20:55:10.876541 18973 master.cpp:10409] Sending offers [ 30860a38-364e-4415-bc91-e246909d5899-O1 ] to framework 30860a38-364e-4415-bc91-e246909d5899-0000 (default) at [email protected]:40021 I1024 20:55:10.877698 18963 sched.cpp:934] Scheduler::resourceOffers took 122392ns I1024 20:55:10.888023 18965 master.cpp:4719] Processing ACCEPT call for offers: [ 30860a38-364e-4415-bc91-e246909d5899-O1 ] on agent 30860a38-364e-4415-bc91-e246909d5899-S0 at slave(1247)@172.17.0.2:40021 (4672c8696740) for framework 30860a38-364e-4415-bc91-e246909d5899-0000 (default) at [email protected]:40021 I1024 20:55:10.888206 18965 master.cpp:4099] 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' I1024 20:55:10.888975 18961 hierarchical.cpp:1853] Performed allocation for 1 agents in 551682ns I1024 20:55:10.890543 18966 master.cpp:12706] Removing offer 30860a38-364e-4415-bc91-e246909d5899-O1 I1024 20:55:10.891163 18966 master.cpp:6011] 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 30860a38-364e-4415-bc91-e246909d5899-0000 (default) at [email protected]:40021 to agent 30860a38-364e-4415-bc91-e246909d5899-S0 at slave(1247)@172.17.0.2:40021 (4672c8696740) I1024 20:55:10.892146 18966 master.cpp:12571] Sending operation '' (uuid: 0e6c9d68-0892-46c5-a423-1ca1909f95a6) to agent 30860a38-364e-4415-bc91-e246909d5899-S0 at slave(1247)@172.17.0.2:40021 (4672c8696740) I1024 20:55:10.892755 18967 hierarchical.cpp:1777] Allocation paused I1024 20:55:10.893025 18976 slave.cpp:4352] Ignoring new checkpointed resources and operations identical to the current version I1024 20:55:10.893455 18967 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role):1024; cpus(allocated: storage/default-role):2; mem(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, offered or allocated: disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:2048) on agent 30860a38-364e-4415-bc91-e246909d5899-S0 from framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:10.895102 18967 hierarchical.cpp:1625] Framework 30860a38-364e-4415-bc91-e246909d5899-0000 filtered agent 30860a38-364e-4415-bc91-e246909d5899-S0 for 5secs I1024 20:55:10.895507 18967 hierarchical.cpp:1787] Allocation resumed I1024 20:55:10.897069 18971 provider.cpp:498] Received APPLY_OPERATION event I1024 20:55:10.897145 18971 provider.cpp:1351] Received CREATE_DISK operation '' (uuid: 0e6c9d68-0892-46c5-a423-1ca1909f95a6) I1024 20:55:10.941820 18963 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:10.942054 18963 hierarchical.cpp:1853] Performed allocation for 1 agents in 916103ns I1024 20:55:10.994119 18983 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:10.994372 18983 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.085321ms I1024 20:55:11.046619 18978 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.046865 18978 hierarchical.cpp:1853] Performed allocation for 1 agents in 911941ns I1024 20:55:11.047796 18962 v1_volume_manager.cpp:293] Creating volume with name '0e6c9d68-0892-46c5-a423-1ca1909f95a6' I1024 20:55:11.051142 856 test_csi_plugin.cpp:922] CreateVolumeRequest '{"name":"0e6c9d68-0892-46c5-a423-1ca1909f95a6","capacityRange":{"requiredBytes":"2147483648","limitBytes":"2147483648"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}' I1024 20:55:11.098803 18976 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.099038 18976 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.044439ms I1024 20:55:11.151253 18969 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.151501 18969 hierarchical.cpp:1853] Performed allocation for 1 agents in 961163ns I1024 20:55:11.203233 18970 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.203480 18970 hierarchical.cpp:1853] Performed allocation for 1 agents in 936973ns I1024 20:55:11.255077 18967 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.255228 18967 hierarchical.cpp:1853] Performed allocation for 1 agents in 582992ns I1024 20:55:11.306996 18974 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.307214 18974 hierarchical.cpp:1853] Performed allocation for 1 agents in 643870ns I1024 20:55:11.359441 18975 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.359730 18975 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.06271ms I1024 20:55:11.411656 18980 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.411921 18980 hierarchical.cpp:1853] Performed allocation for 1 agents in 703457ns I1024 20:55:11.463811 18973 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.464012 18973 hierarchical.cpp:1853] Performed allocation for 1 agents in 789176ns I1024 20:55:11.488847 18981 provider.cpp:1653] 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_WnYUab/2GB-0e6c9d68-0892-46c5-a423-1ca1909f95a6,test)]:2048' for operation (uuid: 0e6c9d68-0892-46c5-a423-1ca1909f95a6) I1024 20:55:11.516187 18978 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.516413 18978 hierarchical.cpp:1853] Performed allocation for 1 agents in 912086ns I1024 20:55:11.568629 18971 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.568861 18971 hierarchical.cpp:1853] Performed allocation for 1 agents in 879850ns I1024 20:55:11.620796 18962 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.621058 18962 hierarchical.cpp:1853] Performed allocation for 1 agents in 900906ns I1024 20:55:11.672811 18982 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.672971 18982 hierarchical.cpp:1853] Performed allocation for 1 agents in 635983ns I1024 20:55:11.680193 18972 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: d7db5a45-e617-480d-88d5-3899e6adcada) for operation UUID 0e6c9d68-0892-46c5-a423-1ca1909f95a6 of framework '30860a38-364e-4415-bc91-e246909d5899-0000' on agent 30860a38-364e-4415-bc91-e246909d5899-S0 I1024 20:55:11.680279 18972 status_update_manager_process.hpp:414] Creating operation status update stream 0e6c9d68-0892-46c5-a423-1ca1909f95a6 checkpoint=true I1024 20:55:11.680733 18972 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: d7db5a45-e617-480d-88d5-3899e6adcada) for operation UUID 0e6c9d68-0892-46c5-a423-1ca1909f95a6 of framework '30860a38-364e-4415-bc91-e246909d5899-0000' on agent 30860a38-364e-4415-bc91-e246909d5899-S0 I1024 20:55:11.725507 18966 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.725792 18966 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.168916ms I1024 20:55:11.778535 18976 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.778836 18976 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.14643ms I1024 20:55:11.830776 18960 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.830969 18960 hierarchical.cpp:1853] Performed allocation for 1 agents in 627974ns I1024 20:55:11.882606 18970 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.882735 18970 hierarchical.cpp:1853] Performed allocation for 1 agents in 519140ns I1024 20:55:11.906769 18972 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: d7db5a45-e617-480d-88d5-3899e6adcada) for operation UUID 0e6c9d68-0892-46c5-a423-1ca1909f95a6 of framework '30860a38-364e-4415-bc91-e246909d5899-0000' on agent 30860a38-364e-4415-bc91-e246909d5899-S0 I1024 20:55:11.907827 18974 http_connection.hpp:131] Sending UPDATE_OPERATION_STATUS call to http://172.17.0.2:40021/slave(1247)/api/v1/resource_provider I1024 20:55:11.909870 18977 process.cpp:3671] Handling HTTP event for process 'slave(1247)' with path: '/slave(1247)/api/v1/resource_provider' I1024 20:55:11.935139 18973 hierarchical.cpp:2661] Filtered offer with ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 for role storage/default-role of framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.935390 18973 hierarchical.cpp:1853] Performed allocation for 1 agents in 1.091504ms I1024 20:55:11.955178 18965 http.cpp:1115] HTTP POST for /slave(1247)/api/v1/resource_provider from 172.17.0.2:47902 I1024 20:55:11.957244 18962 slave.cpp:8483] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 0e6c9d68-0892-46c5-a423-1ca1909f95a6) for framework 30860a38-364e-4415-bc91-e246909d5899-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)' I1024 20:55:11.957607 18962 slave.cpp:8936] Updating the state of operation with no ID (uuid: 0e6c9d68-0892-46c5-a423-1ca1909f95a6) for framework 30860a38-364e-4415-bc91-e246909d5899-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED) I1024 20:55:11.958295 18962 slave.cpp:8690] Forwarding status update of operation with no ID (operation_uuid: 0e6c9d68-0892-46c5-a423-1ca1909f95a6) for framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.958937 18982 master.cpp:12223] Updating the state of operation '' (uuid: 0e6c9d68-0892-46c5-a423-1ca1909f95a6) for framework 30860a38-364e-4415-bc91-e246909d5899-0000 (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED) I1024 20:55:11.961114 18969 slave.cpp:4352] Ignoring new checkpointed resources and operations identical to the current version I1024 20:55:11.962733 18976 hierarchical.cpp:1312] Updated allocation of framework 30860a38-364e-4415-bc91-e246909d5899-0000 on agent 30860a38-364e-4415-bc91-e246909d5899-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_WnYUab/2GB-0e6c9d68-0892-46c5-a423-1ca1909f95a6,test)]:2048 I1024 20:55:11.963218 18976 hierarchical.cpp:1576] Recovered disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_WnYUab/2GB-0e6c9d68-0892-46c5-a423-1ca1909f95a6,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_WnYUab/2GB-0e6c9d68-0892-46c5-a423-1ca1909f95a6,test)]:2048, offered or allocated: {}) on agent 30860a38-364e-4415-bc91-e246909d5899-S0 from framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:11.963647 18963 provider.cpp:498] Received ACKNOWLEDGE_OPERATION_STATUS event I1024 20:55:11.964002 18964 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: d7db5a45-e617-480d-88d5-3899e6adcada) for stream 0e6c9d68-0892-46c5-a423-1ca1909f95a6 I1024 20:55:11.964162 18964 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: d7db5a45-e617-480d-88d5-3899e6adcada) for operation UUID 0e6c9d68-0892-46c5-a423-1ca1909f95a6 of framework '30860a38-364e-4415-bc91-e246909d5899-0000' on agent 30860a38-364e-4415-bc91-e246909d5899-S0 Build timed out (after 240 minutes). Marking the build as failed. I1024 20:55:11.990221 18978 hierarchical.cpp:1853] Performed allocation for 1 agents in 2.524763ms I1024 20:55:11.991092 18971 master.cpp:10409] Sending offers [ 30860a38-364e-4415-bc91-e246909d5899-O2 ] to framework 30860a38-364e-4415-bc91-e246909d5899-0000 (default) at [email protected]:40021 I1024 20:55:11.991920 18965 sched.cpp:934] Scheduler::resourceOffers took 121168ns I1024 20:55:11.996932 18960 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1' I1024 20:55:11.999856 18977 http.cpp:1115] HTTP POST for /master/api/v1 from 172.17.0.2:48050 I1024 20:55:12.000581 18977 http.cpp:263] Processing call RESERVE_RESOURCES I1024 20:55:12.002497 18977 master.cpp:3811] 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_WnYUab/2GB-0e6c9d68-0892-46c5-a423-1ca1909f95a6,test)]:2048' I1024 20:55:12.004771 18978 sched.cpp:960] Rescinded offer 30860a38-364e-4415-bc91-e246909d5899-O2 I1024 20:55:12.004890 18978 sched.cpp:971] Scheduler::offerRescinded took 35026ns I1024 20:55:12.005657 18971 hierarchical.cpp:1576] Recovered ports(allocated: storage/default-role):[31000-32000]; disk(allocated: storage/default-role)(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_WnYUab/2GB-0e6c9d68-0892-46c5-a423-1ca1909f95a6,test)]:2048; cpus(allocated: storage/default-role):2; mem(allocated: storage/default-role):1024; disk(allocated: storage/default-role):1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_OperatorOperationsWithResourceProviderResources_v1_WnYUab/2GB-0e6c9d68-0892-46c5-a423-1ca1909f95a6,test)]:2048, offered or allocated: {}) on agent 30860a38-364e-4415-bc91-e246909d5899-S0 from framework 30860a38-364e-4415-bc91-e246909d5899-0000 I1024 20:55:12.005966 18963 master.cpp:12706] Removing offer 30860a38-364e-4415-bc91-e246909d5899-O2 I1024 20:55:12.007912 18971 hierarchical.cpp:1625] Framework 30860a38-364e-4415-bc91-e246909d5899-0000 filtered agent 30860a38-364e-4415-bc91-e246909d5899-S0 for 5secs I1024 20:55:12.011464 18968 master.cpp:12571] Sending operation '' (uuid: 8bbdb770-4f8b-49c2-8057-729f533bd104) to agent 30860a38-364e-4415-bc91-e246909d5899-S0 at slave(1247)@172.17.0.2:40021 (4672c8696740) I1024 20:55:12.012336 18982 slave.cpp:4352] Ignoring new checkpointed resources and operations identical to the current version I1024 20:55:12.016911 18975 provider.cpp:498] Received APPLY_OPERATION event I1024 20:55:12.016989 18975 provider.cpp:1351] Received RESERVE operation '' (uuid: 8bbdb770-4f8b-49c2-8057-729f533bd104) I1024 20:55:12.042696 18964 status_update_manager_process.hpp:490] Cleaning up operation status update stream 0e6c9d68-0892-46c5-a423-1ca1909f95a6 I1024 20:55:12.269995 18976 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: d7174f3e-87d0-4f6f-812a-b4e313546e27) for operation UUID 8bbdb770-4f8b-49c2-8057-729f533bd104 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 I1024 20:55:12.270151 18976 status_update_manager_process.hpp:414] Creating operation status update stream 8bbdb770-4f8b-49c2-8057-729f533bd104 checkpoint=true I1024 20:55:12.270682 18976 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: d7174f3e-87d0-4f6f-812a-b4e313546e27) for operation UUID 8bbdb770-4f8b-49c2-8057-729f533bd104 on agent 30860a38-364e-4415-bc91-e246909d5899-S0 Build was aborted
