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/14 02:15:50 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 #1771
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/1771/display/redirect?page=changes>
Changes:
[zhq527725] Updated the help message of the agent flag `--csi_plugin_config_dir`.
------------------------------------------
[...truncated 48.18 MB...]
3: I0814 02:15:39.754633 18382 registrar.cpp:339] Recovering registrar
3: I0814 02:15:39.756033 18382 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
3: I0814 02:15:39.756305 18382 registrar.cpp:487] Applied 1 operations in 112753ns; attempting to update the registry
3: I0814 02:15:39.757527 18382 registrar.cpp:544] Successfully updated the registry in 0ns
3: I0814 02:15:39.757779 18382 registrar.cpp:416] Successfully recovered registrar
3: I0814 02:15:39.758688 18402 hierarchical.cpp:673] Skipping recovery of hierarchical allocator: nothing to recover
3: I0814 02:15:39.758656 18384 master.cpp:1814] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
3: W0814 02:15:39.771129 18339 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:46467
3: I0814 02:15:39.774269 18339 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W0814 02:15:39.775477 18339 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
3: W0814 02:15:39.775544 18339 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W0814 02:15:39.775601 18339 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I0814 02:15:39.775682 18339 provisioner.cpp:294] Using default backend 'copy'
3: I0814 02:15:39.780519 18339 cluster.cpp:533] Creating default 'local' authorizer
3: I0814 02:15:39.785197 18346 slave.cpp:279] Mesos agent started on (1244)@172.17.0.2:46467
3: I0814 02:15:39.785305 18346 slave.cpp:280] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/PmjRpD/VvYATc/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/PmjRpD/VvYATc/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/PmjRpD/VvYATc/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/PmjRpD/VvYATc/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/PmjRpD/VvYATc/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/PmjRpD/VvYATc/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/PmjRpD/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_vW8sPi" --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_rYqWLo" --zk_session_timeout="10secs"
3: I0814 02:15:39.786293 18346 credentials.hpp:73] Loading credential for authentication from '/tmp/PmjRpD/VvYATc/credential'
3: I0814 02:15:39.786571 18346 slave.cpp:312] Agent using credential for: test-principal
3: I0814 02:15:39.786623 18346 credentials.hpp:37] Loading credentials for authentication from '/tmp/PmjRpD/VvYATc/http_credentials'
3: I0814 02:15:39.786955 18346 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I0814 02:15:39.787588 18346 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
3: I0814 02:15:39.787847 18433 hierarchical.cpp:1920] Performed allocation for 0 agents in 125953ns
3: I0814 02:15:39.790283 18343 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
3: I0814 02:15:39.790812 18346 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: I0814 02:15:39.791182 18346 slave.cpp:635] Agent attributes: [ ]
3: I0814 02:15:39.791222 18346 slave.cpp:644] Agent hostname: ae45fcb64a52
3: I0814 02:15:39.791529 18405 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0814 02:15:39.791571 18355 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0814 02:15:39.795112 18403 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rYqWLo/meta'
3: I0814 02:15:39.795475 18401 slave.cpp:7723] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rYqWLo/meta', beginning agent recovery
3: I0814 02:15:39.796476 18392 task_status_update_manager.cpp:207] Recovering task status update manager
3: I0814 02:15:39.797191 18389 containerizer.cpp:822] Recovering Mesos containers
3: I0814 02:15:39.797796 18389 containerizer.cpp:1162] Recovering isolators
3: I0814 02:15:39.799453 18351 containerizer.cpp:1201] Recovering provisioner
3: I0814 02:15:39.800678 18341 provisioner.cpp:518] Provisioner recovery complete
3: I0814 02:15:39.801864 18386 composing.cpp:343] Finished recovering all containerizers
3: I0814 02:15:39.802366 18370 slave.cpp:8205] Recovering executors
3: I0814 02:15:39.802556 18370 slave.cpp:8358] Finished recovery
3: I0814 02:15:39.804008 18431 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0814 02:15:39.804054 18410 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0814 02:15:39.804083 18370 slave.cpp:1471] New master detected at master@172.17.0.2:46467
3: I0814 02:15:39.804270 18370 slave.cpp:1536] Detecting new master
3: I0814 02:15:39.807713 18367 slave.cpp:1563] Authenticating with master master@172.17.0.2:46467
3: I0814 02:15:39.807852 18367 slave.cpp:1572] Using default CRAM-MD5 authenticatee
3: I0814 02:15:39.808357 18409 authenticatee.cpp:121] Creating new client SASL connection
3: I0814 02:15:39.808918 18366 master.cpp:9667] Authenticating slave(1244)@172.17.0.2:46467
3: I0814 02:15:39.809150 18372 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2105)@172.17.0.2:46467
3: I0814 02:15:39.809648 18414 authenticator.cpp:98] Creating new server SASL connection
3: I0814 02:15:39.810081 18353 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I0814 02:15:39.810153 18353 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I0814 02:15:39.810415 18412 authenticator.cpp:204] Received SASL authentication start
3: I0814 02:15:39.810561 18412 authenticator.cpp:326] Authentication requires more steps
3: I0814 02:15:39.810775 18340 authenticatee.cpp:259] Received SASL authentication step
3: I0814 02:15:39.811017 18348 authenticator.cpp:232] Received SASL authentication step
3: I0814 02:15:39.811131 18348 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ae45fcb64a52' server FQDN: 'ae45fcb64a52' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I0814 02:15:39.811182 18348 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I0814 02:15:39.811276 18348 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I0814 02:15:39.811355 18348 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ae45fcb64a52' server FQDN: 'ae45fcb64a52' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I0814 02:15:39.811403 18348 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I0814 02:15:39.811437 18348 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I0814 02:15:39.811484 18348 authenticator.cpp:318] Authentication success
3: I0814 02:15:39.811645 18419 authenticatee.cpp:299] Authentication success
3: I0814 02:15:39.811817 18420 master.cpp:9699] Successfully authenticated principal 'test-principal' at slave(1244)@172.17.0.2:46467
3: I0814 02:15:39.811940 18415 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2105)@172.17.0.2:46467
3: I0814 02:15:39.812239 18413 slave.cpp:1663] Successfully authenticated with master master@172.17.0.2:46467
3: I0814 02:15:39.813165 18413 slave.cpp:2113] Will retry registration in 4.199982ms if necessary
3: I0814 02:15:39.813506 18432 master.cpp:6162] Received register agent message from slave(1244)@172.17.0.2:46467 (ae45fcb64a52)
3: I0814 02:15:39.814312 18432 master.cpp:3693] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
3: I0814 02:15:39.815263 18356 master.cpp:6229] Authorized registration of agent at slave(1244)@172.17.0.2:46467 (ae45fcb64a52)
3: I0814 02:15:39.815438 18356 master.cpp:6341] Registering agent at slave(1244)@172.17.0.2:46467 (ae45fcb64a52) with id 16a28219-3875-4e09-9481-40415cdc9679-S0
3: I0814 02:15:39.816680 18395 registrar.cpp:487] Applied 1 operations in 594806ns; attempting to update the registry
3: I0814 02:15:39.817675 18395 registrar.cpp:544] Successfully updated the registry in 886272ns
3: I0814 02:15:39.817968 18391 master.cpp:6389] Admitted agent 16a28219-3875-4e09-9481-40415cdc9679-S0 at slave(1244)@172.17.0.2:46467 (ae45fcb64a52)
3: I0814 02:15:39.818470 18381 slave.cpp:2113] Will retry registration in 37.238711ms if necessary
3: I0814 02:15:39.819186 18391 master.cpp:6434] Registered agent 16a28219-3875-4e09-9481-40415cdc9679-S0 at slave(1244)@172.17.0.2:46467 (ae45fcb64a52) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0814 02:15:39.819372 18416 slave.cpp:1696] Registered with master master@172.17.0.2:46467; given agent ID 16a28219-3875-4e09-9481-40415cdc9679-S0
3: I0814 02:15:39.819571 18407 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I0814 02:15:39.819615 18435 hierarchical.cpp:1026] Added agent 16a28219-3875-4e09-9481-40415cdc9679-S0 (ae45fcb64a52) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
3: I0814 02:15:39.819725 18391 master.cpp:6162] Received register agent message from slave(1244)@172.17.0.2:46467 (ae45fcb64a52)
3: I0814 02:15:39.820128 18435 hierarchical.cpp:1920] Performed allocation for 1 agents in 246416ns
3: I0814 02:15:39.820336 18416 slave.cpp:1731] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rYqWLo/meta/slaves/16a28219-3875-4e09-9481-40415cdc9679-S0/slave.info'
3: I0814 02:15:39.820430 18422 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0814 02:15:39.820477 18391 master.cpp:3693] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
3: I0814 02:15:39.821240 18385 master.cpp:6229] Authorized registration of agent at slave(1244)@172.17.0.2:46467 (ae45fcb64a52)
3: I0814 02:15:39.821403 18385 master.cpp:6320] Agent 16a28219-3875-4e09-9481-40415cdc9679-S0 at slave(1244)@172.17.0.2:46467 (ae45fcb64a52) already registered, resending acknowledgement
3: I0814 02:15:39.822619 18416 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"SZAEzbceSsaD2OYOXMFQVw=="},"slave_id":{"value":"16a28219-3875-4e09-9481-40415cdc9679-S0"},"update_oversubscribed_resources":false}
3: W0814 02:15:39.823055 18416 slave.cpp:1765] Already registered with master master@172.17.0.2:46467
3: I0814 02:15:39.823129 18416 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"SZAEzbceSsaD2OYOXMFQVw=="},"slave_id":{"value":"16a28219-3875-4e09-9481-40415cdc9679-S0"},"update_oversubscribed_resources":false}
3: I0814 02:15:39.824270 18400 master.cpp:7575] Ignoring update on agent 16a28219-3875-4e09-9481-40415cdc9679-S0 at slave(1244)@172.17.0.2:46467 (ae45fcb64a52) as it reports no changes
3: I0814 02:15:39.825523 18400 master.cpp:7575] Ignoring update on agent 16a28219-3875-4e09-9481-40415cdc9679-S0 at slave(1244)@172.17.0.2:46467 (ae45fcb64a52) as it reports no changes
3: I0814 02:15:39.830541 18346 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0814 02:15:39.832171 18371 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:36648
3: I0814 02:15:39.833022 18371 http.cpp:2828] Processing GET_CONTAINERS call
3: I0814 02:15:39.839587 18397 hierarchical.cpp:1920] Performed allocation for 1 agents in 233316ns
3: I0814 02:15:39.842756 18388 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0814 02:15:39.846248 18360 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0814 02:15:39.847574 18354 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:36650
3: I0814 02:15:39.849123 18354 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: I0814 02:15:39.851042 18354 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rYqWLo/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0814 02:15:39.852144 18417 containerizer.cpp:1397] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0814 02:15:39.853349 18417 containerizer.cpp:3406] 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 433920ns
3: I0814 02:15:39.854938 18417 containerizer.cpp:1576] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_vW8sPi/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
3: I0814 02:15:39.855027 18417 containerizer.cpp:3406] 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.681152ms
3: I0814 02:15:39.860651 18353 containerizer.cpp:2102] 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_hDytGu","--available_capacity=0B","--volumes=","--forward=unix:///tmp/PmjRpD/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_rYqWLo/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-7Xf4AZ/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_rYqWLo/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_vW8sPi/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
3: I0814 02:15:39.879587 18353 launcher.cpp:145] Forked child with pid '55200' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0814 02:15:39.881708 18353 containerizer.cpp:3406] 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.668032ms
3: I0814 02:15:39.884894 18353 containerizer.cpp:3406] 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.19488ms
3: I0814 02:15:39.885417 18396 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_rYqWLo/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0814 02:15:39.887377 18432 containerizer.cpp:3406] 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.462976ms
3: I0814 02:15:39.891495 18425 hierarchical.cpp:1920] Performed allocation for 1 agents in 480072ns
3: I0814 02:15:39.892691 18430 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: I0814 02:15:39.893115 18390 service_manager.cpp:775] Connecting to endpoint 'unix:///tmp/mesos-csi-7Xf4AZ/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0814 02:15:39.943274 18385 hierarchical.cpp:1920] Performed allocation for 1 agents in 276728ns
3: I0814 02:15:39.994400 18429 hierarchical.cpp:1920] Performed allocation for 1 agents in 291288ns
3: I0814 02:15:40.045819 18433 hierarchical.cpp:1920] Performed allocation for 1 agents in 267147ns
3: I0814 02:15:40.097121 18365 hierarchical.cpp:1920] Performed allocation for 1 agents in 309398ns
3: I0814 02:15:40.149394 18371 hierarchical.cpp:1920] Performed allocation for 1 agents in 333919ns
3: I0814 02:15:40.200964 18368 hierarchical.cpp:1920] Performed allocation for 1 agents in 367060ns
3: I0814 02:15:40.252451 18423 hierarchical.cpp:1920] Performed allocation for 1 agents in 233676ns
3: I0814 02:15:40.303984 18360 hierarchical.cpp:1920] Performed allocation for 1 agents in 384521ns
3: I0814 02:15:40.355835 18431 hierarchical.cpp:1920] Performed allocation for 1 agents in 225416ns
3: I0814 02:15:40.407522 18417 hierarchical.cpp:1920] Performed allocation for 1 agents in 236406ns
3: I0814 02:15:40.459025 18340 hierarchical.cpp:1920] Performed allocation for 1 agents in 261587ns
3: I0814 02:15:40.510082 18348 hierarchical.cpp:1920] Performed allocation for 1 agents in 286488ns
3: I0814 02:15:40.561194 18353 hierarchical.cpp:1920] Performed allocation for 1 agents in 214595ns
3: I0814 02:15:40.613135 18361 hierarchical.cpp:1920] Performed allocation for 1 agents in 236536ns
3: I0814 02:15:40.664288 18435 hierarchical.cpp:1920] Performed allocation for 1 agents in 236956ns
3: I0814 02:15:40.715490 18362 hierarchical.cpp:1920] Performed allocation for 1 agents in 230486ns
3: I0814 02:15:40.748268 18377 service_manager.cpp:617] Probing endpoint 'unix:///tmp/mesos-csi-7Xf4AZ/endpoint.sock' with CSI v1
3: I0814 02:15:40.752337 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call
3: I0814 02:15:40.758173 18426 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: I0814 02:15:40.763141 18358 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0814 02:15:40.763257 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call
3: I0814 02:15:40.764935 18357 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:36652
3: I0814 02:15:40.765990 18357 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: I0814 02:15:40.766526 18371 hierarchical.cpp:1920] Performed allocation for 1 agents in 226076ns
3: I0814 02:15:40.771343 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0814 02:15:40.772068 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0814 02:15:40.774798 18342 v1_volume_manager.cpp:674] NODE_SERVICE loaded: {}
3: I0814 02:15:40.775738 18342 v1_volume_manager.cpp:674] CONTROLLER_SERVICE loaded: {}
3: I0814 02:15:40.779652 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
3: I0814 02:15:40.786103 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call
3: I0814 02:15:40.792237 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call
3: I0814 02:15:40.796000 18370 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
3: I0814 02:15:40.796228 18373 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0814 02:15:40.796955 18417 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:46467/slave(1244)/api/v1/resource_provider
3: I0814 02:15:40.800830 18412 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:46467/slave(1244)/api/v1/resource_provider
3: I0814 02:15:40.801898 18348 provider.cpp:476] Connected to resource provider manager
3: I0814 02:15:40.803123 18384 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:46467/slave(1244)/api/v1/resource_provider
3: I0814 02:15:40.804742 18353 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0814 02:15:40.807107 18350 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:36654
3: I0814 02:15:40.808662 18427 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_hDytGu","--available_capacity=0B","--volumes=","--forward=unix:///tmp/PmjRpD/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: I0814 02:15:40.815019 18421 slave.cpp:8714] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"88e04846-3861-4e33-9888-4766112c25e1"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_hDytGu","--available_capacity=0B","--volumes=","--forward=unix:///tmp/PmjRpD/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: I0814 02:15:40.817229 18393 provider.cpp:498] Received SUBSCRIBED event
3: I0814 02:15:40.817312 18393 provider.cpp:1309] Subscribed with ID 88e04846-3861-4e33-9888-4766112c25e1
3: I0814 02:15:40.818138 18428 hierarchical.cpp:1920] Performed allocation for 1 agents in 327498ns
3: I0814 02:15:40.818871 18363 status_update_manager_process.hpp:314] Recovering operation status update manager
3: I0814 02:15:40.825094 18400 provider.cpp:790] Reconciling storage pools and volumes
3: I0814 02:15:40.828881 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0814 02:15:40.833196 18357 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 16a28219-3875-4e09-9481-40415cdc9679-S0
3: I0814 02:15:40.833573 18380 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:46467/slave(1244)/api/v1/resource_provider
3: I0814 02:15:40.833745 18357 provider.cpp:748] Resource provider 88e04846-3861-4e33-9888-4766112c25e1 is in READY state
3: I0814 02:15:40.833824 18387 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0814 02:15:40.834923 18404 provider.cpp:1235] Updating profiles { test } for resource provider 88e04846-3861-4e33-9888-4766112c25e1
3: I0814 02:15:40.835136 18375 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0814 02:15:40.836587 18349 provider.cpp:790] Reconciling storage pools and volumes
3: I0814 02:15:40.837339 18386 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:36656
3: I0814 02:15:40.838409 18374 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 88e04846-3861-4e33-9888-4766112c25e1
3: I0814 02:15:40.838861 18354 slave.cpp:8714] Handling resource provider message 'UPDATE_STATE: 88e04846-3861-4e33-9888-4766112c25e1 {}'
3: I0814 02:15:40.839011 18354 slave.cpp:8834] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0814 02:15:40.840579 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0814 02:15:40.841559 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0814 02:15:40.842161 18417 hierarchical.cpp:1177] Grew agent 16a28219-3875-4e09-9481-40415cdc9679-S0 by {} (total), { } (used)
3: I0814 02:15:40.843050 18417 hierarchical.cpp:1134] Agent 16a28219-3875-4e09-9481-40415cdc9679-S0 (ae45fcb64a52) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0814 02:15:40.850551 18396 hierarchical.cpp:1920] Performed allocation for 1 agents in 309238ns
3: I0814 02:15:40.850934 18381 provider.cpp:790] Reconciling storage pools and volumes
3: I0814 02:15:40.854421 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0814 02:15:40.855268 55204 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0814 02:15:40.865888 18339 slave.cpp:1000] Agent terminating
3: I0814 02:15:40.867218 18339 manager.cpp:127] Terminating resource provider 88e04846-3861-4e33-9888-4766112c25e1
3: I0814 02:15:40.867908 18371 master.cpp:1292] Agent 16a28219-3875-4e09-9481-40415cdc9679-S0 at slave(1244)@172.17.0.2:46467 (ae45fcb64a52) disconnected
3: I0814 02:15:40.867974 18371 master.cpp:3361] Disconnecting agent 16a28219-3875-4e09-9481-40415cdc9679-S0 at slave(1244)@172.17.0.2:46467 (ae45fcb64a52)
3: I0814 02:15:40.868127 18371 master.cpp:3380] Deactivating agent 16a28219-3875-4e09-9481-40415cdc9679-S0 at slave(1244)@172.17.0.2:46467 (ae45fcb64a52)
3: I0814 02:15:40.868376 18434 hierarchical.cpp:1223] Agent 16a28219-3875-4e09-9481-40415cdc9679-S0 deactivated
3: E0814 02:15:40.868463 18411 http_connection.hpp:449] End-Of-File received
3: I0814 02:15:40.869215 18411 http_connection.hpp:217] Re-detecting endpoint
3: I0814 02:15:40.869969 18411 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0814 02:15:40.870090 18408 provider.cpp:488] Disconnected from resource provider manager
3: I0814 02:15:40.870157 18411 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0814 02:15:40.870301 18411 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:46467/slave(1244)/api/v1/resource_provider
3: I0814 02:15:40.870340 18364 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0814 02:15:40.872426 18349 containerizer.cpp:2708] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
3: I0814 02:15:40.872529 18349 containerizer.cpp:3406] 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.985176064secs
3: I0814 02:15:40.873147 18349 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: I0814 02:15:40.874527 18394 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:46467/slave(1244)/api/v1/resource_provider
3: I0814 02:15:40.875386 18366 provider.cpp:476] Connected to resource provider manager
3: I0814 02:15:40.876255 18420 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:46467/slave(1244)/api/v1/resource_provider
3: I0814 02:15:40.877348 18436 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1/resource_provider'
3: E0814 02:15:40.879150 18412 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' ()
3: I0814 02:15:40.894198 18419 hierarchical.cpp:1920] Performed allocation for 1 agents in 230186ns
3: I0814 02:15:40.944875 18344 containerizer.cpp:3244] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
3: I0814 02:15:40.946135 18415 hierarchical.cpp:1920] Performed allocation for 1 agents in 398760ns
3: I0814 02:15:40.947445 18396 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: I0814 02:15:40.951671 18424 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: I0814 02:15:40.951968 18352 service_manager.cpp:795] Disconnected from endpoint 'unix:///tmp/mesos-csi-7Xf4AZ/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0814 02:15:40.952304 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: I0814 02:15:40.955942 18436 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1'
3: I0814 02:15:40.978353 18352 master.cpp:1140] Master terminating
3: I0814 02:15:40.978946 18416 hierarchical.cpp:1199] Removed all filters for agent 16a28219-3875-4e09-9481-40415cdc9679-S0
3: I0814 02:15:40.978992 18416 hierarchical.cpp:1075] Removed agent 16a28219-3875-4e09-9481-40415cdc9679-S0
3: [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1280 ms)
3: [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (105106 ms total)
3:
3: [----------] Global test environment tear-down
3: [==========] 2273 tests from 216 test cases ran. (1055435 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: I0814 02:15:41.222154 18436 process.cpp:935] Stopped the socket accept loop
3/3 Test #3: MesosTests .......................***Failed 1058.39 sec
67% tests passed, 1 tests failed out of 3
Total Test time (real) = 1128.11 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 82m57.780s
user 0m17.539s
sys 0m15.958s
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
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
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/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 #1772
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/1772/display/redirect?page=changes>
Changes:
[zhq527725] Updated volume manager to support user specified target path root.
------------------------------------------
[...truncated 48.19 MB...]
3: I0818 04:09:41.780330 18378 registrar.cpp:339] Recovering registrar
3: I0818 04:09:41.781649 18378 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns
3: I0818 04:09:41.781895 18378 registrar.cpp:487] Applied 1 operations in 102632ns; attempting to update the registry
3: I0818 04:09:41.783041 18378 registrar.cpp:544] Successfully updated the registry in 0ns
3: I0818 04:09:41.783273 18378 registrar.cpp:416] Successfully recovered registrar
3: I0818 04:09:41.784225 18440 hierarchical.cpp:673] Skipping recovery of hierarchical allocator: nothing to recover
3: I0818 04:09:41.784186 18407 master.cpp:1814] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister
3: W0818 04:09:41.797169 18347 process.cpp:2877] Attempted to spawn already running process files@172.17.0.2:43017
3: I0818 04:09:41.800324 18347 containerizer.cpp:317] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
3: W0818 04:09:41.801628 18347 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
3: W0818 04:09:41.801699 18347 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges
3: W0818 04:09:41.801757 18347 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
3: I0818 04:09:41.801849 18347 provisioner.cpp:294] Using default backend 'copy'
3: I0818 04:09:41.806805 18347 cluster.cpp:533] Creating default 'local' authorizer
3: I0818 04:09:41.811563 18417 slave.cpp:279] Mesos agent started on (1244)@172.17.0.2:43017
3: I0818 04:09:41.811641 18417 slave.cpp:280] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/lOsUT9/Vmf6GN/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/lOsUT9/Vmf6GN/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/lOsUT9/Vmf6GN/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/lOsUT9/Vmf6GN/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/lOsUT9/Vmf6GN/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/lOsUT9/Vmf6GN/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/lOsUT9/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_fCIXYR" --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_JoK3eW" --zk_session_timeout="10secs"
3: I0818 04:09:41.812566 18417 credentials.hpp:73] Loading credential for authentication from '/tmp/lOsUT9/Vmf6GN/credential'
3: I0818 04:09:41.812847 18417 slave.cpp:312] Agent using credential for: test-principal
3: I0818 04:09:41.812901 18417 credentials.hpp:37] Loading credentials for authentication from '/tmp/lOsUT9/Vmf6GN/http_credentials'
3: I0818 04:09:41.813237 18417 http.cpp:1296] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
3: I0818 04:09:41.813880 18417 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
3: I0818 04:09:41.814198 18362 hierarchical.cpp:1920] Performed allocation for 0 agents in 143914ns
3: I0818 04:09:41.816602 18429 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles
3: I0818 04:09:41.817095 18417 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 04:09:41.817526 18417 slave.cpp:635] Agent attributes: [ ]
3: I0818 04:09:41.817569 18417 slave.cpp:644] Agent hostname: 5f616c95e804
3: I0818 04:09:41.817862 18391 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0818 04:09:41.817905 18356 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0818 04:09:41.821413 18404 state.cpp:68] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_JoK3eW/meta'
3: I0818 04:09:41.821805 18358 slave.cpp:7723] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_JoK3eW/meta', beginning agent recovery
3: I0818 04:09:41.822863 18423 task_status_update_manager.cpp:207] Recovering task status update manager
3: I0818 04:09:41.823601 18383 containerizer.cpp:822] Recovering Mesos containers
3: I0818 04:09:41.824234 18383 containerizer.cpp:1162] Recovering isolators
3: I0818 04:09:41.825820 18351 containerizer.cpp:1201] Recovering provisioner
3: I0818 04:09:41.826850 18385 provisioner.cpp:518] Provisioner recovery complete
3: I0818 04:09:41.828131 18386 composing.cpp:343] Finished recovering all containerizers
3: I0818 04:09:41.828619 18400 slave.cpp:8205] Recovering executors
3: I0818 04:09:41.828819 18400 slave.cpp:8358] Finished recovery
3: I0818 04:09:41.830601 18363 task_status_update_manager.cpp:181] Pausing sending task status updates
3: I0818 04:09:41.830655 18372 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0818 04:09:41.830677 18400 slave.cpp:1471] New master detected at master@172.17.0.2:43017
3: I0818 04:09:41.830865 18400 slave.cpp:1536] Detecting new master
3: I0818 04:09:41.834287 18442 slave.cpp:1563] Authenticating with master master@172.17.0.2:43017
3: I0818 04:09:41.834419 18442 slave.cpp:1572] Using default CRAM-MD5 authenticatee
3: I0818 04:09:41.834898 18437 authenticatee.cpp:121] Creating new client SASL connection
3: I0818 04:09:41.835448 18390 master.cpp:9667] Authenticating slave(1244)@172.17.0.2:43017
3: I0818 04:09:41.835703 18398 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2104)@172.17.0.2:43017
3: I0818 04:09:41.836163 18393 authenticator.cpp:98] Creating new server SASL connection
3: I0818 04:09:41.836560 18379 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
3: I0818 04:09:41.836634 18379 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
3: I0818 04:09:41.836853 18367 authenticator.cpp:204] Received SASL authentication start
3: I0818 04:09:41.837003 18367 authenticator.cpp:326] Authentication requires more steps
3: I0818 04:09:41.837201 18384 authenticatee.cpp:259] Received SASL authentication step
3: I0818 04:09:41.837464 18389 authenticator.cpp:232] Received SASL authentication step
3: I0818 04:09:41.837563 18389 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5f616c95e804' server FQDN: '5f616c95e804' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
3: I0818 04:09:41.837615 18389 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
3: I0818 04:09:41.837708 18389 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
3: I0818 04:09:41.837790 18389 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '5f616c95e804' server FQDN: '5f616c95e804' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
3: I0818 04:09:41.837838 18389 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
3: I0818 04:09:41.837874 18389 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
3: I0818 04:09:41.837924 18389 authenticator.cpp:318] Authentication success
3: I0818 04:09:41.838116 18364 authenticatee.cpp:299] Authentication success
3: I0818 04:09:41.838274 18396 master.cpp:9699] Successfully authenticated principal 'test-principal' at slave(1244)@172.17.0.2:43017
3: I0818 04:09:41.838335 18435 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2104)@172.17.0.2:43017
3: I0818 04:09:41.838836 18422 slave.cpp:1663] Successfully authenticated with master master@172.17.0.2:43017
3: I0818 04:09:41.839681 18422 slave.cpp:2113] Will retry registration in 4.199982ms if necessary
3: I0818 04:09:41.840001 18426 master.cpp:6162] Received register agent message from slave(1244)@172.17.0.2:43017 (5f616c95e804)
3: I0818 04:09:41.840764 18426 master.cpp:3693] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
3: I0818 04:09:41.841785 18405 master.cpp:6229] Authorized registration of agent at slave(1244)@172.17.0.2:43017 (5f616c95e804)
3: I0818 04:09:41.841953 18405 master.cpp:6341] Registering agent at slave(1244)@172.17.0.2:43017 (5f616c95e804) with id 59965c05-0ca6-4586-9fc0-206dedf3203c-S0
3: I0818 04:09:41.843236 18355 registrar.cpp:487] Applied 1 operations in 584185ns; attempting to update the registry
3: I0818 04:09:41.844388 18355 registrar.cpp:544] Successfully updated the registry in 1.043968ms
3: I0818 04:09:41.844700 18365 master.cpp:6389] Admitted agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 at slave(1244)@172.17.0.2:43017 (5f616c95e804)
3: I0818 04:09:41.844856 18439 slave.cpp:2113] Will retry registration in 37.238711ms if necessary
3: I0818 04:09:41.846137 18436 slave.cpp:1696] Registered with master master@172.17.0.2:43017; given agent ID 59965c05-0ca6-4586-9fc0-206dedf3203c-S0
3: I0818 04:09:41.845945 18365 master.cpp:6434] Registered agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 at slave(1244)@172.17.0.2:43017 (5f616c95e804) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0818 04:09:41.846380 18430 task_status_update_manager.cpp:188] Resuming sending task status updates
3: I0818 04:09:41.846351 18402 hierarchical.cpp:1026] Added agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 (5f616c95e804) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
3: I0818 04:09:41.846632 18365 master.cpp:6162] Received register agent message from slave(1244)@172.17.0.2:43017 (5f616c95e804)
3: I0818 04:09:41.846859 18402 hierarchical.cpp:1920] Performed allocation for 1 agents in 204675ns
3: I0818 04:09:41.847031 18436 slave.cpp:1731] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_JoK3eW/meta/slaves/59965c05-0ca6-4586-9fc0-206dedf3203c-S0/slave.info'
3: I0818 04:09:41.847121 18411 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0818 04:09:41.847396 18365 master.cpp:3693] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
3: I0818 04:09:41.848217 18441 master.cpp:6229] Authorized registration of agent at slave(1244)@172.17.0.2:43017 (5f616c95e804)
3: I0818 04:09:41.848369 18441 master.cpp:6320] Agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 at slave(1244)@172.17.0.2:43017 (5f616c95e804) already registered, resending acknowledgement
3: I0818 04:09:41.849146 18436 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"IfhJhg/XQAilF2jAamEjEw=="},"slave_id":{"value":"59965c05-0ca6-4586-9fc0-206dedf3203c-S0"},"update_oversubscribed_resources":false}
3: W0818 04:09:41.849628 18436 slave.cpp:1765] Already registered with master master@172.17.0.2:43017
3: I0818 04:09:41.849707 18436 slave.cpp:1783] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"IfhJhg/XQAilF2jAamEjEw=="},"slave_id":{"value":"59965c05-0ca6-4586-9fc0-206dedf3203c-S0"},"update_oversubscribed_resources":false}
3: I0818 04:09:41.850850 18432 master.cpp:7575] Ignoring update on agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 at slave(1244)@172.17.0.2:43017 (5f616c95e804) as it reports no changes
3: I0818 04:09:41.852133 18432 master.cpp:7575] Ignoring update on agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 at slave(1244)@172.17.0.2:43017 (5f616c95e804) as it reports no changes
3: I0818 04:09:41.856729 18354 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0818 04:09:41.858348 18424 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:59146
3: I0818 04:09:41.859159 18424 http.cpp:2828] Processing GET_CONTAINERS call
3: I0818 04:09:41.866080 18350 hierarchical.cpp:1920] Performed allocation for 1 agents in 297328ns
3: I0818 04:09:41.868937 18359 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 04:09:41.872534 18419 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0818 04:09:41.873754 18348 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:59148
3: I0818 04:09:41.874835 18348 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 04:09:41.876368 18348 http.cpp:3399] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_JoK3eW/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0818 04:09:41.877368 18348 containerizer.cpp:1397] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0818 04:09:41.878484 18348 containerizer.cpp:3406] 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 377088ns
3: I0818 04:09:41.879974 18348 containerizer.cpp:1576] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_fCIXYR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
3: I0818 04:09:41.880064 18348 containerizer.cpp:3406] 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.58208ms
3: I0818 04:09:41.885529 18384 containerizer.cpp:2102] 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_VlY4v0","--available_capacity=0B","--volumes=","--forward=unix:///tmp/lOsUT9/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_JoK3eW/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-nDohCL/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_JoK3eW/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_fCIXYR/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
3: I0818 04:09:41.907685 18384 launcher.cpp:145] Forked child with pid '55218' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
3: I0818 04:09:41.909629 18384 containerizer.cpp:3406] 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.552128ms
3: I0818 04:09:41.912678 18384 containerizer.cpp:3406] 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.049728ms
3: I0818 04:09:41.913250 18408 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_JoK3eW/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
3: I0818 04:09:41.915668 18405 containerizer.cpp:3406] 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.992128ms
3: I0818 04:09:41.918383 18374 hierarchical.cpp:1920] Performed allocation for 1 agents in 460253ns
3: I0818 04:09:41.920439 18425 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 04:09:41.920857 18430 service_manager.cpp:775] Connecting to endpoint 'unix:///tmp/mesos-csi-nDohCL/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 04:09:41.971395 18441 hierarchical.cpp:1920] Performed allocation for 1 agents in 299038ns
3: I0818 04:09:42.022594 18421 hierarchical.cpp:1920] Performed allocation for 1 agents in 217596ns
3: I0818 04:09:42.074329 18362 hierarchical.cpp:1920] Performed allocation for 1 agents in 392860ns
3: I0818 04:09:42.126580 18354 hierarchical.cpp:1920] Performed allocation for 1 agents in 344269ns
3: I0818 04:09:42.178167 18424 hierarchical.cpp:1920] Performed allocation for 1 agents in 226426ns
3: I0818 04:09:42.230139 18383 hierarchical.cpp:1920] Performed allocation for 1 agents in 559785ns
3: I0818 04:09:42.282207 18403 hierarchical.cpp:1920] Performed allocation for 1 agents in 219976ns
3: I0818 04:09:42.333777 18412 hierarchical.cpp:1920] Performed allocation for 1 agents in 411711ns
3: I0818 04:09:42.385613 18363 hierarchical.cpp:1920] Performed allocation for 1 agents in 232436ns
3: I0818 04:09:42.436899 18365 hierarchical.cpp:1920] Performed allocation for 1 agents in 309588ns
3: I0818 04:09:42.488839 18442 hierarchical.cpp:1920] Performed allocation for 1 agents in 252247ns
3: I0818 04:09:42.540967 18364 hierarchical.cpp:1920] Performed allocation for 1 agents in 315468ns
3: I0818 04:09:42.592334 18384 hierarchical.cpp:1920] Performed allocation for 1 agents in 312198ns
3: I0818 04:09:42.644299 18438 hierarchical.cpp:1920] Performed allocation for 1 agents in 311418ns
3: I0818 04:09:42.695998 18411 hierarchical.cpp:1920] Performed allocation for 1 agents in 346840ns
3: I0818 04:09:42.747646 18441 hierarchical.cpp:1920] Performed allocation for 1 agents in 180974ns
3: I0818 04:09:42.787679 18349 service_manager.cpp:617] Probing endpoint 'unix:///tmp/mesos-csi-nDohCL/endpoint.sock' with CSI v1
3: I0818 04:09:42.791465 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call
3: I0818 04:09:42.797047 18432 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 04:09:42.800678 18428 hierarchical.cpp:1920] Performed allocation for 1 agents in 449192ns
3: I0818 04:09:42.802580 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call
3: I0818 04:09:42.802757 18354 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1'
3: I0818 04:09:42.804594 18409 http.cpp:1436] HTTP POST for /slave(1244)/api/v1 from 172.17.0.2:59150
3: I0818 04:09:42.805701 18409 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 04:09:42.810000 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0818 04:09:42.810721 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call
3: I0818 04:09:42.813292 18403 v1_volume_manager.cpp:674] NODE_SERVICE loaded: {}
3: I0818 04:09:42.814560 18403 v1_volume_manager.cpp:674] CONTROLLER_SERVICE loaded: {}
3: I0818 04:09:42.818447 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call
3: I0818 04:09:42.825345 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call
3: I0818 04:09:42.831197 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call
3: I0818 04:09:42.835369 18437 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test'
3: I0818 04:09:42.835589 18348 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0818 04:09:42.836432 18390 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:43017/slave(1244)/api/v1/resource_provider
3: I0818 04:09:42.840539 18389 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:43017/slave(1244)/api/v1/resource_provider
3: I0818 04:09:42.841572 18407 provider.cpp:476] Connected to resource provider manager
3: I0818 04:09:42.842753 18422 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:43017/slave(1244)/api/v1/resource_provider
3: I0818 04:09:42.844316 18413 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0818 04:09:42.846850 18374 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:59152
3: I0818 04:09:42.848052 18438 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_VlY4v0","--available_capacity=0B","--volumes=","--forward=unix:///tmp/lOsUT9/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 04:09:42.851912 18357 hierarchical.cpp:1920] Performed allocation for 1 agents in 230076ns
3: I0818 04:09:42.857344 18392 slave.cpp:8714] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"64b924cc-b3d4-45a9-b8c1-5d5178f2f3f4"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_VlY4v0","--available_capacity=0B","--volumes=","--forward=unix:///tmp/lOsUT9/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 04:09:42.859607 18349 provider.cpp:498] Received SUBSCRIBED event
3: I0818 04:09:42.859669 18349 provider.cpp:1309] Subscribed with ID 64b924cc-b3d4-45a9-b8c1-5d5178f2f3f4
3: I0818 04:09:42.861047 18360 status_update_manager_process.hpp:314] Recovering operation status update manager
3: I0818 04:09:42.867377 18429 provider.cpp:790] Reconciling storage pools and volumes
3: I0818 04:09:42.871307 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0818 04:09:42.876011 18427 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0
3: I0818 04:09:42.876410 18409 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:43017/slave(1244)/api/v1/resource_provider
3: I0818 04:09:42.876564 18427 provider.cpp:748] Resource provider 64b924cc-b3d4-45a9-b8c1-5d5178f2f3f4 is in READY state
3: I0818 04:09:42.876646 18395 status_update_manager_process.hpp:385] Resuming operation status update manager
3: I0818 04:09:42.877679 18406 provider.cpp:1235] Updating profiles { test } for resource provider 64b924cc-b3d4-45a9-b8c1-5d5178f2f3f4
3: I0818 04:09:42.878015 18401 process.cpp:3671] Handling HTTP event for process 'slave(1244)' with path: '/slave(1244)/api/v1/resource_provider'
3: I0818 04:09:42.879539 18420 provider.cpp:790] Reconciling storage pools and volumes
3: I0818 04:09:42.879981 18387 http.cpp:1436] HTTP POST for /slave(1244)/api/v1/resource_provider from 172.17.0.2:59154
3: I0818 04:09:42.880920 18415 manager.cpp:1011] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider 64b924cc-b3d4-45a9-b8c1-5d5178f2f3f4
3: I0818 04:09:42.881229 18434 slave.cpp:8714] Handling resource provider message 'UPDATE_STATE: 64b924cc-b3d4-45a9-b8c1-5d5178f2f3f4 {}'
3: I0818 04:09:42.881388 18434 slave.cpp:8834] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0818 04:09:42.883309 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0818 04:09:42.884093 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0818 04:09:42.884433 18367 hierarchical.cpp:1177] Grew agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 by {} (total), { } (used)
3: I0818 04:09:42.885191 18367 hierarchical.cpp:1134] Agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 (5f616c95e804) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
3: I0818 04:09:42.893623 18408 hierarchical.cpp:1920] Performed allocation for 1 agents in 415111ns
3: I0818 04:09:42.893774 18369 provider.cpp:790] Reconciling storage pools and volumes
3: I0818 04:09:42.897176 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call
3: I0818 04:09:42.897939 55222 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call
3: I0818 04:09:42.908497 18362 slave.cpp:1000] Agent terminating
3: I0818 04:09:42.909886 18362 manager.cpp:127] Terminating resource provider 64b924cc-b3d4-45a9-b8c1-5d5178f2f3f4
3: I0818 04:09:42.910553 18423 master.cpp:1292] Agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 at slave(1244)@172.17.0.2:43017 (5f616c95e804) disconnected
3: I0818 04:09:42.910617 18423 master.cpp:3361] Disconnecting agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 at slave(1244)@172.17.0.2:43017 (5f616c95e804)
3: I0818 04:09:42.910754 18423 master.cpp:3380] Deactivating agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 at slave(1244)@172.17.0.2:43017 (5f616c95e804)
3: I0818 04:09:42.910967 18409 hierarchical.cpp:1223] Agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0 deactivated
3: E0818 04:09:42.911044 18427 http_connection.hpp:449] End-Of-File received
3: I0818 04:09:42.911787 18427 http_connection.hpp:217] Re-detecting endpoint
3: I0818 04:09:42.912503 18427 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0818 04:09:42.912684 18427 http_connection.hpp:338] Ignoring disconnection attempt from stale connection
3: I0818 04:09:42.912740 18403 provider.cpp:488] Disconnected from resource provider manager
3: I0818 04:09:42.912814 18427 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:43017/slave(1244)/api/v1/resource_provider
3: I0818 04:09:42.912950 18350 status_update_manager_process.hpp:379] Pausing operation status update manager
3: I0818 04:09:42.914928 18386 containerizer.cpp:2708] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state
3: I0818 04:09:42.915038 18386 containerizer.cpp:3406] 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.999379968secs
3: I0818 04:09:42.915786 18386 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 04:09:42.917249 18415 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:43017/slave(1244)/api/v1/resource_provider
3: I0818 04:09:42.918129 18393 provider.cpp:476] Connected to resource provider manager
3: I0818 04:09:42.918995 18365 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:43017/slave(1244)/api/v1/resource_provider
3: I0818 04:09:42.920114 18444 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1/resource_provider'
3: E0818 04:09:42.921984 18373 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 04:09:42.937211 18378 hierarchical.cpp:1920] Performed allocation for 1 agents in 216246ns
3: I0818 04:09:42.987790 18435 containerizer.cpp:3244] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited
3: I0818 04:09:42.988855 18422 hierarchical.cpp:1920] Performed allocation for 1 agents in 222826ns
3: I0818 04:09:42.990399 18374 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 04:09:42.994391 18368 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 04:09:42.994680 18438 service_manager.cpp:795] Disconnected from endpoint 'unix:///tmp/mesos-csi-nDohCL/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 04:09:42.995038 18431 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 04:09:42.998186 18444 process.cpp:2781] Returning '404 Not Found' for '/slave(1244)/api/v1'
3: I0818 04:09:43.020965 18439 master.cpp:1140] Master terminating
3: I0818 04:09:43.021499 18438 hierarchical.cpp:1199] Removed all filters for agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0
3: I0818 04:09:43.021549 18438 hierarchical.cpp:1075] Removed agent 59965c05-0ca6-4586-9fc0-206dedf3203c-S0
3: [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1296 ms)
3: [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (105519 ms total)
3:
3: [----------] Global test environment tear-down
3: [==========] 2273 tests from 216 test cases ran. (1059807 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 04:09:43.263890 18444 process.cpp:935] Stopped the socket accept loop
3/3 Test #3: MesosTests .......................***Failed 1062.77 sec
67% tests passed, 1 tests failed out of 3
Total Test time (real) = 1131.10 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 82m42.656s
user 0m17.897s
sys 0m15.646s
Build step 'Execute shell' marked build as failure
Recording test results