You are viewing a plain text version of this content. The canonical link for it is here.
Posted to builds@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2020/08/18 09:06:42 UTC
Build failed in Jenkins: Mesos-Buildbot-ARM » cmake,clang,--verbose --disable-libtool-wrappers --disable-java --disable-python --disable-parallel-test-execution,GLOG_v=1 MESOS_VERBOSE=1 MESOS_TEST_AWAIT_TIMEOUT=60secs JOBS=16 GTEST_FILTER=-DiskQuotaTest.SlaveRecovery,arm1 #1773
See <https://builds.apache.org/job/Mesos-Buildbot-ARM/BUILDTOOL=cmake,COMPILER=clang,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--disable-java%20--disable-python%20--disable-parallel-test-execution,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1%20%20MESOS_TEST_AWAIT_TIMEOUT=60secs%20JOBS=16%20GTEST_FILTER=-DiskQuotaTest.SlaveRecovery,label_exp=arm1/1773/display/redirect?page=changes>
Changes:
[zhq527725] Enabled the `volume/csi` isolator in `MesosContainerizer`.
------------------------------------------
[...truncated 48.22 MB...]
3: I0818 09:06:32.175935 18378 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
3: I0818 09:06:32.176295 18378 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
3: I0818 09:06:32.176602 18378 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
3: I0818 09:06:32.176899 18378 master.cpp:632] Authorization enabled
3: I0818 09:06:32.177623 18405 whitelist_watcher.cpp:77] No whitelist given
3: I0818 09:06:32.177680 18440 hierarchical.cpp:634] Initialized hierarchical allocator process
3: I0818 09:06:32.184479 18362 master.cpp:2165] Elected as the leading master!
3: I0818 09:06:32.184535 18362 master.cpp:1661] Recovering from registrar
3: I0818 09:06:32.184828 18399 registrar.cpp:339] Recovering registrar
3: I0818 09:06:32.186031 18399 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
3: I0818 09:06:32.186329 18399 registrar.cpp:487] Applied 1 operations in 112633ns; attempting to update the registry
3: I0818 09:06:32.187676 18399 registrar.cpp:544] Successfully updated the registry in 0ns
3: I0818 09:06:32.187948 18399 registrar.cpp:416] Successfully recovered registrar
3: I0818 09:06:32.188796 18367 master.cpp:1814] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
3: I0818 09:06:32.188841 18434 hierarchical.cpp:673] Skipping recovery of hierarchical allocator: nothing to recover
3: W0818 09:06:32.201746 18360 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:36589
3: I0818 09:06:32.204937 18360 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W0818 09:06:32.206215 18360 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
3: W0818 09:06:32.206285 18360 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W0818 09:06:32.206343 18360 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I0818 09:06:32.206431 18360 provisioner.cpp:294] Using default backend 'copy'
3: I0818 09:06:32.211369 18360 cluster.cpp:533] Creating default 'local' authorizer
3: I0818 09:06:32.215987 18368 slave.cpp:279] Mesos agent started on (1244)@172.17.0.2:36589
3: I0818 09:06:32.216061 18368 slave.cpp:280] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/tB36hW/raWxgH/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/tB36hW/raWxgH/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/tB36hW/raWxgH/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/tB36hW/raWxgH/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/tB36hW/raWxgH/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/tB36hW/raWxgH/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/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/tB36hW/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_pNYyRu" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Po3Qqi" --zk_session_timeout="10secs"
3: I0818 09:06:32.217191 18368 credentials.hpp:73] Loading credential for authentication from '/tmp/tB36hW/raWxgH/credential'
3: I0818 09:06:32.217512 18368 slave.cpp:312] Agent using credential for: test-principal
3: I0818 09:06:32.217567 18368 credentials.hpp:37] Loading credentials for authentication from '/tmp/tB36hW/raWxgH/http_credentials'
3: I0818 09:06:32.217969 18368 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I0818 09:06:32.218626 18415 hierarchical.cpp:1920] Performed allocation for 0 agents in 112773ns
3: I0818 09:06:32.218654 18368 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
3: I0818 09:06:32.221499 18446 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
3: I0818 09:06:32.222157 18368 slave.cpp:627] 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"}]
3: I0818 09:06:32.222553 18368 slave.cpp:635] Agent attributes: [ ]
3: I0818 09:06:32.222594 18368 slave.cpp:644] Agent hostname: 46c8b6126089
3: I0818 09:06:32.222904 18366 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0818 09:06:32.222946 18407 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0818 09:06:32.226836 18422 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Po3Qqi/meta'
3: I0818 09:06:32.227196 18372 slave.cpp:7723] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Po3Qqi/meta', beginning agent recovery
3: I0818 09:06:32.228286 18393 task_status_update_manager.cpp:207] Recovering task status update manager
3: I0818 09:06:32.229027 18393 containerizer.cpp:830] Recovering Mesos containers
3: I0818 09:06:32.229626 18393 containerizer.cpp:1170] Recovering isolators
3: I0818 09:06:32.231258 18413 containerizer.cpp:1209] Recovering provisioner
3: I0818 09:06:32.232363 18406 provisioner.cpp:518] Provisioner recovery complete
3: I0818 09:06:32.233675 18379 composing.cpp:343] Finished recovering all containerizers
3: I0818 09:06:32.234275 18419 slave.cpp:8205] Recovering executors
3: I0818 09:06:32.234477 18419 slave.cpp:8358] Finished recovery
3: I0818 09:06:32.236163 18438 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0818 09:06:32.236274 18419 slave.cpp:1471] New master detected at master@172.17.0.2:36589
3: I0818 09:06:32.236369 18405 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0818 09:06:32.236485 18419 slave.cpp:1536] Detecting new master
3: I0818 09:06:32.238929 18408 slave.cpp:1563] Authenticating with master master@172.17.0.2:36589
3: I0818 09:06:32.239099 18408 slave.cpp:1572] Using default CRAM-MD5 authenticatee
3: I0818 09:06:32.239528 18378 authenticatee.cpp:121] Creating new client SASL connection
3: I0818 09:06:32.240077 18398 master.cpp:9667] Authenticating slave(1244)@172.17.0.2:36589
3: I0818 09:06:32.240308 18362 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2106)@172.17.0.2:36589
3: I0818 09:06:32.240870 18449 authenticator.cpp:98] Creating new server SASL connection
3: I0818 09:06:32.241387 18409 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I0818 09:06:32.241462 18409 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I0818 09:06:32.241729 18373 authenticator.cpp:204] Received SASL authentication start
3: I0818 09:06:32.241909 18373 authenticator.cpp:326] Authentication requires more steps
3: I0818 09:06:32.242130 18421 authenticatee.cpp:259] Received SASL authentication step
3: I0818 09:06:32.242398 18388 authenticator.cpp:232] Received SASL authentication step
3: I0818 09:06:32.242511 18388 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '46c8b6126089' server FQDN: '46c8b6126089' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I0818 09:06:32.242563 18388 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I0818 09:06:32.242645 18388 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I0818 09:06:32.242738 18388 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '46c8b6126089' server FQDN: '46c8b6126089' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I0818 09:06:32.242785 18388 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I0818 09:06:32.242820 18388 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I0818 09:06:32.242874 18388 authenticator.cpp:318] Authentication success
3: I0818 09:06:32.243052 18430 authenticatee.cpp:299] Authentication success
3: I0818 09:06:32.243221 18447 master.cpp:9699] Successfully authenticated principal 'test-principal' at slave(1244)@172.17.0.2:36589
3: I0818 09:06:32.243273 18387 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2106)@172.17.0.2:36589
3: I0818 09:06:32.243703 18374 slave.cpp:1663] Successfully authenticated with master master@172.17.0.2:36589
3: I0818 09:06:32.244570 18374 slave.cpp:2113] Will retry registration in 8.1243ms if necessary
3: I0818 09:06:32.244915 18390 master.cpp:6162] Received register agent message from slave(1244)@172.17.0.2:36589 (46c8b6126089)
3: I0818 09:06:32.245788 18390 master.cpp:3693] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
3: I0818 09:06:32.246798 18377 master.cpp:6229] Authorized registration of agent at slave(1244)@172.17.0.2:36589 (46c8b6126089)
3: I0818 09:06:32.246978 18377 master.cpp:6341] Registering agent at slave(1244)@172.17.0.2:36589 (46c8b6126089) with id 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0
3: I0818 09:06:32.248417 18426 registrar.cpp:487] Applied 1 operations in 582655ns; attempting to update the registry
3: I0818 09:06:32.249454 18426 registrar.cpp:544] Successfully updated the registry in 939008ns
3: I0818 09:06:32.249727 18395 master.cpp:6389] Admitted agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 at slave(1244)@172.17.0.2:36589 (46c8b6126089)
3: I0818 09:06:32.250926 18395 master.cpp:6434] Registered agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 at slave(1244)@172.17.0.2:36589 (46c8b6126089) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0818 09:06:32.251176 18371 slave.cpp:1696] Registered with master master@172.17.0.2:36589; given agent ID 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0
3: I0818 09:06:32.251389 18451 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I0818 09:06:32.251387 18455 hierarchical.cpp:1026] Added agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 (46c8b6126089) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
3: I0818 09:06:32.251888 18455 hierarchical.cpp:1920] Performed allocation for 1 agents in 235557ns
3: I0818 09:06:32.252045 18371 slave.cpp:1731] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Po3Qqi/meta/slaves/550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0/slave.info'
3: I0818 09:06:32.252101 18455 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0818 09:06:32.254243 18371 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"E91JHb+SQHCihbEuK1qXZw=="},"slave_id":{"value":"550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0"},"update_oversubscribed_resources":false}
3: I0818 09:06:32.256098 18376 master.cpp:7575] Ignoring update on agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 at slave(1244)@172.17.0.2:36589 (46c8b6126089) as it reports no changes
3: I0818 09:06:32.262153 18366 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0818 09:06:32.263900 18422 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:35348
3: I0818 09:06:32.264688 18422 http.cpp:2828] Processing GET_CONTAINERS call
3: I0818 09:06:32.269728 18363 hierarchical.cpp:1920] Performed allocation for 1 agents in 271178ns
3: I0818 09:06:32.274763 18404 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0818 09:06:32.278617 18406 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0818 09:06:32.279966 18450 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:35350
3: I0818 09:06:32.281239 18450 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0818 09:06:32.282930 18450 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Po3Qqi/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0818 09:06:32.284039 18431 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0818 09:06:32.285228 18431 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 406784ns
3: I0818 09:06:32.286938 18431 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_pNYyRu/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
3: I0818 09:06:32.287027 18431 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.801216ms
3: I0818 09:06:32.292559 18398 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_JLiu05","--available_capacity=0B","--volumes=","--forward=unix:///tmp/tB36hW/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Po3Qqi/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-HuWGmV/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Po3Qqi/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="51" --pipe_write="56" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_pNYyRu/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
3: I0818 09:06:32.313354 18398 launcher.cpp:145] Forked child with pid '55227' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0818 09:06:32.315280 18398 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 28.239872ms
3: I0818 09:06:32.318351 18398 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 3.075072ms
3: I0818 09:06:32.318914 18397 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Po3Qqi/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0818 09:06:32.321214 18374 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 2.845184ms
3: I0818 09:06:32.322772 18441 hierarchical.cpp:1920] Performed allocation for 1 agents in 471413ns
3: I0818 09:06:32.325857 18448 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'
3: I0818 09:06:32.326287 18375 service_manager.cpp:775] Connecting to endpoint 'unix:///tmp/mesos-csi-HuWGmV/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0818 09:06:32.374954 18392 hierarchical.cpp:1920] Performed allocation for 1 agents in 333809ns
3: I0818 09:06:32.426237 18376 hierarchical.cpp:1920] Performed allocation for 1 agents in 243987ns
3: I0818 09:06:32.477622 18400 hierarchical.cpp:1920] Performed allocation for 1 agents in 473122ns
3: I0818 09:06:32.529064 18366 hierarchical.cpp:1920] Performed allocation for 1 agents in 371950ns
3: I0818 09:06:32.580257 18401 hierarchical.cpp:1920] Performed allocation for 1 agents in 226086ns
3: I0818 09:06:32.632113 18432 hierarchical.cpp:1920] Performed allocation for 1 agents in 255697ns
3: I0818 09:06:32.684224 18444 hierarchical.cpp:1920] Performed allocation for 1 agents in 253937ns
3: I0818 09:06:32.735455 18437 hierarchical.cpp:1920] Performed allocation for 1 agents in 231696ns
3: I0818 09:06:32.787540 18456 hierarchical.cpp:1920] Performed allocation for 1 agents in 403281ns
3: I0818 09:06:32.839501 18435 hierarchical.cpp:1920] Performed allocation for 1 agents in 251627ns
3: I0818 09:06:32.890753 18438 hierarchical.cpp:1920] Performed allocation for 1 agents in 231226ns
3: I0818 09:06:32.941913 18388 hierarchical.cpp:1920] Performed allocation for 1 agents in 322939ns
3: I0818 09:06:32.993335 18398 hierarchical.cpp:1920] Performed allocation for 1 agents in 325329ns
3: I0818 09:06:33.045511 18390 hierarchical.cpp:1920] Performed allocation for 1 agents in 324309ns
3: I0818 09:06:33.097836 18426 hierarchical.cpp:1920] Performed allocation for 1 agents in 341809ns
3: I0818 09:06:33.149354 18455 hierarchical.cpp:1920] Performed allocation for 1 agents in 260516ns
3: I0818 09:06:33.192709 18403 service_manager.cpp:617] Probing endpoint 'unix:///tmp/mesos-csi-HuWGmV/endpoint.sock' with CSI v1
3: I0818 09:06:33.197760 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call
3: I0818 09:06:33.201210 18369 hierarchical.cpp:1920] Performed allocation for 1 agents in 262337ns
3: I0818 09:06:33.203646 18365 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0818 09:06:33.208403 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call
3: I0818 09:06:33.209545 18424 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0818 09:06:33.211685 18372 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:35352
3: I0818 09:06:33.212708 18372 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0818 09:06:33.217077 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0818 09:06:33.217837 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0818 09:06:33.220373 18445 v1_volume_manager.cpp:674] NODE_SERVICE loaded: {}
3: I0818 09:06:33.221477 18445 v1_volume_manager.cpp:674] CONTROLLER_SERVICE loaded: {}
3: I0818 09:06:33.225788 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
3: I0818 09:06:33.232225 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call
3: I0818 09:06:33.238988 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call
3: I0818 09:06:33.242920 18435 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
3: I0818 09:06:33.243196 18440 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0818 09:06:33.243773 18405 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:36589/slave(1244)/api/v1/resource_provider
3: I0818 09:06:33.248039 18409 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:36589/slave(1244)/api/v1/resource_provider
3: I0818 09:06:33.249127 18399 provider.cpp:476] Connected to resource provider manager
3: I0818 09:06:33.250496 18430 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:36589/slave(1244)/api/v1/resource_provider
3: I0818 09:06:33.252223 18397 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0818 09:06:33.254624 18441 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:35354
3: I0818 09:06:33.254664 18390 hierarchical.cpp:1920] Performed allocation for 1 agents in 248107ns
3: I0818 09:06:33.255838 18382 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_JLiu05","--available_capacity=0B","--volumes=","--forward=unix:///tmp/tB36hW/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}
3: I0818 09:06:33.262681 18455 slave.cpp:8714] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"7de26e63-e661-4878-8693-d40abcfef97d"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_JLiu05","--available_capacity=0B","--volumes=","--forward=unix:///tmp/tB36hW/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}'
3: I0818 09:06:33.265094 18376 provider.cpp:498] Received SUBSCRIBED event
3: I0818 09:06:33.265175 18376 provider.cpp:1309] Subscribed with ID 7de26e63-e661-4878-8693-d40abcfef97d
3: I0818 09:06:33.266762 18417 status_update_manager_process.hpp:314] Recovering operation status update manager
3: I0818 09:06:33.272923 18365 provider.cpp:790] Reconciling storage pools and volumes
3: I0818 09:06:33.276417 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0818 09:06:33.281466 18454 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0
3: I0818 09:06:33.281878 18433 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:36589/slave(1244)/api/v1/resource_provider
3: I0818 09:06:33.282045 18454 provider.cpp:748] Resource provider 7de26e63-e661-4878-8693-d40abcfef97d is in READY state
3: I0818 09:06:33.282127 18363 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0818 09:06:33.283151 18385 provider.cpp:1235] Updating profiles { test } for resource provider 7de26e63-e661-4878-8693-d40abcfef97d
3: I0818 09:06:33.283566 18361 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0818 09:06:33.284942 18437 provider.cpp:790] Reconciling storage pools and volumes
3: I0818 09:06:33.285559 18456 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:35356
3: I0818 09:06:33.286571 18379 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 7de26e63-e661-4878-8693-d40abcfef97d
3: I0818 09:06:33.286885 18389 slave.cpp:8714] Handling resource provider message 'UPDATE_STATE: 7de26e63-e661-4878-8693-d40abcfef97d {}'
3: I0818 09:06:33.287034 18389 slave.cpp:8834] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0818 09:06:33.289753 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0818 09:06:33.290581 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0818 09:06:33.290632 18438 hierarchical.cpp:1177] Grew agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 by {} (total), { } (used)
3: I0818 09:06:33.291366 18438 hierarchical.cpp:1134] Agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 (46c8b6126089) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0818 09:06:33.300316 18397 hierarchical.cpp:1920] Performed allocation for 1 agents in 377890ns
3: I0818 09:06:33.300705 18375 provider.cpp:790] Reconciling storage pools and volumes
3: I0818 09:06:33.304250 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0818 09:06:33.304966 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0818 09:06:33.315707 18365 slave.cpp:1000] Agent terminating
3: I0818 09:06:33.316960 18365 manager.cpp:127] Terminating resource provider 7de26e63-e661-4878-8693-d40abcfef97d
3: I0818 09:06:33.317615 18396 master.cpp:1292] Agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 at slave(1244)@172.17.0.2:36589 (46c8b6126089) disconnected
3: I0818 09:06:33.317679 18396 master.cpp:3361] Disconnecting agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 at slave(1244)@172.17.0.2:36589 (46c8b6126089)
3: I0818 09:06:33.317812 18396 master.cpp:3380] Deactivating agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 at slave(1244)@172.17.0.2:36589 (46c8b6126089)
3: I0818 09:06:33.318071 18433 hierarchical.cpp:1223] Agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0 deactivated
3: E0818 09:06:33.318331 18432 http_connection.hpp:449] End-Of-File received
3: I0818 09:06:33.319042 18432 http_connection.hpp:217] Re-detecting endpoint
3: I0818 09:06:33.319687 18432 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0818 09:06:33.319808 18432 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0818 09:06:33.319859 18404 provider.cpp:488] Disconnected from resource provider manager
3: I0818 09:06:33.319931 18432 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:36589/slave(1244)/api/v1/resource_provider
3: I0818 09:06:33.320109 18364 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0818 09:06:33.321959 18450 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
3: I0818 09:06:33.322063 18450 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 16.000875008secs
3: I0818 09:06:33.322640 18450 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0818 09:06:33.324568 18419 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:36589/slave(1244)/api/v1/resource_provider
3: I0818 09:06:33.325520 18431 provider.cpp:476] Connected to resource provider manager
3: I0818 09:06:33.326388 18362 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:36589/slave(1244)/api/v1/resource_provider
3: I0818 09:06:33.327477 18457 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1/resource_provider'
3: E0818 09:06:33.329519 18438 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
3: I0818 09:06:33.344529 18367 hierarchical.cpp:1920] Performed allocation for 1 agents in 197135ns
3: I0818 09:06:33.394318 18430 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
3: I0818 09:06:33.396224 18443 hierarchical.cpp:1920] Performed allocation for 1 agents in 219886ns
3: I0818 09:06:33.397135 18441 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0818 09:06:33.401441 18451 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'
3: I0818 09:06:33.401746 18384 service_manager.cpp:795] Disconnected from endpoint 'unix:///tmp/mesos-csi-HuWGmV/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0818 09:06:33.402102 18370 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0818 09:06:33.405995 18457 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1'
3: I0818 09:06:33.427863 18455 master.cpp:1140] Master terminating
3: I0818 09:06:33.428422 18384 hierarchical.cpp:1199] Removed all filters for agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0
3: I0818 09:06:33.428467 18384 hierarchical.cpp:1075] Removed agent 550a1c14-2e7e-4662-85bb-eaa77770b7cb-S0
3: [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1298 ms)
3: [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (105441 ms total)
3:
3: [----------] Global test environment tear-down
3: [==========] 2273 tests from 216 test cases ran. (1063494 ms total)
3: [ PASSED ] 2272 tests.
3: [ FAILED ] 1 test, listed below:
3: [ FAILED ] SlaveTest.RunTaskGroupReferenceTypeSecret
3:
3: 1 FAILED TEST
3: YOU HAVE 34 DISABLED TESTS
3:
3: I0818 09:06:33.668040 18457 process.cpp:935] Stopped the socket accept loop
3/3 Test #3: MesosTests .......................***Failed 1066.41 sec
67% tests passed, 1 tests failed out of 3
Total Test time (real) = 1135.36 sec
The following tests FAILED:
3 - MesosTests (Failed)
Errors while running CTest
CMakeFiles/check.dir/build.make:60: recipe for target 'CMakeFiles/check' failed
make[3]: *** [CMakeFiles/check] Error 8
make[3]: Leaving directory '/tmp/SRC/build'
CMakeFiles/Makefile2:255: recipe for target 'CMakeFiles/check.dir/all' failed
make[2]: *** [CMakeFiles/check.dir/all] Error 2
make[2]: Leaving directory '/tmp/SRC/build'
CMakeFiles/Makefile2:262: recipe for target 'CMakeFiles/check.dir/rule' failed
make[1]: *** [CMakeFiles/check.dir/rule] Error 2
make[1]: Leaving directory '/tmp/SRC/build'
Makefile:278: recipe for target 'check' failed
make: *** [check] Error 2
real 83m5.342s
user 0m17.423s
sys 0m16.170s
Build step 'Execute shell' marked build as failure
Recording test results
Build failed in Jenkins: Mesos-Buildbot-ARM » cmake,clang,--verbose --disable-libtool-wrappers --disable-java --disable-python --disable-parallel-test-execution,GLOG_v=1 MESOS_VERBOSE=1 MESOS_TEST_AWAIT_TIMEOUT=60secs JOBS=16 GTEST_FILTER=-DiskQuotaTest.SlaveRecovery,arm1 #1776
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Buildbot-ARM/BUILDTOOL=cmake,COMPILER=clang,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--disable-java%20--disable-python%20--disable-parallel-test-execution,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1%20%20MESOS_TEST_AWAIT_TIMEOUT=60secs%20JOBS=16%20GTEST_FILTER=-DiskQuotaTest.SlaveRecovery,label_exp=arm1/1776/display/redirect?page=changes>
Changes:
[asekretenko] Added a scheduler API test for a valid offer constraints update.
------------------------------------------
[...truncated 48.24 MB...]
3: I0820 20:47:21.680338 18455 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
3: I0820 20:47:21.680718 18455 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
3: I0820 20:47:21.681028 18455 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
3: I0820 20:47:21.681350 18455 master.cpp:634] Authorization enabled
3: I0820 20:47:21.681957 18382 hierarchical.cpp:637] Initialized hierarchical allocator process
3: I0820 20:47:21.682032 18427 whitelist_watcher.cpp:77] No whitelist given
3: I0820 20:47:21.688356 18398 master.cpp:2167] Elected as the leading master!
3: I0820 20:47:21.688412 18398 master.cpp:1663] Recovering from registrar
3: I0820 20:47:21.688750 18393 registrar.cpp:339] Recovering registrar
3: I0820 20:47:21.690313 18393 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
3: I0820 20:47:21.690614 18393 registrar.cpp:487] Applied 1 operations in 127083ns; attempting to update the registry
3: I0820 20:47:21.691929 18393 registrar.cpp:544] Successfully updated the registry in 0ns
3: I0820 20:47:21.692190 18393 registrar.cpp:416] Successfully recovered registrar
3: I0820 20:47:21.693033 18477 hierarchical.cpp:676] Skipping recovery of hierarchical allocator: nothing to recover
3: I0820 20:47:21.693008 18399 master.cpp:1816] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
3: W0820 20:47:21.706012 18381 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:40485
3: I0820 20:47:21.709112 18381 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W0820 20:47:21.710377 18381 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
3: W0820 20:47:21.710446 18381 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W0820 20:47:21.710505 18381 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I0820 20:47:21.710592 18381 provisioner.cpp:294] Using default backend 'copy'
3: I0820 20:47:21.715471 18381 cluster.cpp:533] Creating default 'local' authorizer
3: I0820 20:47:21.720077 18470 slave.cpp:279] Mesos agent started on (1245)@172.17.0.2:40485
3: I0820 20:47:21.720153 18470 slave.cpp:280] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/ifI6j8/Ov6MYo/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/ifI6j8/Ov6MYo/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/ifI6j8/Ov6MYo/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/ifI6j8/Ov6MYo/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/ifI6j8/Ov6MYo/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/ifI6j8/Ov6MYo/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/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/ifI6j8/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_elHCDz" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_w2hZiK" --zk_session_timeout="10secs"
3: I0820 20:47:21.721112 18470 credentials.hpp:73] Loading credential for authentication from '/tmp/ifI6j8/Ov6MYo/credential'
3: I0820 20:47:21.721437 18470 slave.cpp:312] Agent using credential for: test-principal
3: I0820 20:47:21.721491 18470 credentials.hpp:37] Loading credentials for authentication from '/tmp/ifI6j8/Ov6MYo/http_credentials'
3: I0820 20:47:21.721889 18470 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I0820 20:47:21.722522 18402 hierarchical.cpp:1935] Performed allocation for 0 agents in 108803ns
3: I0820 20:47:21.722576 18470 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
3: I0820 20:47:21.725632 18469 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
3: I0820 20:47:21.725903 18470 slave.cpp:627] 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"}]
3: I0820 20:47:21.726305 18470 slave.cpp:635] Agent attributes: [ ]
3: I0820 20:47:21.726346 18470 slave.cpp:644] Agent hostname: 4c3ac7c32224
3: I0820 20:47:21.726656 18419 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0820 20:47:21.726698 18440 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0820 20:47:21.730768 18458 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_w2hZiK/meta'
3: I0820 20:47:21.731143 18449 slave.cpp:7723] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_w2hZiK/meta', beginning agent recovery
3: I0820 20:47:21.732187 18460 task_status_update_manager.cpp:207] Recovering task status update manager
3: I0820 20:47:21.732916 18464 containerizer.cpp:830] Recovering Mesos containers
3: I0820 20:47:21.733733 18464 containerizer.cpp:1170] Recovering isolators
3: I0820 20:47:21.735479 18396 containerizer.cpp:1209] Recovering provisioner
3: I0820 20:47:21.736752 18446 provisioner.cpp:518] Provisioner recovery complete
3: I0820 20:47:21.737996 18423 composing.cpp:343] Finished recovering all containerizers
3: I0820 20:47:21.738667 18428 slave.cpp:8205] Recovering executors
3: I0820 20:47:21.738850 18428 slave.cpp:8358] Finished recovery
3: I0820 20:47:21.740552 18406 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0820 20:47:21.740593 18427 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0820 20:47:21.740639 18390 slave.cpp:1471] New master detected at master@172.17.0.2:40485
3: I0820 20:47:21.740859 18390 slave.cpp:1536] Detecting new master
3: I0820 20:47:21.743248 18417 slave.cpp:1563] Authenticating with master master@172.17.0.2:40485
3: I0820 20:47:21.743427 18417 slave.cpp:1572] Using default CRAM-MD5 authenticatee
3: I0820 20:47:21.743902 18455 authenticatee.cpp:121] Creating new client SASL connection
3: I0820 20:47:21.744416 18456 master.cpp:9721] Authenticating slave(1245)@172.17.0.2:40485
3: I0820 20:47:21.744675 18408 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2108)@172.17.0.2:40485
3: I0820 20:47:21.745198 18407 authenticator.cpp:98] Creating new server SASL connection
3: I0820 20:47:21.745784 18398 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I0820 20:47:21.745856 18398 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I0820 20:47:21.746088 18429 authenticator.cpp:204] Received SASL authentication start
3: I0820 20:47:21.746245 18429 authenticator.cpp:326] Authentication requires more steps
3: I0820 20:47:21.746475 18431 authenticatee.cpp:259] Received SASL authentication step
3: I0820 20:47:21.746699 18466 authenticator.cpp:232] Received SASL authentication step
3: I0820 20:47:21.746776 18466 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4c3ac7c32224' server FQDN: '4c3ac7c32224' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I0820 20:47:21.746825 18466 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I0820 20:47:21.746912 18466 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I0820 20:47:21.747002 18466 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '4c3ac7c32224' server FQDN: '4c3ac7c32224' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I0820 20:47:21.747048 18466 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I0820 20:47:21.747083 18466 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I0820 20:47:21.747131 18466 authenticator.cpp:318] Authentication success
3: I0820 20:47:21.747303 18441 authenticatee.cpp:299] Authentication success
3: I0820 20:47:21.747442 18444 master.cpp:9753] Successfully authenticated principal 'test-principal' at slave(1245)@172.17.0.2:40485
3: I0820 20:47:21.747537 18383 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2108)@172.17.0.2:40485
3: I0820 20:47:21.747913 18405 slave.cpp:1663] Successfully authenticated with master master@172.17.0.2:40485
3: I0820 20:47:21.749225 18405 slave.cpp:2113] Will retry registration in 8.1243ms if necessary
3: I0820 20:47:21.749569 18388 master.cpp:6215] Received register agent message from slave(1245)@172.17.0.2:40485 (4c3ac7c32224)
3: I0820 20:47:21.750330 18388 master.cpp:3746] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
3: I0820 20:47:21.751415 18476 master.cpp:6282] Authorized registration of agent at slave(1245)@172.17.0.2:40485 (4c3ac7c32224)
3: I0820 20:47:21.751621 18476 master.cpp:6394] Registering agent at slave(1245)@172.17.0.2:40485 (4c3ac7c32224) with id 5910f37c-140a-4536-9f0f-512a27e3af2a-S0
3: I0820 20:47:21.752894 18410 registrar.cpp:487] Applied 1 operations in 604566ns; attempting to update the registry
3: I0820 20:47:21.753832 18410 registrar.cpp:544] Successfully updated the registry in 841984ns
3: I0820 20:47:21.754134 18418 master.cpp:6442] Admitted agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 at slave(1245)@172.17.0.2:40485 (4c3ac7c32224)
3: I0820 20:47:21.755484 18418 master.cpp:6487] Registered agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 at slave(1245)@172.17.0.2:40485 (4c3ac7c32224) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0820 20:47:21.755717 18421 slave.cpp:1696] Registered with master master@172.17.0.2:40485; given agent ID 5910f37c-140a-4536-9f0f-512a27e3af2a-S0
3: I0820 20:47:21.755931 18415 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I0820 20:47:21.756106 18467 hierarchical.cpp:1041] Added agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 (4c3ac7c32224) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
3: I0820 20:47:21.756659 18421 slave.cpp:1731] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_w2hZiK/meta/slaves/5910f37c-140a-4536-9f0f-512a27e3af2a-S0/slave.info'
3: I0820 20:47:21.756736 18467 hierarchical.cpp:1935] Performed allocation for 1 agents in 297008ns
3: I0820 20:47:21.756774 18412 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0820 20:47:21.759090 18421 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"0nMFPIlSTHW2klLBl0jWDQ=="},"slave_id":{"value":"5910f37c-140a-4536-9f0f-512a27e3af2a-S0"},"update_oversubscribed_resources":false}
3: I0820 20:47:21.761061 18392 master.cpp:7629] Ignoring update on agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 at slave(1245)@172.17.0.2:40485 (4c3ac7c32224) as it reports no changes
3: I0820 20:47:21.766464 18433 process.cpp:3671] Handling HTTP event for process 'slave(1245)' with path: '/slave(1245)/api/v1'
3: I0820 20:47:21.768297 18449 http.cpp:1436] HTTP POST for /slave(1245)/api/v1 from 172.17.0.2:58394
3: I0820 20:47:21.769232 18449 http.cpp:2828] Processing GET_CONTAINERS call
3: I0820 20:47:21.773912 18471 hierarchical.cpp:1935] Performed allocation for 1 agents in 341189ns
3: I0820 20:47:21.779098 18385 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0820 20:47:21.782747 18438 process.cpp:3671] Handling HTTP event for process 'slave(1245)' with path: '/slave(1245)/api/v1'
3: I0820 20:47:21.784309 18423 http.cpp:1436] HTTP POST for /slave(1245)/api/v1 from 172.17.0.2:58396
3: I0820 20:47:21.785689 18423 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0820 20:47:21.787499 18423 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_w2hZiK/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0820 20:47:21.788664 18416 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0820 20:47:21.789907 18416 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 421888ns
3: I0820 20:47:21.791689 18416 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_elHCDz/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
3: I0820 20:47:21.791779 18416 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.874944ms
3: I0820 20:47:21.797587 18408 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_6W0sWU","--available_capacity=0B","--volumes=","--forward=unix:///tmp/ifI6j8/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_w2hZiK/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-ochKoS/endpoint.sock"},{"name":"MESOS_AGENT_ID","type":"VALUE","value":"5910f37c-140a-4536-9f0f-512a27e3af2a-S0"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_w2hZiK/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="51" --pipe_write="56" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_elHCDz/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
3: I0820 20:47:21.818225 18408 launcher.cpp:145] Forked child with pid '55243' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0820 20:47:21.820343 18408 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 28.546048ms
3: I0820 20:47:21.823628 18408 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 3.293184ms
3: I0820 20:47:21.824177 18383 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_w2hZiK/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0820 20:47:21.826135 18384 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 2.500864ms
3: I0820 20:47:21.826905 18405 hierarchical.cpp:1935] Performed allocation for 1 agents in 485112ns
3: I0820 20:47:21.831095 18434 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'
3: I0820 20:47:21.831506 18400 service_manager.cpp:795] Connecting to endpoint 'unix:///tmp/mesos-csi-ochKoS/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0820 20:47:21.878757 18467 hierarchical.cpp:1935] Performed allocation for 1 agents in 271237ns
3: I0820 20:47:21.930001 18420 hierarchical.cpp:1935] Performed allocation for 1 agents in 250797ns
3: I0820 20:47:21.982024 18402 hierarchical.cpp:1935] Performed allocation for 1 agents in 358090ns
3: I0820 20:47:22.033418 18404 hierarchical.cpp:1935] Performed allocation for 1 agents in 409750ns
3: I0820 20:47:22.084751 18460 hierarchical.cpp:1935] Performed allocation for 1 agents in 312259ns
3: I0820 20:47:22.136145 18395 hierarchical.cpp:1935] Performed allocation for 1 agents in 256097ns
3: I0820 20:47:22.187491 18424 hierarchical.cpp:1935] Performed allocation for 1 agents in 224386ns
3: I0820 20:47:22.238708 18462 hierarchical.cpp:1935] Performed allocation for 1 agents in 382350ns
3: I0820 20:47:22.289840 18446 hierarchical.cpp:1935] Performed allocation for 1 agents in 223786ns
3: I0820 20:47:22.341226 18463 hierarchical.cpp:1935] Performed allocation for 1 agents in 241556ns
3: I0820 20:47:22.392725 18390 hierarchical.cpp:1935] Performed allocation for 1 agents in 253597ns
3: I0820 20:47:22.444413 18431 hierarchical.cpp:1935] Performed allocation for 1 agents in 312628ns
3: I0820 20:47:22.496605 18399 hierarchical.cpp:1935] Performed allocation for 1 agents in 347710ns
3: I0820 20:47:22.548707 18384 hierarchical.cpp:1935] Performed allocation for 1 agents in 319119ns
3: I0820 20:47:22.600306 18410 hierarchical.cpp:1935] Performed allocation for 1 agents in 349199ns
3: I0820 20:47:22.652180 18415 hierarchical.cpp:1935] Performed allocation for 1 agents in 223686ns
3: I0820 20:47:22.690160 18454 service_manager.cpp:622] Probing endpoint 'unix:///tmp/mesos-csi-ochKoS/endpoint.sock' with CSI v1
3: I0820 20:47:22.693923 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call
3: I0820 20:47:22.699867 18392 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0820 20:47:22.703845 18461 hierarchical.cpp:1935] Performed allocation for 1 agents in 281367ns
3: I0820 20:47:22.704473 18404 process.cpp:3671] Handling HTTP event for process 'slave(1245)' with path: '/slave(1245)/api/v1'
3: I0820 20:47:22.704982 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call
3: I0820 20:47:22.706238 18425 http.cpp:1436] HTTP POST for /slave(1245)/api/v1 from 172.17.0.2:58398
3: I0820 20:47:22.707199 18425 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0820 20:47:22.713174 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0820 20:47:22.713937 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0820 20:47:22.716694 18432 v1_volume_manager.cpp:674] NODE_SERVICE loaded: {}
3: I0820 20:47:22.717598 18432 v1_volume_manager.cpp:674] CONTROLLER_SERVICE loaded: {}
3: I0820 20:47:22.721681 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
3: I0820 20:47:22.728050 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call
3: I0820 20:47:22.733969 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call
3: I0820 20:47:22.738114 18406 provider.cpp:677] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
3: I0820 20:47:22.738325 18463 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0820 20:47:22.739305 18382 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:40485/slave(1245)/api/v1/resource_provider
3: I0820 20:47:22.743168 18417 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:40485/slave(1245)/api/v1/resource_provider
3: I0820 20:47:22.744123 18444 provider.cpp:476] Connected to resource provider manager
3: I0820 20:47:22.745220 18477 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:40485/slave(1245)/api/v1/resource_provider
3: I0820 20:47:22.746853 18389 process.cpp:3671] Handling HTTP event for process 'slave(1245)' with path: '/slave(1245)/api/v1/resource_provider'
3: I0820 20:47:22.749537 18384 http.cpp:1436] HTTP POST for /slave(1245)/api/v1/resource_provider from 172.17.0.2:58400
3: I0820 20:47:22.750957 18430 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_6W0sWU","--available_capacity=0B","--volumes=","--forward=unix:///tmp/ifI6j8/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}
3: I0820 20:47:22.754864 18400 hierarchical.cpp:1935] Performed allocation for 1 agents in 244086ns
3: I0820 20:47:22.757931 18418 slave.cpp:8714] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"38da8022-f3cd-4d09-883b-bd564d076347"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_6W0sWU","--available_capacity=0B","--volumes=","--forward=unix:///tmp/ifI6j8/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}'
3: I0820 20:47:22.760243 18421 provider.cpp:498] Received SUBSCRIBED event
3: I0820 20:47:22.760429 18421 provider.cpp:1310] Subscribed with ID 38da8022-f3cd-4d09-883b-bd564d076347
3: I0820 20:47:22.761976 18439 status_update_manager_process.hpp:314] Recovering operation status update manager
3: I0820 20:47:22.772553 18392 provider.cpp:791] Reconciling storage pools and volumes
3: I0820 20:47:22.776093 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0820 20:47:22.780859 18425 provider.cpp:2218] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0
3: I0820 20:47:22.781296 18386 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:40485/slave(1245)/api/v1/resource_provider
3: I0820 20:47:22.781484 18425 provider.cpp:749] Resource provider 38da8022-f3cd-4d09-883b-bd564d076347 is in READY state
3: I0820 20:47:22.781576 18395 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0820 20:47:22.782671 18447 provider.cpp:1236] Updating profiles { test } for resource provider 38da8022-f3cd-4d09-883b-bd564d076347
3: I0820 20:47:22.783198 18437 process.cpp:3671] Handling HTTP event for process 'slave(1245)' with path: '/slave(1245)/api/v1/resource_provider'
3: I0820 20:47:22.784579 18396 provider.cpp:791] Reconciling storage pools and volumes
3: I0820 20:47:22.785120 18459 http.cpp:1436] HTTP POST for /slave(1245)/api/v1/resource_provider from 172.17.0.2:58402
3: I0820 20:47:22.786226 18453 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 38da8022-f3cd-4d09-883b-bd564d076347
3: I0820 20:47:22.786523 18446 slave.cpp:8714] Handling resource provider message 'UPDATE_STATE: 38da8022-f3cd-4d09-883b-bd564d076347 {}'
3: I0820 20:47:22.786674 18446 slave.cpp:8834] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0820 20:47:22.788446 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0820 20:47:22.789340 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0820 20:47:22.790577 18455 hierarchical.cpp:1192] Grew agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 by {} (total), { } (used)
3: I0820 20:47:22.791476 18455 hierarchical.cpp:1149] Agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 (4c3ac7c32224) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0820 20:47:22.798511 18408 hierarchical.cpp:1935] Performed allocation for 1 agents in 338809ns
3: I0820 20:47:22.798825 18476 provider.cpp:791] Reconciling storage pools and volumes
3: I0820 20:47:22.802567 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0820 20:47:22.803249 55247 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0820 20:47:22.813771 18402 slave.cpp:1000] Agent terminating
3: I0820 20:47:22.815069 18402 manager.cpp:127] Terminating resource provider 38da8022-f3cd-4d09-883b-bd564d076347
3: I0820 20:47:22.815745 18460 master.cpp:1294] Agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 at slave(1245)@172.17.0.2:40485 (4c3ac7c32224) disconnected
3: I0820 20:47:22.815812 18460 master.cpp:3414] Disconnecting agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 at slave(1245)@172.17.0.2:40485 (4c3ac7c32224)
3: I0820 20:47:22.815969 18460 master.cpp:3433] Deactivating agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 at slave(1245)@172.17.0.2:40485 (4c3ac7c32224)
3: I0820 20:47:22.816169 18395 hierarchical.cpp:1238] Agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0 deactivated
3: E0820 20:47:22.816489 18409 http_connection.hpp:449] End-Of-File received
3: I0820 20:47:22.817180 18409 http_connection.hpp:217] Re-detecting endpoint
3: I0820 20:47:22.817972 18409 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0820 20:47:22.818068 18449 provider.cpp:488] Disconnected from resource provider manager
3: I0820 20:47:22.818138 18409 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0820 20:47:22.818280 18409 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:40485/slave(1245)/api/v1/resource_provider
3: I0820 20:47:22.818359 18471 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0820 20:47:22.820343 18396 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
3: I0820 20:47:22.820444 18396 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.994324992secs
3: I0820 20:47:22.821192 18396 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0820 20:47:22.822888 18443 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:40485/slave(1245)/api/v1/resource_provider
3: I0820 20:47:22.823853 18427 provider.cpp:476] Connected to resource provider manager
3: I0820 20:47:22.824714 18456 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:40485/slave(1245)/api/v1/resource_provider
3: I0820 20:47:22.825966 18478 process.cpp:2781] Returning '404 Not Found' for '/slave(1245)/api/v1/resource_provider'
3: E0820 20:47:22.827750 18417 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
3: I0820 20:47:22.842994 18444 hierarchical.cpp:1935] Performed allocation for 1 agents in 246487ns
3: I0820 20:47:22.893628 18441 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
3: I0820 20:47:22.894589 18399 hierarchical.cpp:1935] Performed allocation for 1 agents in 183935ns
3: I0820 20:47:22.896054 18430 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0820 20:47:22.900046 18412 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'
3: I0820 20:47:22.900424 18467 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-ochKoS/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0820 20:47:22.900913 18474 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0820 20:47:22.904309 18478 process.cpp:2781] Returning '404 Not Found' for '/slave(1245)/api/v1'
3: I0820 20:47:22.926270 18474 master.cpp:1142] Master terminating
3: I0820 20:47:22.926760 18403 hierarchical.cpp:1214] Removed all filters for agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0
3: I0820 20:47:22.926815 18403 hierarchical.cpp:1090] Removed agent 5910f37c-140a-4536-9f0f-512a27e3af2a-S0
3: [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1293 ms)
3: [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (105768 ms total)
3:
3: [----------] Global test environment tear-down
3: [==========] 2279 tests from 217 test cases ran. (1066543 ms total)
3: [ PASSED ] 2278 tests.
3: [ FAILED ] 1 test, listed below:
3: [ FAILED ] SlaveTest.RunTaskGroupReferenceTypeSecret
3:
3: 1 FAILED TEST
3: YOU HAVE 34 DISABLED TESTS
3:
3: I0820 20:47:23.170256 18478 process.cpp:935] Stopped the socket accept loop
3/3 Test #3: MesosTests .......................***Failed 1069.50 sec
67% tests passed, 1 tests failed out of 3
Total Test time (real) = 1137.75 sec
The following tests FAILED:
3 - MesosTests (Failed)
Errors while running CTest
CMakeFiles/check.dir/build.make:60: recipe for target 'CMakeFiles/check' failed
make[3]: *** [CMakeFiles/check] Error 8
make[3]: Leaving directory '/tmp/SRC/build'
CMakeFiles/Makefile2:255: recipe for target 'CMakeFiles/check.dir/all' failed
make[2]: *** [CMakeFiles/check.dir/all] Error 2
make[2]: Leaving directory '/tmp/SRC/build'
CMakeFiles/Makefile2:262: recipe for target 'CMakeFiles/check.dir/rule' failed
make[1]: *** [CMakeFiles/check.dir/rule] Error 2
make[1]: Leaving directory '/tmp/SRC/build'
Makefile:278: recipe for target 'check' failed
make: *** [check] Error 2
real 83m18.168s
user 0m17.393s
sys 0m16.450s
Build step 'Execute shell' marked build as failure
Recording test results
Build failed in Jenkins: Mesos-Buildbot-ARM » cmake,clang,--verbose --disable-libtool-wrappers --disable-java --disable-python --disable-parallel-test-execution,GLOG_v=1 MESOS_VERBOSE=1 MESOS_TEST_AWAIT_TIMEOUT=60secs JOBS=16 GTEST_FILTER=-DiskQuotaTest.SlaveRecovery,arm1 #1775
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Buildbot-ARM/BUILDTOOL=cmake,COMPILER=clang,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--disable-java%20--disable-python%20--disable-parallel-test-execution,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1%20%20MESOS_TEST_AWAIT_TIMEOUT=60secs%20JOBS=16%20GTEST_FILTER=-DiskQuotaTest.SlaveRecovery,label_exp=arm1/1775/display/redirect?page=changes>
Changes:
[asekretenko] Removed `evolve(const scheduler::Call&)`.
------------------------------------------
[...truncated 48.22 MB...]
3: I0819 14:09:51.560688 18410 registrar.cpp:339] Recovering registrar
3: I0819 14:09:51.562103 18410 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
3: I0819 14:09:51.562389 18410 registrar.cpp:487] Applied 1 operations in 116733ns; attempting to update the registry
3: I0819 14:09:51.563740 18410 registrar.cpp:544] Successfully updated the registry in 0ns
3: I0819 14:09:51.564020 18410 registrar.cpp:416] Successfully recovered registrar
3: I0819 14:09:51.564914 18440 hierarchical.cpp:673] Skipping recovery of hierarchical allocator: nothing to recover
3: I0819 14:09:51.564883 18407 master.cpp:1814] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
3: W0819 14:09:51.577457 18360 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:33643
3: I0819 14:09:51.580631 18360 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W0819 14:09:51.581849 18360 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
3: W0819 14:09:51.581920 18360 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W0819 14:09:51.581977 18360 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I0819 14:09:51.582052 18360 provisioner.cpp:294] Using default backend 'copy'
3: I0819 14:09:51.587029 18360 cluster.cpp:533] Creating default 'local' authorizer
3: I0819 14:09:51.591816 18416 slave.cpp:279] Mesos agent started on (1244)@172.17.0.2:33643
3: I0819 14:09:51.591897 18416 slave.cpp:280] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/Mifeqk/oMRdXY/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/Mifeqk/oMRdXY/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/Mifeqk/oMRdXY/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/Mifeqk/oMRdXY/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/Mifeqk/oMRdXY/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/Mifeqk/oMRdXY/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/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/Mifeqk/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Xbmabj" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MhemnD" --zk_session_timeout="10secs"
3: I0819 14:09:51.592969 18416 credentials.hpp:73] Loading credential for authentication from '/tmp/Mifeqk/oMRdXY/credential'
3: I0819 14:09:51.593300 18416 slave.cpp:312] Agent using credential for: test-principal
3: I0819 14:09:51.593353 18416 credentials.hpp:37] Loading credentials for authentication from '/tmp/Mifeqk/oMRdXY/http_credentials'
3: I0819 14:09:51.593698 18416 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I0819 14:09:51.594338 18416 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
3: I0819 14:09:51.594347 18430 hierarchical.cpp:1920] Performed allocation for 0 agents in 116053ns
3: I0819 14:09:51.596853 18448 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
3: I0819 14:09:51.597533 18416 slave.cpp:627] 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"}]
3: I0819 14:09:51.597905 18416 slave.cpp:635] Agent attributes: [ ]
3: I0819 14:09:51.597944 18416 slave.cpp:644] Agent hostname: 5f6aaf744609
3: I0819 14:09:51.598230 18378 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0819 14:09:51.598273 18403 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0819 14:09:51.601929 18389 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MhemnD/meta'
3: I0819 14:09:51.602303 18421 slave.cpp:7723] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MhemnD/meta', beginning agent recovery
3: I0819 14:09:51.603308 18450 task_status_update_manager.cpp:207] Recovering task status update manager
3: I0819 14:09:51.604038 18439 containerizer.cpp:830] Recovering Mesos containers
3: I0819 14:09:51.604627 18439 containerizer.cpp:1170] Recovering isolators
3: I0819 14:09:51.606071 18391 containerizer.cpp:1209] Recovering provisioner
3: I0819 14:09:51.607184 18438 provisioner.cpp:518] Provisioner recovery complete
3: I0819 14:09:51.608299 18401 composing.cpp:343] Finished recovering all containerizers
3: I0819 14:09:51.608780 18393 slave.cpp:8205] Recovering executors
3: I0819 14:09:51.608973 18393 slave.cpp:8358] Finished recovery
3: I0819 14:09:51.610819 18365 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0819 14:09:51.610884 18385 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0819 14:09:51.610900 18393 slave.cpp:1471] New master detected at master@172.17.0.2:33643
3: I0819 14:09:51.611099 18393 slave.cpp:1536] Detecting new master
3: I0819 14:09:51.614497 18364 slave.cpp:1563] Authenticating with master master@172.17.0.2:33643
3: I0819 14:09:51.614637 18364 slave.cpp:1572] Using default CRAM-MD5 authenticatee
3: I0819 14:09:51.615167 18431 authenticatee.cpp:121] Creating new client SASL connection
3: I0819 14:09:51.615689 18442 master.cpp:9667] Authenticating slave(1244)@172.17.0.2:33643
3: I0819 14:09:51.615917 18399 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2106)@172.17.0.2:33643
3: I0819 14:09:51.616442 18443 authenticator.cpp:98] Creating new server SASL connection
3: I0819 14:09:51.617019 18452 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I0819 14:09:51.617084 18452 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I0819 14:09:51.617313 18390 authenticator.cpp:204] Received SASL authentication start
3: I0819 14:09:51.617468 18390 authenticator.cpp:326] Authentication requires more steps
3: I0819 14:09:51.617696 18446 authenticatee.cpp:259] Received SASL authentication step
3: I0819 14:09:51.617961 18426 authenticator.cpp:232] Received SASL authentication step
3: I0819 14:09:51.618050 18426 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5f6aaf744609' server FQDN: '5f6aaf744609' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I0819 14:09:51.618103 18426 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I0819 14:09:51.618206 18426 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I0819 14:09:51.618295 18426 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5f6aaf744609' server FQDN: '5f6aaf744609' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I0819 14:09:51.618342 18426 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I0819 14:09:51.618377 18426 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I0819 14:09:51.618427 18426 authenticator.cpp:318] Authentication success
3: I0819 14:09:51.618582 18425 authenticatee.cpp:299] Authentication success
3: I0819 14:09:51.618750 18447 master.cpp:9699] Successfully authenticated principal 'test-principal' at slave(1244)@172.17.0.2:33643
3: I0819 14:09:51.618875 18408 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2106)@172.17.0.2:33643
3: I0819 14:09:51.619233 18397 slave.cpp:1663] Successfully authenticated with master master@172.17.0.2:33643
3: I0819 14:09:51.620220 18397 slave.cpp:2113] Will retry registration in 4.199982ms if necessary
3: I0819 14:09:51.620465 18367 master.cpp:6162] Received register agent message from slave(1244)@172.17.0.2:33643 (5f6aaf744609)
3: I0819 14:09:51.621197 18367 master.cpp:3693] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
3: I0819 14:09:51.622236 18396 master.cpp:6229] Authorized registration of agent at slave(1244)@172.17.0.2:33643 (5f6aaf744609)
3: I0819 14:09:51.622412 18396 master.cpp:6341] Registering agent at slave(1244)@172.17.0.2:33643 (5f6aaf744609) with id 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0
3: I0819 14:09:51.623723 18445 registrar.cpp:487] Applied 1 operations in 561235ns; attempting to update the registry
3: I0819 14:09:51.624650 18445 registrar.cpp:544] Successfully updated the registry in 824064ns
3: I0819 14:09:51.624951 18419 master.cpp:6389] Admitted agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 at slave(1244)@172.17.0.2:33643 (5f6aaf744609)
3: I0819 14:09:51.626193 18419 master.cpp:6434] Registered agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 at slave(1244)@172.17.0.2:33643 (5f6aaf744609) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0819 14:09:51.626454 18433 slave.cpp:2113] Will retry registration in 37.238711ms if necessary
3: I0819 14:09:51.626664 18374 hierarchical.cpp:1026] Added agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 (5f6aaf744609) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
3: I0819 14:09:51.626729 18419 master.cpp:6162] Received register agent message from slave(1244)@172.17.0.2:33643 (5f6aaf744609)
3: I0819 14:09:51.626886 18433 slave.cpp:1696] Registered with master master@172.17.0.2:33643; given agent ID 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0
3: I0819 14:09:51.627094 18427 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I0819 14:09:51.627226 18374 hierarchical.cpp:1920] Performed allocation for 1 agents in 296728ns
3: I0819 14:09:51.627427 18419 master.cpp:3693] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
3: I0819 14:09:51.627756 18433 slave.cpp:1731] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MhemnD/meta/slaves/640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0/slave.info'
3: I0819 14:09:51.627888 18437 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0819 14:09:51.628163 18455 master.cpp:6229] Authorized registration of agent at slave(1244)@172.17.0.2:33643 (5f6aaf744609)
3: I0819 14:09:51.628324 18455 master.cpp:6320] Agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 at slave(1244)@172.17.0.2:33643 (5f6aaf744609) already registered, resending acknowledgement
3: I0819 14:09:51.629894 18433 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"3DKkDiE2Q8Os0rph71YcjA=="},"slave_id":{"value":"640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0"},"update_oversubscribed_resources":false}
3: W0819 14:09:51.630338 18433 slave.cpp:1765] Already registered with master master@172.17.0.2:33643
3: I0819 14:09:51.630424 18433 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"3DKkDiE2Q8Os0rph71YcjA=="},"slave_id":{"value":"640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0"},"update_oversubscribed_resources":false}
3: I0819 14:09:51.631914 18409 master.cpp:7575] Ignoring update on agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 at slave(1244)@172.17.0.2:33643 (5f6aaf744609) as it reports no changes
3: I0819 14:09:51.633288 18409 master.cpp:7575] Ignoring update on agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 at slave(1244)@172.17.0.2:33643 (5f6aaf744609) as it reports no changes
3: I0819 14:09:51.637310 18394 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0819 14:09:51.639076 18373 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:36330
3: I0819 14:09:51.639878 18373 http.cpp:2828] Processing GET_CONTAINERS call
3: I0819 14:09:51.646248 18368 hierarchical.cpp:1920] Performed allocation for 1 agents in 280397ns
3: I0819 14:09:51.649089 18384 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 14:09:51.652262 18387 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0819 14:09:51.653506 18449 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:36332
3: I0819 14:09:51.654649 18449 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 14:09:51.656286 18449 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MhemnD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 14:09:51.657578 18393 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 14:09:51.658753 18393 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 424192ns
3: I0819 14:09:51.660375 18393 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Xbmabj/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
3: I0819 14:09:51.660465 18393 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 1.712896ms
3: I0819 14:09:51.666049 18390 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_PyMcyX","--available_capacity=0B","--volumes=","--forward=unix:///tmp/Mifeqk/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MhemnD/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-ciU3BR/endpoint.sock"},{"name":"MESOS_AGENT_ID","type":"VALUE","value":"640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MhemnD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="53" --pipe_write="58" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_Xbmabj/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
3: I0819 14:09:51.684908 18390 launcher.cpp:145] Forked child with pid '55229' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 14:09:51.687027 18390 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 26.550016ms
3: I0819 14:09:51.690351 18390 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 3.337984ms
3: I0819 14:09:51.690852 18392 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_MhemnD/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 14:09:51.692787 18367 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 2.425088ms
3: I0819 14:09:51.697896 18445 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'
3: I0819 14:09:51.698271 18428 service_manager.cpp:795] Connecting to endpoint 'unix:///tmp/mesos-csi-ciU3BR/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 14:09:51.698545 18423 hierarchical.cpp:1920] Performed allocation for 1 agents in 461552ns
3: I0819 14:09:51.750492 18441 hierarchical.cpp:1920] Performed allocation for 1 agents in 246227ns
3: I0819 14:09:51.802120 18412 hierarchical.cpp:1920] Performed allocation for 1 agents in 268507ns
3: I0819 14:09:51.853366 18448 hierarchical.cpp:1920] Performed allocation for 1 agents in 289248ns
3: I0819 14:09:51.904808 18361 hierarchical.cpp:1920] Performed allocation for 1 agents in 371910ns
3: I0819 14:09:51.956223 18373 hierarchical.cpp:1920] Performed allocation for 1 agents in 370440ns
3: I0819 14:09:52.008476 18406 hierarchical.cpp:1920] Performed allocation for 1 agents in 402800ns
3: I0819 14:09:52.060482 18391 hierarchical.cpp:1920] Performed allocation for 1 agents in 239996ns
3: I0819 14:09:52.111886 18382 hierarchical.cpp:1920] Performed allocation for 1 agents in 237026ns
3: I0819 14:09:52.162799 18414 hierarchical.cpp:1920] Performed allocation for 1 agents in 231546ns
3: I0819 14:09:52.213991 18366 hierarchical.cpp:1920] Performed allocation for 1 agents in 229776ns
3: I0819 14:09:52.266221 18452 hierarchical.cpp:1920] Performed allocation for 1 agents in 345189ns
3: I0819 14:09:52.317764 18407 hierarchical.cpp:1920] Performed allocation for 1 agents in 229116ns
3: I0819 14:09:52.368669 18390 hierarchical.cpp:1920] Performed allocation for 1 agents in 195625ns
3: I0819 14:09:52.420486 18396 hierarchical.cpp:1920] Performed allocation for 1 agents in 285788ns
3: I0819 14:09:52.471474 18423 hierarchical.cpp:1920] Performed allocation for 1 agents in 180215ns
3: I0819 14:09:52.522189 18441 hierarchical.cpp:1920] Performed allocation for 1 agents in 176275ns
3: I0819 14:09:52.542055 18381 service_manager.cpp:622] Probing endpoint 'unix:///tmp/mesos-csi-ciU3BR/endpoint.sock' with CSI v1
3: I0819 14:09:52.546097 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call
3: I0819 14:09:52.551899 18453 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 14:09:52.556756 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call
3: I0819 14:09:52.556874 18448 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0819 14:09:52.559315 18372 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:36334
3: I0819 14:09:52.560271 18372 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 14:09:52.564699 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0819 14:09:52.565438 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0819 14:09:52.568023 18377 v1_volume_manager.cpp:674] NODE_SERVICE loaded: {}
3: I0819 14:09:52.568907 18377 v1_volume_manager.cpp:674] CONTROLLER_SERVICE loaded: {}
3: I0819 14:09:52.573531 18436 hierarchical.cpp:1920] Performed allocation for 1 agents in 302748ns
3: I0819 14:09:52.573804 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
3: I0819 14:09:52.580461 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call
3: I0819 14:09:52.586541 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call
3: I0819 14:09:52.590451 18385 provider.cpp:677] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
3: I0819 14:09:52.590672 18369 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0819 14:09:52.591382 18393 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:33643/slave(1244)/api/v1/resource_provider
3: I0819 14:09:52.595294 18431 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:33643/slave(1244)/api/v1/resource_provider
3: I0819 14:09:52.596267 18410 provider.cpp:476] Connected to resource provider manager
3: I0819 14:09:52.597245 18375 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:33643/slave(1244)/api/v1/resource_provider
3: I0819 14:09:52.598774 18397 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0819 14:09:52.601141 18363 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:36336
3: I0819 14:09:52.602421 18424 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_PyMcyX","--available_capacity=0B","--volumes=","--forward=unix:///tmp/Mifeqk/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}
3: I0819 14:09:52.608371 18398 slave.cpp:8714] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"b621a7cc-37fe-4f06-9331-3d2fe1a5c856"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_PyMcyX","--available_capacity=0B","--volumes=","--forward=unix:///tmp/Mifeqk/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}'
3: I0819 14:09:52.610563 18381 provider.cpp:498] Received SUBSCRIBED event
3: I0819 14:09:52.610622 18381 provider.cpp:1310] Subscribed with ID b621a7cc-37fe-4f06-9331-3d2fe1a5c856
3: I0819 14:09:52.612089 18412 status_update_manager_process.hpp:314] Recovering operation status update manager
3: I0819 14:09:52.618487 18420 provider.cpp:791] Reconciling storage pools and volumes
3: I0819 14:09:52.622227 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0819 14:09:52.624760 18389 hierarchical.cpp:1920] Performed allocation for 1 agents in 352480ns
3: I0819 14:09:52.626843 18434 provider.cpp:2218] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0
3: I0819 14:09:52.627184 18429 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:33643/slave(1244)/api/v1/resource_provider
3: I0819 14:09:52.627363 18434 provider.cpp:749] Resource provider b621a7cc-37fe-4f06-9331-3d2fe1a5c856 is in READY state
3: I0819 14:09:52.627437 18418 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0819 14:09:52.628511 18439 provider.cpp:1236] Updating profiles { test } for resource provider b621a7cc-37fe-4f06-9331-3d2fe1a5c856
3: I0819 14:09:52.628682 18422 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0819 14:09:52.630163 18411 provider.cpp:791] Reconciling storage pools and volumes
3: I0819 14:09:52.630708 18438 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:36338
3: I0819 14:09:52.631615 18400 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider b621a7cc-37fe-4f06-9331-3d2fe1a5c856
3: I0819 14:09:52.631884 18402 slave.cpp:8714] Handling resource provider message 'UPDATE_STATE: b621a7cc-37fe-4f06-9331-3d2fe1a5c856 {}'
3: I0819 14:09:52.632045 18402 slave.cpp:8834] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0819 14:09:52.633837 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0819 14:09:52.634603 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0819 14:09:52.634858 18371 hierarchical.cpp:1177] Grew agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 by {} (total), { } (used)
3: I0819 14:09:52.635640 18371 hierarchical.cpp:1134] Agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 (5f6aaf744609) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0819 14:09:52.643775 18397 hierarchical.cpp:1920] Performed allocation for 1 agents in 405781ns
3: I0819 14:09:52.644021 18415 provider.cpp:791] Reconciling storage pools and volumes
3: I0819 14:09:52.647413 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0819 14:09:52.648079 55233 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0819 14:09:52.658869 18420 slave.cpp:1000] Agent terminating
3: I0819 14:09:52.660112 18420 manager.cpp:127] Terminating resource provider b621a7cc-37fe-4f06-9331-3d2fe1a5c856
3: I0819 14:09:52.660746 18389 master.cpp:1292] Agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 at slave(1244)@172.17.0.2:33643 (5f6aaf744609) disconnected
3: I0819 14:09:52.660809 18389 master.cpp:3361] Disconnecting agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 at slave(1244)@172.17.0.2:33643 (5f6aaf744609)
3: I0819 14:09:52.660949 18389 master.cpp:3380] Deactivating agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 at slave(1244)@172.17.0.2:33643 (5f6aaf744609)
3: I0819 14:09:52.661175 18418 hierarchical.cpp:1223] Agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0 deactivated
3: E0819 14:09:52.661455 18361 http_connection.hpp:449] End-Of-File received
3: I0819 14:09:52.662215 18361 http_connection.hpp:217] Re-detecting endpoint
3: I0819 14:09:52.662955 18361 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0819 14:09:52.663067 18391 provider.cpp:488] Disconnected from resource provider manager
3: I0819 14:09:52.663128 18361 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0819 14:09:52.663264 18391 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0819 14:09:52.663344 18361 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:33643/slave(1244)/api/v1/resource_provider
3: I0819 14:09:52.665570 18401 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
3: I0819 14:09:52.665685 18401 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.972908032secs
3: I0819 14:09:52.666358 18401 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 14:09:52.667582 18364 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:33643/slave(1244)/api/v1/resource_provider
3: I0819 14:09:52.668560 18385 provider.cpp:476] Connected to resource provider manager
3: I0819 14:09:52.669312 18399 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:33643/slave(1244)/api/v1/resource_provider
3: I0819 14:09:52.670446 18457 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1/resource_provider'
3: E0819 14:09:52.672183 18431 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
3: I0819 14:09:52.688359 18426 hierarchical.cpp:1920] Performed allocation for 1 agents in 204466ns
3: I0819 14:09:52.738065 18408 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
3: I0819 14:09:52.740216 18395 hierarchical.cpp:1920] Performed allocation for 1 agents in 184265ns
3: I0819 14:09:52.740489 18424 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 14:09:52.744181 18398 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'
3: I0819 14:09:52.744468 18437 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-ciU3BR/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 14:09:52.744796 18455 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 14:09:52.747931 18457 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1'
3: I0819 14:09:52.770972 18376 master.cpp:1140] Master terminating
3: I0819 14:09:52.771502 18455 hierarchical.cpp:1199] Removed all filters for agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0
3: I0819 14:09:52.771546 18455 hierarchical.cpp:1075] Removed agent 640b0491-dd19-4a0c-86c1-4b89e2eb33aa-S0
3: [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1269 ms)
3: [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (105182 ms total)
3:
3: [----------] Global test environment tear-down
3: [==========] 2273 tests from 216 test cases ran. (1054665 ms total)
3: [ PASSED ] 2272 tests.
3: [ FAILED ] 1 test, listed below:
3: [ FAILED ] SlaveTest.RunTaskGroupReferenceTypeSecret
3:
3: 1 FAILED TEST
3: YOU HAVE 34 DISABLED TESTS
3:
3: I0819 14:09:53.015148 18457 process.cpp:935] Stopped the socket accept loop
3/3 Test #3: MesosTests .......................***Failed 1057.61 sec
67% tests passed, 1 tests failed out of 3
Total Test time (real) = 1127.15 sec
The following tests FAILED:
3 - MesosTests (Failed)
Errors while running CTest
CMakeFiles/check.dir/build.make:60: recipe for target 'CMakeFiles/check' failed
make[3]: *** [CMakeFiles/check] Error 8
make[3]: Leaving directory '/tmp/SRC/build'
CMakeFiles/Makefile2:255: recipe for target 'CMakeFiles/check.dir/all' failed
make[2]: *** [CMakeFiles/check.dir/all] Error 2
make[2]: Leaving directory '/tmp/SRC/build'
CMakeFiles/Makefile2:262: recipe for target 'CMakeFiles/check.dir/rule' failed
make[1]: *** [CMakeFiles/check.dir/rule] Error 2
make[1]: Leaving directory '/tmp/SRC/build'
Makefile:278: recipe for target 'check' failed
make: *** [check] Error 2
real 82m54.049s
user 0m17.444s
sys 0m16.144s
Build step 'Execute shell' marked build as failure
Recording test results
Build failed in Jenkins: Mesos-Buildbot-ARM » cmake,clang,--verbose --disable-libtool-wrappers --disable-java --disable-python --disable-parallel-test-execution,GLOG_v=1 MESOS_VERBOSE=1 MESOS_TEST_AWAIT_TIMEOUT=60secs JOBS=16 GTEST_FILTER=-DiskQuotaTest.SlaveRecovery,arm1 #1774
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Buildbot-ARM/BUILDTOOL=cmake,COMPILER=clang,CONFIGURATION=--verbose%20--disable-libtool-wrappers%20--disable-java%20--disable-python%20--disable-parallel-test-execution,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1%20%20MESOS_TEST_AWAIT_TIMEOUT=60secs%20JOBS=16%20GTEST_FILTER=-DiskQuotaTest.SlaveRecovery,label_exp=arm1/1774/display/redirect?page=changes>
Changes:
[zhq527725] Exposed Mesos agent ID to managed CSI plugins.
------------------------------------------
[...truncated 48.23 MB...]
3: I0819 04:17:41.261914 18414 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
3: I0819 04:17:41.262406 18414 master.cpp:632] Authorization enabled
3: I0819 04:17:41.263267 18392 whitelist_watcher.cpp:77] No whitelist given
3: I0819 04:17:41.263447 18391 hierarchical.cpp:634] Initialized hierarchical allocator process
3: I0819 04:17:41.270534 18410 master.cpp:2165] Elected as the leading master!
3: I0819 04:17:41.270588 18410 master.cpp:1661] Recovering from registrar
3: I0819 04:17:41.271047 18397 registrar.cpp:339] Recovering registrar
3: I0819 04:17:41.272794 18397 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
3: I0819 04:17:41.273102 18397 registrar.cpp:487] Applied 1 operations in 117593ns; attempting to update the registry
3: I0819 04:17:41.274473 18397 registrar.cpp:544] Successfully updated the registry in 0ns
3: I0819 04:17:41.274741 18397 registrar.cpp:416] Successfully recovered registrar
3: I0819 04:17:41.275776 18363 master.cpp:1814] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
3: I0819 04:17:41.276240 18406 hierarchical.cpp:673] Skipping recovery of hierarchical allocator: nothing to recover
3: W0819 04:17:41.290340 18362 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:41087
3: I0819 04:17:41.293876 18362 containerizer.cpp:320] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W0819 04:17:41.295168 18362 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
3: W0819 04:17:41.295238 18362 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W0819 04:17:41.295295 18362 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I0819 04:17:41.295385 18362 provisioner.cpp:294] Using default backend 'copy'
3: I0819 04:17:41.301158 18362 cluster.cpp:533] Creating default 'local' authorizer
3: I0819 04:17:41.306174 18377 slave.cpp:279] Mesos agent started on (1244)@172.17.0.2:41087
3: I0819 04:17:41.306411 18377 slave.cpp:280] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/E3vvNB/4wrTAL/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/E3vvNB/4wrTAL/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/E3vvNB/4wrTAL/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/E3vvNB/4wrTAL/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/E3vvNB/4wrTAL/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/E3vvNB/4wrTAL/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/tmp/SRC/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/E3vvNB/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_75KEAs" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_CHcfz9" --zk_session_timeout="10secs"
3: I0819 04:17:41.307545 18377 credentials.hpp:73] Loading credential for authentication from '/tmp/E3vvNB/4wrTAL/credential'
3: I0819 04:17:41.307824 18377 slave.cpp:312] Agent using credential for: test-principal
3: I0819 04:17:41.307876 18377 credentials.hpp:37] Loading credentials for authentication from '/tmp/E3vvNB/4wrTAL/http_credentials'
3: I0819 04:17:41.308223 18377 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I0819 04:17:41.308923 18377 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
3: I0819 04:17:41.309140 18454 hierarchical.cpp:1920] Performed allocation for 0 agents in 209546ns
3: I0819 04:17:41.312559 18395 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
3: I0819 04:17:41.312841 18377 slave.cpp:627] 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"}]
3: I0819 04:17:41.313254 18377 slave.cpp:635] Agent attributes: [ ]
3: I0819 04:17:41.313309 18377 slave.cpp:644] Agent hostname: 2cc5a5279807
3: I0819 04:17:41.313699 18375 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0819 04:17:41.313740 18366 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0819 04:17:41.316684 18413 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_CHcfz9/meta'
3: I0819 04:17:41.317204 18424 slave.cpp:7723] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_CHcfz9/meta', beginning agent recovery
3: I0819 04:17:41.318291 18388 task_status_update_manager.cpp:207] Recovering task status update manager
3: I0819 04:17:41.319154 18437 containerizer.cpp:830] Recovering Mesos containers
3: I0819 04:17:41.319989 18437 containerizer.cpp:1170] Recovering isolators
3: I0819 04:17:41.321996 18365 containerizer.cpp:1209] Recovering provisioner
3: I0819 04:17:41.323652 18379 provisioner.cpp:518] Provisioner recovery complete
3: I0819 04:17:41.325140 18371 composing.cpp:343] Finished recovering all containerizers
3: I0819 04:17:41.325731 18430 slave.cpp:8205] Recovering executors
3: I0819 04:17:41.325961 18430 slave.cpp:8358] Finished recovery
3: I0819 04:17:41.327937 18416 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0819 04:17:41.328053 18404 slave.cpp:1471] New master detected at master@172.17.0.2:41087
3: I0819 04:17:41.328173 18392 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0819 04:17:41.328300 18404 slave.cpp:1536] Detecting new master
3: I0819 04:17:41.335750 18391 slave.cpp:1563] Authenticating with master master@172.17.0.2:41087
3: I0819 04:17:41.335886 18391 slave.cpp:1572] Using default CRAM-MD5 authenticatee
3: I0819 04:17:41.336414 18458 authenticatee.cpp:121] Creating new client SASL connection
3: I0819 04:17:41.336887 18385 master.cpp:9667] Authenticating slave(1244)@172.17.0.2:41087
3: I0819 04:17:41.337102 18431 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2106)@172.17.0.2:41087
3: I0819 04:17:41.337566 18410 authenticator.cpp:98] Creating new server SASL connection
3: I0819 04:17:41.338126 18433 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I0819 04:17:41.338204 18433 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I0819 04:17:41.338524 18390 authenticator.cpp:204] Received SASL authentication start
3: I0819 04:17:41.338729 18390 authenticator.cpp:326] Authentication requires more steps
3: I0819 04:17:41.338974 18418 authenticatee.cpp:259] Received SASL authentication step
3: I0819 04:17:41.339351 18408 authenticator.cpp:232] Received SASL authentication step
3: I0819 04:17:41.339568 18408 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2cc5a5279807' server FQDN: '2cc5a5279807' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I0819 04:17:41.339622 18408 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I0819 04:17:41.339741 18408 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I0819 04:17:41.339830 18408 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '2cc5a5279807' server FQDN: '2cc5a5279807' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I0819 04:17:41.339877 18408 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I0819 04:17:41.339913 18408 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I0819 04:17:41.339973 18408 authenticator.cpp:318] Authentication success
3: I0819 04:17:41.340142 18447 authenticatee.cpp:299] Authentication success
3: I0819 04:17:41.340562 18442 master.cpp:9699] Successfully authenticated principal 'test-principal' at slave(1244)@172.17.0.2:41087
3: I0819 04:17:41.340713 18401 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2106)@172.17.0.2:41087
3: I0819 04:17:41.341034 18393 slave.cpp:1663] Successfully authenticated with master master@172.17.0.2:41087
3: I0819 04:17:41.342314 18393 slave.cpp:2113] Will retry registration in 886926ns if necessary
3: I0819 04:17:41.342767 18398 master.cpp:6162] Received register agent message from slave(1244)@172.17.0.2:41087 (2cc5a5279807)
3: I0819 04:17:41.343729 18398 master.cpp:3693] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
3: I0819 04:17:41.344765 18427 slave.cpp:2113] Will retry registration in 5.144262ms if necessary
3: I0819 04:17:41.344810 18407 master.cpp:6229] Authorized registration of agent at slave(1244)@172.17.0.2:41087 (2cc5a5279807)
3: I0819 04:17:41.344990 18407 master.cpp:6341] Registering agent at slave(1244)@172.17.0.2:41087 (2cc5a5279807) with id 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0
3: I0819 04:17:41.345854 18407 master.cpp:6155] Ignoring register agent message from slave(1244)@172.17.0.2:41087 (2cc5a5279807) as registration is already in progress
3: I0819 04:17:41.346539 18402 registrar.cpp:487] Applied 1 operations in 642127ns; attempting to update the registry
3: I0819 04:17:41.347702 18402 registrar.cpp:544] Successfully updated the registry in 1.039872ms
3: I0819 04:17:41.348057 18444 master.cpp:6389] Admitted agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 at slave(1244)@172.17.0.2:41087 (2cc5a5279807)
3: I0819 04:17:41.349803 18444 master.cpp:6434] Registered agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 at slave(1244)@172.17.0.2:41087 (2cc5a5279807) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0819 04:17:41.350675 18443 slave.cpp:1696] Registered with master master@172.17.0.2:41087; given agent ID 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0
3: I0819 04:17:41.350703 18417 hierarchical.cpp:1026] Added agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 (2cc5a5279807) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
3: I0819 04:17:41.350977 18364 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I0819 04:17:41.351295 18417 hierarchical.cpp:1920] Performed allocation for 1 agents in 227846ns
3: I0819 04:17:41.351631 18443 slave.cpp:1731] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_CHcfz9/meta/slaves/69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0/slave.info'
3: I0819 04:17:41.351923 18428 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0819 04:17:41.354324 18443 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"Z2E8Bl9WSzmEFeeT/4zlLw=="},"slave_id":{"value":"69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0"},"update_oversubscribed_resources":false}
3: I0819 04:17:41.356616 18380 master.cpp:7575] Ignoring update on agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 at slave(1244)@172.17.0.2:41087 (2cc5a5279807) as it reports no changes
3: I0819 04:17:41.360697 18395 hierarchical.cpp:1920] Performed allocation for 1 agents in 282068ns
3: I0819 04:17:41.362274 18426 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0819 04:17:41.364188 18388 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:37522
3: I0819 04:17:41.365013 18388 http.cpp:2828] Processing GET_CONTAINERS call
3: I0819 04:17:41.375941 18423 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 04:17:41.379220 18387 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0819 04:17:41.380532 18399 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:37524
3: I0819 04:17:41.382036 18399 http.cpp:3289] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 04:17:41.383932 18399 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_CHcfz9/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 04:17:41.385320 18416 containerizer.cpp:1405] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 04:17:41.386492 18416 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 398848ns
3: I0819 04:17:41.388407 18416 containerizer.cpp:1584] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_75KEAs/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
3: I0819 04:17:41.388496 18416 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 2.006016ms
3: I0819 04:17:41.394217 18410 containerizer.cpp:2110] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_FanbyQ","--available_capacity=0B","--volumes=","--forward=unix:///tmp/E3vvNB/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_CHcfz9/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-qYydlo/endpoint.sock"},{"name":"MESOS_AGENT_ID","type":"VALUE","value":"69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_CHcfz9/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="49" --pipe_write="54" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_75KEAs/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
3: I0819 04:17:41.415737 18410 launcher.cpp:145] Forked child with pid '55227' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 04:17:41.417275 18418 hierarchical.cpp:1920] Performed allocation for 1 agents in 509973ns
3: I0819 04:17:41.417816 18410 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 29.315072ms
3: I0819 04:17:41.420814 18410 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 2.991872ms
3: I0819 04:17:41.421335 18393 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_CHcfz9/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 04:17:41.423547 18432 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 2.729984ms
3: I0819 04:17:41.428735 18449 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'
3: I0819 04:17:41.429224 18451 service_manager.cpp:795] Connecting to endpoint 'unix:///tmp/mesos-csi-qYydlo/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 04:17:41.468812 18364 hierarchical.cpp:1920] Performed allocation for 1 agents in 218606ns
3: I0819 04:17:41.521167 18443 hierarchical.cpp:1920] Performed allocation for 1 agents in 399300ns
3: I0819 04:17:41.572389 18454 hierarchical.cpp:1920] Performed allocation for 1 agents in 234726ns
3: I0819 04:17:41.623908 18375 hierarchical.cpp:1920] Performed allocation for 1 agents in 341059ns
3: I0819 04:17:41.675894 18456 hierarchical.cpp:1920] Performed allocation for 1 agents in 296858ns
3: I0819 04:17:41.727409 18429 hierarchical.cpp:1920] Performed allocation for 1 agents in 257587ns
3: I0819 04:17:41.778800 18439 hierarchical.cpp:1920] Performed allocation for 1 agents in 408440ns
3: I0819 04:17:41.830904 18382 hierarchical.cpp:1920] Performed allocation for 1 agents in 221365ns
3: I0819 04:17:41.881994 18371 hierarchical.cpp:1920] Performed allocation for 1 agents in 215646ns
3: I0819 04:17:41.934186 18392 hierarchical.cpp:1920] Performed allocation for 1 agents in 363129ns
3: I0819 04:17:41.986313 18385 hierarchical.cpp:1920] Performed allocation for 1 agents in 283127ns
3: I0819 04:17:42.038136 18418 hierarchical.cpp:1920] Performed allocation for 1 agents in 183265ns
3: I0819 04:17:42.089622 18406 hierarchical.cpp:1920] Performed allocation for 1 agents in 228656ns
3: I0819 04:17:42.140870 18412 hierarchical.cpp:1920] Performed allocation for 1 agents in 341239ns
3: I0819 04:17:42.192375 18389 hierarchical.cpp:1920] Performed allocation for 1 agents in 322748ns
3: I0819 04:17:42.243818 18450 hierarchical.cpp:1920] Performed allocation for 1 agents in 244907ns
3: I0819 04:17:42.286178 18421 service_manager.cpp:622] Probing endpoint 'unix:///tmp/mesos-csi-qYydlo/endpoint.sock' with CSI v1
3: I0819 04:17:42.290309 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call
3: I0819 04:17:42.295663 18381 hierarchical.cpp:1920] Performed allocation for 1 agents in 265447ns
3: I0819 04:17:42.296346 18435 container_daemon.cpp:171] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 04:17:42.301074 18377 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0819 04:17:42.301841 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call
3: I0819 04:17:42.303170 18424 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:37526
3: I0819 04:17:42.304024 18424 http.cpp:3513] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 04:17:42.309060 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0819 04:17:42.309831 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0819 04:17:42.312644 18457 v1_volume_manager.cpp:674] NODE_SERVICE loaded: {}
3: I0819 04:17:42.313786 18457 v1_volume_manager.cpp:674] CONTROLLER_SERVICE loaded: {}
3: I0819 04:17:42.317926 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
3: I0819 04:17:42.324877 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call
3: I0819 04:17:42.330554 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call
3: I0819 04:17:42.334686 18404 provider.cpp:677] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
3: I0819 04:17:42.334925 18422 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0819 04:17:42.335619 18416 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:41087/slave(1244)/api/v1/resource_provider
3: I0819 04:17:42.340735 18408 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:41087/slave(1244)/api/v1/resource_provider
3: I0819 04:17:42.341814 18397 provider.cpp:476] Connected to resource provider manager
3: I0819 04:17:42.342751 18406 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:41087/slave(1244)/api/v1/resource_provider
3: I0819 04:17:42.344614 18393 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0819 04:17:42.346930 18432 hierarchical.cpp:1920] Performed allocation for 1 agents in 223736ns
3: I0819 04:17:42.347015 18407 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:37528
3: I0819 04:17:42.348392 18449 manager.cpp:779] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_FanbyQ","--available_capacity=0B","--volumes=","--forward=unix:///tmp/E3vvNB/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}
3: I0819 04:17:42.355152 18417 slave.cpp:8714] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"8fd334a6-7a9c-4c73-aec0-881530744248"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_FanbyQ","--available_capacity=0B","--volumes=","--forward=unix:///tmp/E3vvNB/mock_csi.sock","--create_parameters=","--volume_metadata="],"shell":false,"value":"/tmp/SRC/build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":15.0},"type":"org.apache.mesos.rp.local.storage"}'
3: I0819 04:17:42.357883 18381 provider.cpp:498] Received SUBSCRIBED event
3: I0819 04:17:42.358047 18381 provider.cpp:1310] Subscribed with ID 8fd334a6-7a9c-4c73-aec0-881530744248
3: I0819 04:17:42.359486 18435 status_update_manager_process.hpp:314] Recovering operation status update manager
3: I0819 04:17:42.365783 18445 provider.cpp:791] Reconciling storage pools and volumes
3: I0819 04:17:42.369755 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0819 04:17:42.374548 18373 provider.cpp:2218] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0
3: I0819 04:17:42.375005 18372 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:41087/slave(1244)/api/v1/resource_provider
3: I0819 04:17:42.375175 18373 provider.cpp:749] Resource provider 8fd334a6-7a9c-4c73-aec0-881530744248 is in READY state
3: I0819 04:17:42.375252 18386 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0819 04:17:42.376381 18437 provider.cpp:1236] Updating profiles { test } for resource provider 8fd334a6-7a9c-4c73-aec0-881530744248
3: I0819 04:17:42.376572 18455 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0819 04:17:42.378170 18453 provider.cpp:791] Reconciling storage pools and volumes
3: I0819 04:17:42.378887 18371 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:37530
3: I0819 04:17:42.379830 18430 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 8fd334a6-7a9c-4c73-aec0-881530744248
3: I0819 04:17:42.380142 18384 slave.cpp:8714] Handling resource provider message 'UPDATE_STATE: 8fd334a6-7a9c-4c73-aec0-881530744248 {}'
3: I0819 04:17:42.380290 18384 slave.cpp:8834] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0819 04:17:42.382141 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0819 04:17:42.382997 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0819 04:17:42.383188 18416 hierarchical.cpp:1177] Grew agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 by {} (total), { } (used)
3: I0819 04:17:42.383983 18416 hierarchical.cpp:1134] Agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 (2cc5a5279807) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0819 04:17:42.392093 18393 hierarchical.cpp:1920] Performed allocation for 1 agents in 372600ns
3: I0819 04:17:42.392355 18389 provider.cpp:791] Reconciling storage pools and volumes
3: I0819 04:17:42.396088 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0819 04:17:42.396813 55231 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0819 04:17:42.407354 18452 slave.cpp:1000] Agent terminating
3: I0819 04:17:42.408668 18452 manager.cpp:127] Terminating resource provider 8fd334a6-7a9c-4c73-aec0-881530744248
3: I0819 04:17:42.409361 18456 master.cpp:1292] Agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 at slave(1244)@172.17.0.2:41087 (2cc5a5279807) disconnected
3: I0819 04:17:42.409426 18456 master.cpp:3361] Disconnecting agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 at slave(1244)@172.17.0.2:41087 (2cc5a5279807)
3: I0819 04:17:42.409562 18456 master.cpp:3380] Deactivating agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 at slave(1244)@172.17.0.2:41087 (2cc5a5279807)
3: I0819 04:17:42.409835 18386 hierarchical.cpp:1223] Agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0 deactivated
3: E0819 04:17:42.410024 18373 http_connection.hpp:449] End-Of-File received
3: I0819 04:17:42.410795 18373 http_connection.hpp:217] Re-detecting endpoint
3: I0819 04:17:42.411557 18373 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0819 04:17:42.411721 18455 provider.cpp:488] Disconnected from resource provider manager
3: I0819 04:17:42.411792 18373 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0819 04:17:42.411947 18373 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:41087/slave(1244)/api/v1/resource_provider
3: I0819 04:17:42.411972 18382 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0819 04:17:42.414173 18369 containerizer.cpp:2716] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
3: I0819 04:17:42.414278 18369 containerizer.cpp:3414] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 15.990745088secs
3: I0819 04:17:42.414842 18369 launcher.cpp:161] Asked to destroy container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 04:17:42.416330 18384 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:41087/slave(1244)/api/v1/resource_provider
3: I0819 04:17:42.417239 18391 provider.cpp:476] Connected to resource provider manager
3: I0819 04:17:42.418164 18431 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:41087/slave(1244)/api/v1/resource_provider
3: I0819 04:17:42.419268 18459 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1/resource_provider'
3: E0819 04:17:42.421058 18418 provider.cpp:722] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
3: I0819 04:17:42.435322 18390 hierarchical.cpp:1920] Performed allocation for 1 agents in 212866ns
3: I0819 04:17:42.486968 18406 hierarchical.cpp:1920] Performed allocation for 1 agents in 183745ns
3: I0819 04:17:42.487028 18401 containerizer.cpp:3252] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
3: I0819 04:17:42.489738 18432 provisioner.cpp:652] Ignoring destroy request for unknown container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 04:17:42.493834 18376 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'
3: I0819 04:17:42.494110 18368 service_manager.cpp:815] Disconnected from endpoint 'unix:///tmp/mesos-csi-qYydlo/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0819 04:17:42.494467 18417 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0819 04:17:42.497967 18459 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1'
3: I0819 04:17:42.519856 18376 master.cpp:1140] Master terminating
3: I0819 04:17:42.520339 18383 hierarchical.cpp:1199] Removed all filters for agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0
3: I0819 04:17:42.520391 18383 hierarchical.cpp:1075] Removed agent 69016f9b-6e12-4bf1-940c-ac83866bb4fe-S0
3: [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1315 ms)
3: [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (105423 ms total)
3:
3: [----------] Global test environment tear-down
3: [==========] 2273 tests from 216 test cases ran. (1067061 ms total)
3: [ PASSED ] 2272 tests.
3: [ FAILED ] 1 test, listed below:
3: [ FAILED ] SlaveTest.RunTaskGroupReferenceTypeSecret
3:
3: 1 FAILED TEST
3: YOU HAVE 34 DISABLED TESTS
3:
3: I0819 04:17:42.763180 18459 process.cpp:935] Stopped the socket accept loop
3/3 Test #3: MesosTests .......................***Failed 1070.02 sec
67% tests passed, 1 tests failed out of 3
Total Test time (real) = 1139.58 sec
The following tests FAILED:
3 - MesosTests (Failed)
Errors while running CTest
CMakeFiles/check.dir/build.make:60: recipe for target 'CMakeFiles/check' failed
make[3]: *** [CMakeFiles/check] Error 8
make[3]: Leaving directory '/tmp/SRC/build'
CMakeFiles/Makefile2:255: recipe for target 'CMakeFiles/check.dir/all' failed
make[2]: *** [CMakeFiles/check.dir/all] Error 2
make[2]: Leaving directory '/tmp/SRC/build'
CMakeFiles/Makefile2:262: recipe for target 'CMakeFiles/check.dir/rule' failed
make[1]: *** [CMakeFiles/check.dir/rule] Error 2
make[1]: Leaving directory '/tmp/SRC/build'
Makefile:278: recipe for target 'check' failed
make: *** [check] Error 2
real 83m7.562s
user 0m17.935s
sys 0m15.913s
Build step 'Execute shell' marked build as failure
Recording test results