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=arm/1620/display/redirect?page=changes>
Changes: [mzhu] Added an benchmark for `allocator->UpdateAllocation()`. ------------------------------------------ [...truncated 48.50 MB...] 3: I1031 06:26:06.648938 18388 whitelist_watcher.cpp:77] No whitelist given 3: I1031 06:26:06.655969 18309 master.cpp:2169] Elected as the leading master! 3: I1031 06:26:06.656026 18309 master.cpp:1665] Recovering from registrar 3: I1031 06:26:06.656327 18383 registrar.cpp:339] Recovering registrar 3: I1031 06:26:06.657739 18383 registrar.cpp:383] Successfully fetched the registry (0B) in 0ns 3: I1031 06:26:06.658041 18383 registrar.cpp:487] Applied 1 operations in 126804ns; attempting to update the registry 3: I1031 06:26:06.659317 18383 registrar.cpp:544] Successfully updated the registry in 0ns 3: I1031 06:26:06.659574 18383 registrar.cpp:416] Successfully recovered registrar 3: I1031 06:26:06.660398 18359 master.cpp:1818] Recovered 0 agents from the registry (144B); allowing 10mins for agents to reregister 3: I1031 06:26:06.660441 18344 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover 3: W1031 06:26:06.674727 18294 process.cpp:2877] Attempted to spawn already running process [email protected]:44705 3: I1031 06:26:06.677973 18294 containerizer.cpp:318] Using isolation { environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } 3: W1031 06:26:06.679265 18294 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges 3: W1031 06:26:06.679334 18294 backend.cpp:76] Failed to create 'aufs' backend: AufsBackend requires root privileges 3: W1031 06:26:06.679404 18294 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges 3: I1031 06:26:06.679497 18294 provisioner.cpp:294] Using default backend 'copy' 3: I1031 06:26:06.684403 18294 cluster.cpp:524] Creating default 'local' authorizer 3: I1031 06:26:06.694136 18316 slave.cpp:267] Mesos agent started on (1243)@172.17.0.2:44705 3: I1031 06:26:06.694275 18316 slave.cpp:268] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; --appc_store_dir="/tmp/1LaEh6/RU1fja/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/1LaEh6/RU1fja/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/1LaEh6/RU1fja/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/1LaEh6/RU1fja/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/1LaEh6/RU1fja/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/1LaEh6/RU1fja/http_credentials" --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/1LaEh6/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_dGySkn" --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_nzOMlA" --zk_session_timeout="10secs" 3: I1031 06:26:06.696518 18316 credentials.hpp:86] Loading credential for authentication from '/tmp/1LaEh6/RU1fja/credential' 3: I1031 06:26:06.697217 18316 slave.cpp:300] Agent using credential for: test-principal 3: I1031 06:26:06.697304 18316 credentials.hpp:37] Loading credentials for authentication from '/tmp/1LaEh6/RU1fja/http_credentials' 3: I1031 06:26:06.698153 18316 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' 3: I1031 06:26:06.698614 18371 hierarchical.cpp:1853] Performed allocation for 0 agents in 310478ns 3: I1031 06:26:06.699172 18316 disk_profile_adaptor.cpp:82] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor' 3: I1031 06:26:06.702869 18306 uri_disk_profile_adaptor.cpp:305] Updated disk profile mapping to 1 active profiles 3: I1031 06:26:06.704558 18316 slave.cpp:615] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}] 3: I1031 06:26:06.705225 18316 slave.cpp:623] Agent attributes: [ ] 3: I1031 06:26:06.705278 18316 slave.cpp:632] Agent hostname: a9ac9d0cf529 3: I1031 06:26:06.705780 18351 status_update_manager_process.hpp:379] Pausing operation status update manager 3: I1031 06:26:06.705838 18378 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1031 06:26:06.711362 18370 state.cpp:67] Recovering state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_nzOMlA/meta' 3: I1031 06:26:06.711845 18349 slave.cpp:7492] Finished recovering checkpointed state from '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_nzOMlA/meta', beginning agent recovery 3: I1031 06:26:06.713174 18328 task_status_update_manager.cpp:207] Recovering task status update manager 3: I1031 06:26:06.714960 18366 containerizer.cpp:821] Recovering Mesos containers 3: I1031 06:26:06.715800 18366 containerizer.cpp:1161] Recovering isolators 3: I1031 06:26:06.719451 18382 containerizer.cpp:1200] Recovering provisioner 3: I1031 06:26:06.722020 18363 provisioner.cpp:518] Provisioner recovery complete 3: I1031 06:26:06.724721 18360 composing.cpp:339] Finished recovering all containerizers 3: I1031 06:26:06.725422 18365 slave.cpp:7974] Recovering executors 3: I1031 06:26:06.725641 18365 slave.cpp:8127] Finished recovery 3: I1031 06:26:06.728055 18330 task_status_update_manager.cpp:181] Pausing sending task status updates 3: I1031 06:26:06.728216 18330 status_update_manager_process.hpp:379] Pausing operation status update manager 3: I1031 06:26:06.728199 18334 slave.cpp:1351] New master detected at [email protected]:44705 3: I1031 06:26:06.728718 18334 slave.cpp:1416] Detecting new master 3: I1031 06:26:06.734473 18353 slave.cpp:1443] Authenticating with master [email protected]:44705 3: I1031 06:26:06.734866 18353 slave.cpp:1452] Using default CRAM-MD5 authenticatee 3: I1031 06:26:06.735744 18333 authenticatee.cpp:121] Creating new client SASL connection 3: I1031 06:26:06.736587 18384 master.cpp:10594] Authenticating slave(1243)@172.17.0.2:44705 3: I1031 06:26:06.736927 18324 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(2096)@172.17.0.2:44705 3: I1031 06:26:06.737493 18309 authenticator.cpp:98] Creating new server SASL connection 3: I1031 06:26:06.737926 18300 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5 3: I1031 06:26:06.737995 18300 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5' 3: I1031 06:26:06.738226 18390 authenticator.cpp:204] Received SASL authentication start 3: I1031 06:26:06.738378 18390 authenticator.cpp:326] Authentication requires more steps 3: I1031 06:26:06.738600 18340 authenticatee.cpp:259] Received SASL authentication step 3: I1031 06:26:06.738942 18310 authenticator.cpp:232] Received SASL authentication step 3: I1031 06:26:06.739087 18310 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'a9ac9d0cf529' server FQDN: 'a9ac9d0cf529' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 3: I1031 06:26:06.739159 18310 auxprop.cpp:181] Looking up auxiliary property '*userPassword' 3: I1031 06:26:06.739311 18310 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' 3: I1031 06:26:06.739413 18310 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'a9ac9d0cf529' server FQDN: 'a9ac9d0cf529' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 3: I1031 06:26:06.739480 18310 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true 3: I1031 06:26:06.739528 18310 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true 3: I1031 06:26:06.739600 18310 authenticator.cpp:318] Authentication success 3: I1031 06:26:06.739814 18295 authenticatee.cpp:299] Authentication success 3: I1031 06:26:06.740011 18329 master.cpp:10626] Successfully authenticated principal 'test-principal' at slave(1243)@172.17.0.2:44705 3: I1031 06:26:06.740101 18343 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(2096)@172.17.0.2:44705 3: I1031 06:26:06.740788 18389 slave.cpp:1543] Successfully authenticated with master [email protected]:44705 3: I1031 06:26:06.742017 18389 slave.cpp:1993] Will retry registration in 19.71941ms if necessary 3: I1031 06:26:06.742561 18344 master.cpp:7083] Received register agent message from slave(1243)@172.17.0.2:44705 (a9ac9d0cf529) 3: I1031 06:26:06.743312 18344 master.cpp:4189] Authorizing agent providing resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 'test-principal' 3: I1031 06:26:06.745234 18364 master.cpp:7150] Authorized registration of agent at slave(1243)@172.17.0.2:44705 (a9ac9d0cf529) 3: I1031 06:26:06.745471 18364 master.cpp:7262] Registering agent at slave(1243)@172.17.0.2:44705 (a9ac9d0cf529) with id 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 3: I1031 06:26:06.746984 18377 registrar.cpp:487] Applied 1 operations in 676887ns; attempting to update the registry 3: I1031 06:26:06.748692 18377 registrar.cpp:544] Successfully updated the registry in 1.483264ms 3: I1031 06:26:06.749172 18377 master.cpp:7310] Admitted agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 at slave(1243)@172.17.0.2:44705 (a9ac9d0cf529) 3: I1031 06:26:06.750746 18377 master.cpp:7355] Registered agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 at slave(1243)@172.17.0.2:44705 (a9ac9d0cf529) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] 3: I1031 06:26:06.751091 18368 hierarchical.cpp:1853] Performed allocation for 0 agents in 482413ns 3: I1031 06:26:06.751498 18331 slave.cpp:1576] Registered with master [email protected]:44705; given agent ID 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 3: I1031 06:26:06.752691 18368 hierarchical.cpp:959] Added agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 (a9ac9d0cf529) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {}) 3: I1031 06:26:06.753016 18331 slave.cpp:1611] Checkpointing SlaveInfo to '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_nzOMlA/meta/slaves/4d6b1126-43e5-47a9-95a7-797bf34392fe-S0/slave.info' 3: I1031 06:26:06.753051 18315 task_status_update_manager.cpp:188] Resuming sending task status updates 3: I1031 06:26:06.753396 18315 status_update_manager_process.hpp:385] Resuming operation status update manager 3: I1031 06:26:06.753450 18368 hierarchical.cpp:1853] Performed allocation for 1 agents in 288278ns 3: I1031 06:26:06.757591 18331 slave.cpp:1663] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"nh1mjRcLR92KK4PUG+uKgA=="},"slave_id":{"value":"4d6b1126-43e5-47a9-95a7-797bf34392fe-S0"},"update_oversubscribed_resources":false} 3: I1031 06:26:06.761675 18379 master.cpp:8474] Ignoring update on agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 at slave(1243)@172.17.0.2:44705 (a9ac9d0cf529) as it reports no changes 3: I1031 06:26:06.769428 18372 process.cpp:3671] Handling HTTP event for process 'slave(1243)' with path: '/slave(1243)/api/v1' 3: I1031 06:26:06.771847 18316 http.cpp:1115] HTTP POST for /slave(1243)/api/v1 from 172.17.0.2:50526 3: I1031 06:26:06.773319 18316 http.cpp:2146] Processing GET_CONTAINERS call 3: I1031 06:26:06.790987 18301 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' 3: I1031 06:26:06.798741 18299 process.cpp:3671] Handling HTTP event for process 'slave(1243)' with path: '/slave(1243)/api/v1' 3: I1031 06:26:06.800814 18367 http.cpp:1115] HTTP POST for /slave(1243)/api/v1 from 172.17.0.2:50528 3: I1031 06:26:06.803090 18367 http.cpp:2606] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' 3: I1031 06:26:06.803431 18361 hierarchical.cpp:1853] Performed allocation for 1 agents in 562135ns 3: I1031 06:26:06.806104 18367 http.cpp:2710] Creating sandbox '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_nzOMlA/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' 3: I1031 06:26:06.807374 18358 containerizer.cpp:1396] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE 3: I1031 06:26:06.809262 18358 containerizer.cpp:3318] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from STARTING to PROVISIONING after 620800ns 3: I1031 06:26:06.812137 18358 containerizer.cpp:1574] Checkpointed ContainerConfig at '/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_dGySkn/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config' 3: I1031 06:26:06.812235 18358 containerizer.cpp:3318] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING after 2.978304ms 3: I1031 06:26:06.821660 18353 containerizer.cpp:2100] 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_bPTOlN","--available_capacity=0B","--volumes=","--forward=unix:///tmp/1LaEh6/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_nzOMlA/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-Vy1TMF/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_nzOMlA/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="53" --pipe_write="54" --runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_dGySkn/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"' 3: I1031 06:26:06.843200 18353 launcher.cpp:145] Forked child with pid '54506' for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' 3: I1031 06:26:06.845702 18353 containerizer.cpp:3318] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING after 33.430016ms 3: I1031 06:26:06.849504 18353 containerizer.cpp:3318] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING after 3.819008ms 3: I1031 06:26:06.850129 18359 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_nzOMlA/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE 3: I1031 06:26:06.852736 18359 containerizer.cpp:3318] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING after 3.227904ms 3: I1031 06:26:06.857116 18344 hierarchical.cpp:1853] Performed allocation for 1 agents in 594066ns 3: I1031 06:26:06.858865 18364 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: I1031 06:26:06.859308 18327 service_manager.cpp:703] Connecting to endpoint 'unix:///tmp/mesos-csi-Vy1TMF/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE 3: I1031 06:26:06.911880 18368 hierarchical.cpp:1853] Performed allocation for 1 agents in 555444ns 3: I1031 06:26:06.964819 18376 hierarchical.cpp:1853] Performed allocation for 1 agents in 529174ns 3: I1031 06:26:07.017282 18322 hierarchical.cpp:1853] Performed allocation for 1 agents in 578125ns 3: I1031 06:26:07.070101 18371 hierarchical.cpp:1853] Performed allocation for 1 agents in 549395ns 3: I1031 06:26:07.123755 18332 hierarchical.cpp:1853] Performed allocation for 1 agents in 613156ns 3: I1031 06:26:07.175827 18349 hierarchical.cpp:1853] Performed allocation for 1 agents in 515283ns 3: I1031 06:26:07.228435 18381 hierarchical.cpp:1853] Performed allocation for 1 agents in 558784ns 3: I1031 06:26:07.280604 18387 hierarchical.cpp:1853] Performed allocation for 1 agents in 617146ns 3: I1031 06:26:07.333111 18299 hierarchical.cpp:1853] Performed allocation for 1 agents in 565045ns 3: I1031 06:26:07.386660 18361 hierarchical.cpp:1853] Performed allocation for 1 agents in 555485ns 3: I1031 06:26:07.439054 18334 hierarchical.cpp:1853] Performed allocation for 1 agents in 621706ns 3: I1031 06:26:07.491602 18384 hierarchical.cpp:1853] Performed allocation for 1 agents in 871803ns 3: I1031 06:26:07.543215 18329 hierarchical.cpp:1853] Performed allocation for 1 agents in 474322ns 3: I1031 06:26:07.597049 18359 hierarchical.cpp:1853] Performed allocation for 1 agents in 499603ns 3: I1031 06:26:07.649544 18352 hierarchical.cpp:1853] Performed allocation for 1 agents in 452782ns 3: I1031 06:26:07.702704 18373 hierarchical.cpp:1853] Performed allocation for 1 agents in 547684ns 3: I1031 06:26:07.755165 18313 hierarchical.cpp:1853] Performed allocation for 1 agents in 556545ns 3: I1031 06:26:07.808457 18323 hierarchical.cpp:1853] Performed allocation for 1 agents in 527204ns 3: I1031 06:26:07.862072 18362 hierarchical.cpp:1853] Performed allocation for 1 agents in 541834ns 3: I1031 06:26:07.880563 18371 service_manager.cpp:545] Probing endpoint 'unix:///tmp/mesos-csi-Vy1TMF/endpoint.sock' with CSI v1 3: I1031 06:26:07.885192 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/Probe call 3: I1031 06:26:07.893607 18372 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: I1031 06:26:07.902729 18328 process.cpp:3671] Handling HTTP event for process 'slave(1243)' with path: '/slave(1243)/api/v1' 3: I1031 06:26:07.902863 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginCapabilities call 3: I1031 06:26:07.905297 18369 http.cpp:1115] HTTP POST for /slave(1243)/api/v1 from 172.17.0.2:50530 3: I1031 06:26:07.906901 18369 http.cpp:2824] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' 3: I1031 06:26:07.914222 18382 hierarchical.cpp:1853] Performed allocation for 1 agents in 535794ns 3: I1031 06:26:07.917713 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call 3: I1031 06:26:07.919178 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Identity/GetPluginInfo call 3: I1031 06:26:07.923861 18375 v1_volume_manager.cpp:649] NODE_SERVICE loaded: {} 3: I1031 06:26:07.925119 18375 v1_volume_manager.cpp:649] CONTROLLER_SERVICE loaded: {} 3: I1031 06:26:07.933267 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ControllerGetCapabilities call 3: I1031 06:26:07.948473 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetCapabilities call 3: I1031 06:26:07.959017 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Node/NodeGetInfo call 3: I1031 06:26:07.964702 18333 provider.cpp:676] Recovered resources '{}' and 0 operations for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test' 3: I1031 06:26:07.964962 18384 status_update_manager_process.hpp:379] Pausing operation status update manager 3: I1031 06:26:07.966179 18333 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:44705/slave(1243)/api/v1/resource_provider 3: I1031 06:26:07.966578 18300 hierarchical.cpp:1853] Performed allocation for 1 agents in 509913ns 3: I1031 06:26:07.974638 18385 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:44705/slave(1243)/api/v1/resource_provider 3: I1031 06:26:07.976136 18383 provider.cpp:476] Connected to resource provider manager 3: I1031 06:26:07.977762 18312 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:44705/slave(1243)/api/v1/resource_provider 3: I1031 06:26:07.980372 18321 process.cpp:3671] Handling HTTP event for process 'slave(1243)' with path: '/slave(1243)/api/v1/resource_provider' 3: I1031 06:26:07.983781 18356 http.cpp:1115] HTTP POST for /slave(1243)/api/v1/resource_provider from 172.17.0.2:50532 3: I1031 06:26:07.986093 18356 manager.cpp:813] 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_bPTOlN","--available_capacity=0B","--volumes=","--forward=unix:///tmp/1LaEh6/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: I1031 06:26:07.997995 18323 slave.cpp:8483] Handling resource provider message 'SUBSCRIBE: {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"b03c7142-30d7-4e6f-b15f-11ea744245b1"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/tmp/SRC/build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_Update_v1_bPTOlN","--available_capacity=0B","--volumes=","--forward=unix:///tmp/1LaEh6/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: I1031 06:26:08.007108 18322 provider.cpp:498] Received SUBSCRIBED event 3: I1031 06:26:08.007236 18322 provider.cpp:1309] Subscribed with ID b03c7142-30d7-4e6f-b15f-11ea744245b1 3: I1031 06:26:08.009785 18371 status_update_manager_process.hpp:314] Recovering operation status update manager 3: I1031 06:26:08.018570 18306 provider.cpp:790] Reconciling storage pools and volumes 3: I1031 06:26:08.020463 18378 hierarchical.cpp:1853] Performed allocation for 1 agents in 487903ns 3: I1031 06:26:08.025488 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call 3: I1031 06:26:08.032514 18387 provider.cpp:2217] Sending UPDATE_STATE call with resources '{}' and 0 operations to agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 3: I1031 06:26:08.033145 18339 http_connection.hpp:131] Sending UPDATE_STATE call to http://172.17.0.2:44705/slave(1243)/api/v1/resource_provider 3: I1031 06:26:08.033349 18387 provider.cpp:748] Resource provider b03c7142-30d7-4e6f-b15f-11ea744245b1 is in READY state 3: I1031 06:26:08.033419 18381 status_update_manager_process.hpp:385] Resuming operation status update manager 3: I1031 06:26:08.035374 18317 provider.cpp:1235] Updating profiles { test } for resource provider b03c7142-30d7-4e6f-b15f-11ea744245b1 3: I1031 06:26:08.036048 18305 process.cpp:3671] Handling HTTP event for process 'slave(1243)' with path: '/slave(1243)/api/v1/resource_provider' 3: I1031 06:26:08.037879 18311 provider.cpp:790] Reconciling storage pools and volumes 3: I1031 06:26:08.039759 18303 http.cpp:1115] HTTP POST for /slave(1243)/api/v1/resource_provider from 172.17.0.2:50534 3: I1031 06:26:08.041232 18388 manager.cpp:1045] Received UPDATE_STATE call with resources '[]' and 0 operations from resource provider b03c7142-30d7-4e6f-b15f-11ea744245b1 3: I1031 06:26:08.041760 18326 slave.cpp:8483] Handling resource provider message 'UPDATE_STATE: b03c7142-30d7-4e6f-b15f-11ea744245b1 {}' 3: I1031 06:26:08.041962 18326 slave.cpp:8603] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] 3: I1031 06:26:08.044972 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call 3: I1031 06:26:08.046038 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call 3: I1031 06:26:08.046736 18340 hierarchical.cpp:1110] Grew agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 by {} (total), { } (used) 3: I1031 06:26:08.048068 18340 hierarchical.cpp:1067] Agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 (a9ac9d0cf529) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000] 3: I1031 06:26:08.062551 18331 provider.cpp:790] Reconciling storage pools and volumes 3: I1031 06:26:08.062825 18320 hierarchical.cpp:1853] Performed allocation for 1 agents in 515423ns 3: I1031 06:26:08.070961 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/ListVolumes call 3: I1031 06:26:08.072156 54510 test_csi_plugin.cpp:1915] Forwarding /csi.v1.Controller/GetCapacity call 3: I1031 06:26:08.083482 18351 slave.cpp:924] Agent terminating 3: I1031 06:26:08.085656 18351 manager.cpp:163] Terminating resource provider b03c7142-30d7-4e6f-b15f-11ea744245b1 3: I1031 06:26:08.087167 18357 master.cpp:1296] Agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 at slave(1243)@172.17.0.2:44705 (a9ac9d0cf529) disconnected 3: I1031 06:26:08.087273 18357 master.cpp:3391] Disconnecting agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 at slave(1243)@172.17.0.2:44705 (a9ac9d0cf529) 3: I1031 06:26:08.087440 18357 master.cpp:3410] Deactivating agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 at slave(1243)@172.17.0.2:44705 (a9ac9d0cf529) 3: I1031 06:26:08.087720 18354 hierarchical.cpp:1156] Agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 deactivated 3: E1031 06:26:08.088374 18354 http_connection.hpp:452] End-Of-File received 3: I1031 06:26:08.090353 18354 http_connection.hpp:217] Re-detecting endpoint 3: I1031 06:26:08.091564 18354 http_connection.hpp:338] Ignoring disconnection attempt from stale connection 3: I1031 06:26:08.091730 18354 http_connection.hpp:338] Ignoring disconnection attempt from stale connection 3: I1031 06:26:08.091881 18361 provider.cpp:488] Disconnected from resource provider manager 3: I1031 06:26:08.092229 18317 status_update_manager_process.hpp:379] Pausing operation status update manager 3: I1031 06:26:08.092509 18354 http_connection.hpp:227] New endpoint detected at http://172.17.0.2:44705/slave(1243)/api/v1/resource_provider 3: I1031 06:26:08.095782 18341 containerizer.cpp:2620] Destroying container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE in RUNNING state 3: I1031 06:26:08.095933 18341 containerizer.cpp:3318] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE from RUNNING to DESTROYING after 16.243219968secs 3: I1031 06:26:08.096864 18341 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: I1031 06:26:08.100095 18300 http_connection.hpp:283] Connected with the remote endpoint at http://172.17.0.2:44705/slave(1243)/api/v1/resource_provider 3: I1031 06:26:08.101915 18384 provider.cpp:476] Connected to resource provider manager 3: I1031 06:26:08.102146 18300 hierarchical.cpp:1853] Performed allocation for 1 agents in 369480ns 3: I1031 06:26:08.103546 18309 http_connection.hpp:131] Sending SUBSCRIBE call to http://172.17.0.2:44705/slave(1243)/api/v1/resource_provider 3: I1031 06:26:08.107340 18391 process.cpp:2781] Returning '404 Not Found' for '/slave(1243)/api/v1/resource_provider' 3: E1031 06:26:08.110530 18329 provider.cpp:721] Failed to subscribe resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test': Received '404 Not Found' () 3: I1031 06:26:08.152324 18383 containerizer.cpp:3156] Container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE has exited 3: I1031 06:26:08.154191 18352 hierarchical.cpp:1853] Performed allocation for 1 agents in 386420ns 3: I1031 06:26:08.155792 18383 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: I1031 06:26:08.161396 18315 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: I1031 06:26:08.161923 18314 service_manager.cpp:723] Disconnected from endpoint 'unix:///tmp/mesos-csi-Vy1TMF/endpoint.sock' of CSI plugin container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE 3: I1031 06:26:08.162523 18348 container_daemon.cpp:121] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE' 3: I1031 06:26:08.168887 18391 process.cpp:2781] Returning '404 Not Found' for '/slave(1243)/api/v1' 3: I1031 06:26:08.195186 18294 master.cpp:1137] Master terminating 3: I1031 06:26:08.195866 18314 hierarchical.cpp:1132] Removed all filters for agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 3: I1031 06:26:08.195915 18314 hierarchical.cpp:1008] Removed agent 4d6b1126-43e5-47a9-95a7-797bf34392fe-S0 3: [ OK ] CSIVersion/StorageLocalResourceProviderTest.Update/v1 (1598 ms) 3: [----------] 54 tests from CSIVersion/StorageLocalResourceProviderTest (141590 ms total) 3: 3: [----------] Global test environment tear-down 3: [==========] 2264 tests from 215 test cases ran. (1313837 ms total) 3: [ PASSED ] 2263 tests. 3: [ FAILED ] 1 test, listed below: 3: [ FAILED ] Enforcing/DiskQuotaEnforcement.SlaveRecovery/Sandbox, where GetParam() = 0 3: 3: 1 FAILED TEST 3: YOU HAVE 34 DISABLED TESTS 3: 3: I1031 06:26:08.553737 18391 process.cpp:935] Stopped the socket accept loop 3/3 Test #3: MesosTests .......................***Failed 1317.57 sec 67% tests passed, 1 tests failed out of 3 Total Test time (real) = 1402.03 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:232: recipe for target 'check' failed make: *** [check] Error 2 real 109m54.971s user 0m23.875s sys 0m19.737s Build step 'Execute shell' marked build as failure Recording test results
