Neil Conway created MESOS-5274: ---------------------------------- Summary: DockerRuntimeIsolatorTest.ROOT_DockerDefaultEntryptLocalPuller is flaky Key: MESOS-5274 URL: https://issues.apache.org/jira/browse/MESOS-5274 Project: Mesos Issue Type: Bug Reporter: Neil Conway
Observed on Mesosphere internal CI: {noformat} [15:07:02] : [Step 10/10] [ RUN ] DockerRuntimeIsolatorTest.ROOT_DockerDefaultEntryptLocalPuller [15:07:02]W: [Step 10/10] I0425 15:07:02.166211 32147 cluster.cpp:149] Creating default 'local' authorizer [15:07:02]W: [Step 10/10] I0425 15:07:02.178527 32147 leveldb.cpp:174] Opened db in 12.157082ms [15:07:02]W: [Step 10/10] I0425 15:07:02.179869 32147 leveldb.cpp:181] Compacted db in 1.313946ms [15:07:02]W: [Step 10/10] I0425 15:07:02.179893 32147 leveldb.cpp:196] Created db iterator in 3836ns [15:07:02]W: [Step 10/10] I0425 15:07:02.179913 32147 leveldb.cpp:202] Seeked to beginning of db in 656ns [15:07:02]W: [Step 10/10] I0425 15:07:02.179919 32147 leveldb.cpp:271] Iterated through 0 keys in the db in 553ns [15:07:02]W: [Step 10/10] I0425 15:07:02.179934 32147 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned [15:07:02]W: [Step 10/10] I0425 15:07:02.180132 32165 recover.cpp:447] Starting replica recovery [15:07:02]W: [Step 10/10] I0425 15:07:02.180217 32163 recover.cpp:473] Replica is in EMPTY status [15:07:02]W: [Step 10/10] I0425 15:07:02.180500 32161 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (17793)@172.30.2.13:42326 [15:07:02]W: [Step 10/10] I0425 15:07:02.180655 32167 recover.cpp:193] Received a recover response from a replica in EMPTY status [15:07:02]W: [Step 10/10] I0425 15:07:02.180891 32165 recover.cpp:564] Updating replica status to STARTING [15:07:02]W: [Step 10/10] I0425 15:07:02.181026 32168 master.cpp:382] Master f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517 (ip-172-30-2-13.mesosphere.io) started on 172.30.2.13:42326 [15:07:02]W: [Step 10/10] I0425 15:07:02.181040 32168 master.cpp:384] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_http_frameworks="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/G2DxFl/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_framework_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/G2DxFl/master" --zk_session_timeout="10secs" [15:07:02]W: [Step 10/10] I0425 15:07:02.181165 32168 master.cpp:433] Master only allowing authenticated frameworks to register [15:07:02]W: [Step 10/10] I0425 15:07:02.181171 32168 master.cpp:439] Master only allowing authenticated agents to register [15:07:02]W: [Step 10/10] I0425 15:07:02.181175 32168 master.cpp:445] Master only allowing authenticated HTTP frameworks to register [15:07:02]W: [Step 10/10] I0425 15:07:02.181180 32168 credentials.hpp:37] Loading credentials for authentication from '/tmp/G2DxFl/credentials' [15:07:02]W: [Step 10/10] I0425 15:07:02.181313 32168 master.cpp:489] Using default 'crammd5' authenticator [15:07:02]W: [Step 10/10] I0425 15:07:02.181352 32168 master.cpp:560] Using default 'basic' HTTP authenticator [15:07:02]W: [Step 10/10] I0425 15:07:02.181421 32168 master.cpp:640] Using default 'basic' HTTP framework authenticator [15:07:02]W: [Step 10/10] I0425 15:07:02.181473 32168 master.cpp:687] Authorization enabled [15:07:02]W: [Step 10/10] I0425 15:07:02.181556 32162 whitelist_watcher.cpp:77] No whitelist given [15:07:02]W: [Step 10/10] I0425 15:07:02.181576 32163 hierarchical.cpp:142] Initialized hierarchical allocator process [15:07:02]W: [Step 10/10] I0425 15:07:02.182076 32164 master.cpp:1932] The newly elected leader is master@172.30.2.13:42326 with id f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517 [15:07:02]W: [Step 10/10] I0425 15:07:02.182090 32164 master.cpp:1945] Elected as the leading master! [15:07:02]W: [Step 10/10] I0425 15:07:02.182095 32164 master.cpp:1632] Recovering from registrar [15:07:02]W: [Step 10/10] I0425 15:07:02.182142 32168 registrar.cpp:331] Recovering registrar [15:07:02]W: [Step 10/10] I0425 15:07:02.182188 32167 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.2377ms [15:07:02]W: [Step 10/10] I0425 15:07:02.182205 32167 replica.cpp:320] Persisted replica status to STARTING [15:07:02]W: [Step 10/10] I0425 15:07:02.182320 32167 recover.cpp:473] Replica is in STARTING status [15:07:02]W: [Step 10/10] I0425 15:07:02.182600 32162 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (17796)@172.30.2.13:42326 [15:07:02]W: [Step 10/10] I0425 15:07:02.182705 32165 recover.cpp:193] Received a recover response from a replica in STARTING status [15:07:02]W: [Step 10/10] I0425 15:07:02.182840 32161 recover.cpp:564] Updating replica status to VOTING [15:07:02]W: [Step 10/10] I0425 15:07:02.183964 32162 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.061794ms [15:07:02]W: [Step 10/10] I0425 15:07:02.183980 32162 replica.cpp:320] Persisted replica status to VOTING [15:07:02]W: [Step 10/10] I0425 15:07:02.184012 32162 recover.cpp:578] Successfully joined the Paxos group [15:07:02]W: [Step 10/10] I0425 15:07:02.184056 32162 recover.cpp:462] Recover process terminated [15:07:02]W: [Step 10/10] I0425 15:07:02.184185 32161 log.cpp:524] Attempting to start the writer [15:07:02]W: [Step 10/10] I0425 15:07:02.184515 32167 replica.cpp:493] Replica received implicit promise request from (17797)@172.30.2.13:42326 with proposal 1 [15:07:02]W: [Step 10/10] I0425 15:07:02.185619 32167 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.087808ms [15:07:02]W: [Step 10/10] I0425 15:07:02.185634 32167 replica.cpp:342] Persisted promised to 1 [15:07:02]W: [Step 10/10] I0425 15:07:02.185812 32162 coordinator.cpp:238] Coordinator attempting to fill missing positions [15:07:02]W: [Step 10/10] I0425 15:07:02.186211 32164 replica.cpp:388] Replica received explicit promise request from (17798)@172.30.2.13:42326 for position 0 with proposal 2 [15:07:02]W: [Step 10/10] I0425 15:07:02.187296 32164 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.067669ms [15:07:02]W: [Step 10/10] I0425 15:07:02.187312 32164 replica.cpp:712] Persisted action at 0 [15:07:02]W: [Step 10/10] I0425 15:07:02.187705 32167 replica.cpp:537] Replica received write request for position 0 from (17799)@172.30.2.13:42326 [15:07:02]W: [Step 10/10] I0425 15:07:02.187729 32167 leveldb.cpp:436] Reading position from leveldb took 10052ns [15:07:02]W: [Step 10/10] I0425 15:07:02.188858 32167 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.11514ms [15:07:02]W: [Step 10/10] I0425 15:07:02.188874 32167 replica.cpp:712] Persisted action at 0 [15:07:02]W: [Step 10/10] I0425 15:07:02.189128 32163 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0 [15:07:02]W: [Step 10/10] I0425 15:07:02.190341 32163 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.197513ms [15:07:02]W: [Step 10/10] I0425 15:07:02.190356 32163 replica.cpp:712] Persisted action at 0 [15:07:02]W: [Step 10/10] I0425 15:07:02.190362 32163 replica.cpp:697] Replica learned NOP action at position 0 [15:07:02]W: [Step 10/10] I0425 15:07:02.190518 32162 log.cpp:540] Writer started with ending position 0 [15:07:02]W: [Step 10/10] I0425 15:07:02.190822 32165 leveldb.cpp:436] Reading position from leveldb took 10027ns [15:07:02]W: [Step 10/10] I0425 15:07:02.191026 32163 registrar.cpp:364] Successfully fetched the registry (0B) in 8.86912ms [15:07:02]W: [Step 10/10] I0425 15:07:02.191061 32163 registrar.cpp:463] Applied 1 operations in 4130ns; attempting to update the 'registry' [15:07:02]W: [Step 10/10] I0425 15:07:02.191259 32166 log.cpp:548] Attempting to append 205 bytes to the log [15:07:02]W: [Step 10/10] I0425 15:07:02.191301 32166 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 [15:07:02]W: [Step 10/10] I0425 15:07:02.191524 32162 replica.cpp:537] Replica received write request for position 1 from (17800)@172.30.2.13:42326 [15:07:02]W: [Step 10/10] I0425 15:07:02.192633 32162 leveldb.cpp:341] Persisting action (224 bytes) to leveldb took 1.092846ms [15:07:02]W: [Step 10/10] I0425 15:07:02.192648 32162 replica.cpp:712] Persisted action at 1 [15:07:02]W: [Step 10/10] I0425 15:07:02.192883 32164 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0 [15:07:02]W: [Step 10/10] I0425 15:07:02.193985 32164 leveldb.cpp:341] Persisting action (226 bytes) to leveldb took 1.08493ms [15:07:02]W: [Step 10/10] I0425 15:07:02.194001 32164 replica.cpp:712] Persisted action at 1 [15:07:02]W: [Step 10/10] I0425 15:07:02.194006 32164 replica.cpp:697] Replica learned APPEND action at position 1 [15:07:02]W: [Step 10/10] I0425 15:07:02.194190 32165 registrar.cpp:508] Successfully updated the 'registry' in 3.108864ms [15:07:02]W: [Step 10/10] I0425 15:07:02.194236 32165 registrar.cpp:394] Successfully recovered registrar [15:07:02]W: [Step 10/10] I0425 15:07:02.194283 32168 log.cpp:567] Attempting to truncate the log to 1 [15:07:02]W: [Step 10/10] I0425 15:07:02.194350 32162 master.cpp:1740] Recovered 0 agents from the Registry (166B) ; allowing 10mins for agents to re-register [15:07:02]W: [Step 10/10] I0425 15:07:02.194396 32167 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover [15:07:02]W: [Step 10/10] I0425 15:07:02.194461 32166 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2 [15:07:02]W: [Step 10/10] I0425 15:07:02.194767 32163 replica.cpp:537] Replica received write request for position 2 from (17801)@172.30.2.13:42326 [15:07:02]W: [Step 10/10] I0425 15:07:02.195948 32163 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.163067ms [15:07:02]W: [Step 10/10] I0425 15:07:02.195963 32163 replica.cpp:712] Persisted action at 2 [15:07:02]W: [Step 10/10] I0425 15:07:02.196156 32161 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0 [15:07:02]W: [Step 10/10] I0425 15:07:02.197480 32161 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.305359ms [15:07:02]W: [Step 10/10] I0425 15:07:02.197509 32161 leveldb.cpp:399] Deleting ~1 keys from leveldb took 13719ns [15:07:02]W: [Step 10/10] I0425 15:07:02.197516 32161 replica.cpp:712] Persisted action at 2 [15:07:02]W: [Step 10/10] I0425 15:07:02.197521 32161 replica.cpp:697] Replica learned TRUNCATE action at position 2 [15:07:03]W: [Step 10/10] I0425 15:07:03.182390 32167 hierarchical.cpp:1488] No resources available to allocate! [15:07:03]W: [Step 10/10] I0425 15:07:03.182428 32167 hierarchical.cpp:1139] Performed allocation for 0 agents in 69623ns [15:07:04]W: [Step 10/10] I0425 15:07:04.182711 32168 hierarchical.cpp:1488] No resources available to allocate! [15:07:04]W: [Step 10/10] I0425 15:07:04.182757 32168 hierarchical.cpp:1139] Performed allocation for 0 agents in 91881ns [15:07:05]W: [Step 10/10] I0425 15:07:05.183476 32163 hierarchical.cpp:1488] No resources available to allocate! [15:07:05]W: [Step 10/10] I0425 15:07:05.183509 32163 hierarchical.cpp:1139] Performed allocation for 0 agents in 59724ns [15:07:06]W: [Step 10/10] I0425 15:07:06.184595 32168 hierarchical.cpp:1488] No resources available to allocate! [15:07:06]W: [Step 10/10] I0425 15:07:06.184630 32168 hierarchical.cpp:1139] Performed allocation for 0 agents in 51046ns [15:07:07]W: [Step 10/10] I0425 15:07:07.184818 32167 hierarchical.cpp:1488] No resources available to allocate! [15:07:07]W: [Step 10/10] I0425 15:07:07.184854 32167 hierarchical.cpp:1139] Performed allocation for 0 agents in 56653ns [15:07:08]W: [Step 10/10] I0425 15:07:08.185839 32168 hierarchical.cpp:1488] No resources available to allocate! [15:07:08]W: [Step 10/10] I0425 15:07:08.185873 32168 hierarchical.cpp:1139] Performed allocation for 0 agents in 46112ns [15:07:09]W: [Step 10/10] I0425 15:07:09.186439 32167 hierarchical.cpp:1488] No resources available to allocate! [15:07:09]W: [Step 10/10] I0425 15:07:09.186473 32167 hierarchical.cpp:1139] Performed allocation for 0 agents in 54647ns [15:07:10]W: [Step 10/10] I0425 15:07:10.186907 32168 hierarchical.cpp:1488] No resources available to allocate! [15:07:10]W: [Step 10/10] I0425 15:07:10.186942 32168 hierarchical.cpp:1139] Performed allocation for 0 agents in 49298ns [15:07:11]W: [Step 10/10] I0425 15:07:11.188061 32164 hierarchical.cpp:1488] No resources available to allocate! [15:07:11]W: [Step 10/10] I0425 15:07:11.188093 32164 hierarchical.cpp:1139] Performed allocation for 0 agents in 67195ns [15:07:12]W: [Step 10/10] I0425 15:07:12.189275 32161 hierarchical.cpp:1488] No resources available to allocate! [15:07:12]W: [Step 10/10] I0425 15:07:12.189311 32161 hierarchical.cpp:1139] Performed allocation for 0 agents in 68130ns [15:07:13]W: [Step 10/10] I0425 15:07:13.190248 32163 hierarchical.cpp:1488] No resources available to allocate! [15:07:13]W: [Step 10/10] I0425 15:07:13.190286 32163 hierarchical.cpp:1139] Performed allocation for 0 agents in 57124ns [15:07:14]W: [Step 10/10] I0425 15:07:14.191352 32161 hierarchical.cpp:1488] No resources available to allocate! [15:07:14]W: [Step 10/10] I0425 15:07:14.191382 32161 hierarchical.cpp:1139] Performed allocation for 0 agents in 50249ns [15:07:15]W: [Step 10/10] I0425 15:07:15.192203 32166 hierarchical.cpp:1488] No resources available to allocate! [15:07:15]W: [Step 10/10] I0425 15:07:15.192237 32166 hierarchical.cpp:1139] Performed allocation for 0 agents in 75731ns [15:07:16]W: [Step 10/10] I0425 15:07:16.192332 32164 hierarchical.cpp:1488] No resources available to allocate! [15:07:16]W: [Step 10/10] I0425 15:07:16.192363 32164 hierarchical.cpp:1139] Performed allocation for 0 agents in 57948ns [15:07:17]W: [Step 10/10] I0425 15:07:17.193349 32162 hierarchical.cpp:1488] No resources available to allocate! [15:07:17]W: [Step 10/10] I0425 15:07:17.193379 32162 hierarchical.cpp:1139] Performed allocation for 0 agents in 57275ns [15:07:18]W: [Step 10/10] I0425 15:07:18.081517 32147 containerizer.cpp:178] Using isolation: docker/runtime,filesystem/linux,network/cni [15:07:18]W: [Step 10/10] I0425 15:07:18.088409 32147 linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher [15:07:18]W: [Step 10/10] E0425 15:07:18.093040 32147 shell.hpp:106] Command 'hadoop version 2>&1' failed; this is the output: [15:07:18]W: [Step 10/10] sh: hadoop: command not found [15:07:18]W: [Step 10/10] I0425 15:07:18.093065 32147 fetcher.cpp:59] Skipping URI fetcher plugin 'hadoop' as it could not be created: Failed to create HDFS client: Failed to execute 'hadoop version 2>&1'; the command was either not found or exited with a non-zero exit status: 127 [15:07:18]W: [Step 10/10] I0425 15:07:18.093106 32147 local_puller.cpp:90] Creating local puller with docker registry '/tmp/G2DxFl/archives' [15:07:18]W: [Step 10/10] I0425 15:07:18.093937 32147 linux.cpp:81] Making '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S' a shared mount [15:07:18]W: [Step 10/10] I0425 15:07:18.101300 32164 slave.cpp:202] Agent started on 456)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.101318 32164 slave.cpp:203] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="/tmp/G2DxFl/archives" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/G2DxFl/store" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/http_credentials" --image_providers="docker" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="docker/runtime,filesystem/linux" --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S" [15:07:18]W: [Step 10/10] I0425 15:07:18.101650 32164 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/credential' [15:07:18]W: [Step 10/10] I0425 15:07:18.101753 32164 slave.cpp:340] Agent using credential for: test-principal [15:07:18]W: [Step 10/10] I0425 15:07:18.101765 32164 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/http_credentials' [15:07:18]W: [Step 10/10] I0425 15:07:18.101934 32164 slave.cpp:392] Using default 'basic' HTTP authenticator [15:07:18]W: [Step 10/10] I0425 15:07:18.102025 32147 sched.cpp:224] Version: 0.29.0 [15:07:18]W: [Step 10/10] I0425 15:07:18.102108 32164 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000] [15:07:18]W: [Step 10/10] Trying semicolon-delimited string format instead [15:07:18]W: [Step 10/10] I0425 15:07:18.102246 32164 slave.cpp:591] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] [15:07:18]W: [Step 10/10] I0425 15:07:18.102258 32168 sched.cpp:328] New master detected at master@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.102270 32164 slave.cpp:599] Agent attributes: [ ] [15:07:18]W: [Step 10/10] I0425 15:07:18.102288 32164 slave.cpp:604] Agent hostname: ip-172-30-2-13.mesosphere.io [15:07:18]W: [Step 10/10] I0425 15:07:18.102298 32168 sched.cpp:384] Authenticating with master master@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.102304 32168 sched.cpp:391] Using default CRAM-MD5 authenticatee [15:07:18]W: [Step 10/10] I0425 15:07:18.102377 32167 authenticatee.cpp:121] Creating new client SASL connection [15:07:18]W: [Step 10/10] I0425 15:07:18.102607 32167 master.cpp:5803] Authenticating scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.102687 32165 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/meta' [15:07:18]W: [Step 10/10] I0425 15:07:18.102716 32168 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(929)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.102793 32166 authenticator.cpp:98] Creating new server SASL connection [15:07:18]W: [Step 10/10] I0425 15:07:18.102864 32167 status_update_manager.cpp:200] Recovering status update manager [15:07:18]W: [Step 10/10] I0425 15:07:18.102946 32163 containerizer.cpp:444] Recovering containerizer [15:07:18]W: [Step 10/10] I0425 15:07:18.103004 32162 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5 [15:07:18]W: [Step 10/10] I0425 15:07:18.103031 32162 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5' [15:07:18]W: [Step 10/10] I0425 15:07:18.103080 32162 authenticator.cpp:203] Received SASL authentication start [15:07:18]W: [Step 10/10] I0425 15:07:18.103122 32162 authenticator.cpp:325] Authentication requires more steps [15:07:18]W: [Step 10/10] I0425 15:07:18.103206 32162 authenticatee.cpp:258] Received SASL authentication step [15:07:18]W: [Step 10/10] I0425 15:07:18.103269 32162 authenticator.cpp:231] Received SASL authentication step [15:07:18]W: [Step 10/10] I0425 15:07:18.103291 32162 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-13.mesosphere.io' server FQDN: 'ip-172-30-2-13.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false [15:07:18]W: [Step 10/10] I0425 15:07:18.103302 32162 auxprop.cpp:179] Looking up auxiliary property '*userPassword' [15:07:18]W: [Step 10/10] I0425 15:07:18.103317 32162 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' [15:07:18]W: [Step 10/10] I0425 15:07:18.103332 32162 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-13.mesosphere.io' server FQDN: 'ip-172-30-2-13.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true [15:07:18]W: [Step 10/10] I0425 15:07:18.103339 32162 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true [15:07:18]W: [Step 10/10] I0425 15:07:18.103346 32162 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true [15:07:18]W: [Step 10/10] I0425 15:07:18.103358 32162 authenticator.cpp:317] Authentication success [15:07:18]W: [Step 10/10] I0425 15:07:18.103404 32166 authenticatee.cpp:298] Authentication success [15:07:18]W: [Step 10/10] I0425 15:07:18.103425 32164 master.cpp:5833] Successfully authenticated principal 'test-principal' at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.103446 32161 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(929)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.103514 32168 sched.cpp:474] Successfully authenticated with master master@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.103528 32168 sched.cpp:783] Sending SUBSCRIBE call to master@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.103580 32168 sched.cpp:816] Will retry registration in 628.03409ms if necessary [15:07:18]W: [Step 10/10] I0425 15:07:18.103618 32167 master.cpp:2465] Received SUBSCRIBE call for framework 'default' at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.103634 32167 master.cpp:1971] Authorizing framework principal 'test-principal' to receive offers for role '*' [15:07:18]W: [Step 10/10] I0425 15:07:18.103719 32166 master.cpp:2541] Subscribing framework default with checkpointing disabled and capabilities [ ] [15:07:18]W: [Step 10/10] I0425 15:07:18.103853 32167 hierarchical.cpp:264] Added framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:18]W: [Step 10/10] I0425 15:07:18.103874 32167 hierarchical.cpp:1488] No resources available to allocate! [15:07:18]W: [Step 10/10] I0425 15:07:18.103884 32167 hierarchical.cpp:1583] No inverse offers to send out! [15:07:18]W: [Step 10/10] I0425 15:07:18.103901 32167 hierarchical.cpp:1139] Performed allocation for 0 agents in 34160ns [15:07:18]W: [Step 10/10] I0425 15:07:18.103919 32161 sched.cpp:710] Framework registered with f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:18]W: [Step 10/10] I0425 15:07:18.103940 32161 sched.cpp:724] Scheduler::registered took 8133ns [15:07:18]W: [Step 10/10] I0425 15:07:18.104763 32162 metadata_manager.cpp:192] No images to load from disk. Docker provisioner image storage path '/tmp/G2DxFl/store/storedImages' does not exist [15:07:18]W: [Step 10/10] I0425 15:07:18.104841 32161 provisioner.cpp:245] Provisioner recovery complete [15:07:18]W: [Step 10/10] I0425 15:07:18.104950 32162 slave.cpp:4824] Finished recovery [15:07:18]W: [Step 10/10] I0425 15:07:18.105165 32162 slave.cpp:4996] Querying resource estimator for oversubscribable resources [15:07:18]W: [Step 10/10] I0425 15:07:18.105257 32168 status_update_manager.cpp:174] Pausing sending status updates [15:07:18]W: [Step 10/10] I0425 15:07:18.105257 32165 slave.cpp:951] New master detected at master@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.105294 32165 slave.cpp:1014] Authenticating with master master@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.105300 32165 slave.cpp:1019] Using default CRAM-MD5 authenticatee [15:07:18]W: [Step 10/10] I0425 15:07:18.105330 32165 slave.cpp:987] Detecting new master [15:07:18]W: [Step 10/10] I0425 15:07:18.105345 32161 authenticatee.cpp:121] Creating new client SASL connection [15:07:18]W: [Step 10/10] I0425 15:07:18.105358 32165 slave.cpp:5010] Received oversubscribable resources from the resource estimator [15:07:18]W: [Step 10/10] I0425 15:07:18.105512 32161 master.cpp:5803] Authenticating slave(456)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.105566 32166 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(930)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.105621 32166 authenticator.cpp:98] Creating new server SASL connection [15:07:18]W: [Step 10/10] I0425 15:07:18.105792 32166 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5 [15:07:18]W: [Step 10/10] I0425 15:07:18.105808 32166 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5' [15:07:18]W: [Step 10/10] I0425 15:07:18.105854 32167 authenticator.cpp:203] Received SASL authentication start [15:07:18]W: [Step 10/10] I0425 15:07:18.105885 32167 authenticator.cpp:325] Authentication requires more steps [15:07:18]W: [Step 10/10] I0425 15:07:18.105916 32167 authenticatee.cpp:258] Received SASL authentication step [15:07:18]W: [Step 10/10] I0425 15:07:18.105948 32167 authenticator.cpp:231] Received SASL authentication step [15:07:18]W: [Step 10/10] I0425 15:07:18.105963 32167 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-13.mesosphere.io' server FQDN: 'ip-172-30-2-13.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false [15:07:18]W: [Step 10/10] I0425 15:07:18.105975 32167 auxprop.cpp:179] Looking up auxiliary property '*userPassword' [15:07:18]W: [Step 10/10] I0425 15:07:18.105986 32167 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5' [15:07:18]W: [Step 10/10] I0425 15:07:18.105993 32167 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-13.mesosphere.io' server FQDN: 'ip-172-30-2-13.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true [15:07:18]W: [Step 10/10] I0425 15:07:18.105998 32167 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true [15:07:18]W: [Step 10/10] I0425 15:07:18.106001 32167 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true [15:07:18]W: [Step 10/10] I0425 15:07:18.106009 32167 authenticator.cpp:317] Authentication success [15:07:18]W: [Step 10/10] I0425 15:07:18.106045 32167 authenticatee.cpp:298] Authentication success [15:07:18]W: [Step 10/10] I0425 15:07:18.106070 32165 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(930)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.106088 32161 master.cpp:5833] Successfully authenticated principal 'test-principal' at slave(456)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.106149 32167 slave.cpp:1084] Successfully authenticated with master master@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.106194 32167 slave.cpp:1480] Will retry registration in 3.523044ms if necessary [15:07:18]W: [Step 10/10] I0425 15:07:18.106245 32162 master.cpp:4514] Registering agent at slave(456)@172.30.2.13:42326 (ip-172-30-2-13.mesosphere.io) with id f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 [15:07:18]W: [Step 10/10] I0425 15:07:18.106359 32165 registrar.cpp:463] Applied 1 operations in 13916ns; attempting to update the 'registry' [15:07:18]W: [Step 10/10] I0425 15:07:18.106518 32161 log.cpp:548] Attempting to append 390 bytes to the log [15:07:18]W: [Step 10/10] I0425 15:07:18.106564 32161 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 [15:07:18]W: [Step 10/10] I0425 15:07:18.106839 32163 replica.cpp:537] Replica received write request for position 3 from (17825)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.107951 32163 leveldb.cpp:341] Persisting action (409 bytes) to leveldb took 1.089055ms [15:07:18]W: [Step 10/10] I0425 15:07:18.107967 32163 replica.cpp:712] Persisted action at 3 [15:07:18]W: [Step 10/10] I0425 15:07:18.108248 32167 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0 [15:07:18]W: [Step 10/10] I0425 15:07:18.109148 32167 leveldb.cpp:341] Persisting action (411 bytes) to leveldb took 880495ns [15:07:18]W: [Step 10/10] I0425 15:07:18.109159 32167 replica.cpp:712] Persisted action at 3 [15:07:18]W: [Step 10/10] I0425 15:07:18.109165 32167 replica.cpp:697] Replica learned APPEND action at position 3 [15:07:18]W: [Step 10/10] I0425 15:07:18.109462 32164 registrar.cpp:508] Successfully updated the 'registry' in 3.08096ms [15:07:18]W: [Step 10/10] I0425 15:07:18.109516 32163 log.cpp:567] Attempting to truncate the log to 3 [15:07:18]W: [Step 10/10] I0425 15:07:18.109577 32163 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4 [15:07:18]W: [Step 10/10] I0425 15:07:18.109673 32163 slave.cpp:3699] Received ping from slave-observer(420)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.109658 32161 master.cpp:4582] Registered agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 at slave(456)@172.30.2.13:42326 (ip-172-30-2-13.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] [15:07:18]W: [Step 10/10] I0425 15:07:18.109694 32166 hierarchical.cpp:473] Added agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 (ip-172-30-2-13.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) [15:07:18]W: [Step 10/10] I0425 15:07:18.109729 32163 slave.cpp:1128] Registered with master master@172.30.2.13:42326; given agent ID f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 [15:07:18]W: [Step 10/10] I0425 15:07:18.109738 32163 fetcher.cpp:81] Clearing fetcher cache [15:07:18]W: [Step 10/10] I0425 15:07:18.109789 32161 status_update_manager.cpp:181] Resuming sending status updates [15:07:18]W: [Step 10/10] I0425 15:07:18.109817 32166 hierarchical.cpp:1583] No inverse offers to send out! [15:07:18]W: [Step 10/10] I0425 15:07:18.109843 32166 hierarchical.cpp:1162] Performed allocation for agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 in 122827ns [15:07:18]W: [Step 10/10] I0425 15:07:18.109891 32167 replica.cpp:537] Replica received write request for position 4 from (17826)@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.109915 32164 master.cpp:5632] Sending 1 offers to framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.109956 32163 slave.cpp:1151] Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/meta/slaves/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0/slave.info' [15:07:18]W: [Step 10/10] I0425 15:07:18.110071 32162 sched.cpp:880] Scheduler::resourceOffers took 32262ns [15:07:18]W: [Step 10/10] I0425 15:07:18.110090 32163 slave.cpp:1188] Forwarding total oversubscribed resources [15:07:18]W: [Step 10/10] I0425 15:07:18.110218 32165 master.cpp:4926] Received update of agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 at slave(456)@172.30.2.13:42326 (ip-172-30-2-13.mesosphere.io) with total oversubscribed resources [15:07:18]W: [Step 10/10] I0425 15:07:18.110232 32147 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:128 [15:07:18]W: [Step 10/10] Trying semicolon-delimited string format instead [15:07:18]W: [Step 10/10] I0425 15:07:18.110344 32163 hierarchical.cpp:531] Agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 (ip-172-30-2-13.mesosphere.io) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) [15:07:18]W: [Step 10/10] I0425 15:07:18.110394 32163 hierarchical.cpp:1488] No resources available to allocate! [15:07:18]W: [Step 10/10] I0425 15:07:18.110405 32163 hierarchical.cpp:1583] No inverse offers to send out! [15:07:18]W: [Step 10/10] I0425 15:07:18.110422 32163 hierarchical.cpp:1162] Performed allocation for agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 in 47476ns [15:07:18]W: [Step 10/10] I0425 15:07:18.110503 32163 master.cpp:3412] Processing ACCEPT call for offers: [ f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-O0 ] on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 at slave(456)@172.30.2.13:42326 (ip-172-30-2-13.mesosphere.io) for framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:07:18]W: [Step 10/10] I0425 15:07:18.110517 32163 master.cpp:3015] Authorizing framework principal 'test-principal' to launch task 41d96480-fae8-44fe-bd96-7c625ddc6a09 as user 'root' [15:07:18]W: [Step 10/10] I0425 15:07:18.110780 32161 master.hpp:177] Adding task 41d96480-fae8-44fe-bd96-7c625ddc6a09 with resources cpus(*):1; mem(*):128 on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 (ip-172-30-2-13.mesosphere.io) [15:07:18]W: [Step 10/10] I0425 15:07:18.110822 32167 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 913411ns [15:07:18]W: [Step 10/10] I0425 15:07:18.110819 32161 master.cpp:3897] Launching task 41d96480-fae8-44fe-bd96-7c625ddc6a09 of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 with resources cpus(*):1; mem(*):128 on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 at slave(456)@172.30.2.13:42326 (ip-172-30-2-13.mesosphere.io) [15:07:18]W: [Step 10/10] I0425 15:07:18.110836 32167 replica.cpp:712] Persisted action at 4 [15:07:18]W: [Step 10/10] I0425 15:07:18.110921 32165 slave.cpp:1520] Got assigned task 41d96480-fae8-44fe-bd96-7c625ddc6a09 for framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:18]W: [Step 10/10] I0425 15:07:18.111024 32165 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32 [15:07:18]W: [Step 10/10] Trying semicolon-delimited string format instead [15:07:18]W: [Step 10/10] I0425 15:07:18.111018 32164 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):128) on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 from framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:18]W: [Step 10/10] I0425 15:07:18.111047 32167 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0 [15:07:18]W: [Step 10/10] I0425 15:07:18.111050 32164 hierarchical.cpp:928] Framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 filtered agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 for 5secs [15:07:18]W: [Step 10/10] I0425 15:07:18.111176 32165 slave.cpp:1639] Launching task 41d96480-fae8-44fe-bd96-7c625ddc6a09 for framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:18]W: [Step 10/10] I0425 15:07:18.111212 32165 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32 [15:07:18]W: [Step 10/10] Trying semicolon-delimited string format instead [15:07:18]W: [Step 10/10] I0425 15:07:18.111510 32165 paths.cpp:528] Trying to chown '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/slaves/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0/frameworks/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000/executors/41d96480-fae8-44fe-bd96-7c625ddc6a09/runs/dca2f70c-0fdf-42f6-afba-3cca70f28b01' to user 'root' [15:07:18]W: [Step 10/10] I0425 15:07:18.112715 32167 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 624784ns [15:07:18]W: [Step 10/10] I0425 15:07:18.112800 32167 leveldb.cpp:399] Deleting ~2 keys from leveldb took 52809ns [15:07:18]W: [Step 10/10] I0425 15:07:18.112815 32167 replica.cpp:712] Persisted action at 4 [15:07:18]W: [Step 10/10] I0425 15:07:18.112823 32167 replica.cpp:697] Replica learned TRUNCATE action at position 4 [15:07:18]W: [Step 10/10] I0425 15:07:18.116066 32165 slave.cpp:5644] Launching executor 41d96480-fae8-44fe-bd96-7c625ddc6a09 of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/slaves/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0/frameworks/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000/executors/41d96480-fae8-44fe-bd96-7c625ddc6a09/runs/dca2f70c-0fdf-42f6-afba-3cca70f28b01' [15:07:18]W: [Step 10/10] I0425 15:07:18.116205 32167 containerizer.cpp:703] Starting container 'dca2f70c-0fdf-42f6-afba-3cca70f28b01' for executor '41d96480-fae8-44fe-bd96-7c625ddc6a09' of framework 'f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000' [15:07:18]W: [Step 10/10] I0425 15:07:18.116210 32165 slave.cpp:1865] Queuing task '41d96480-fae8-44fe-bd96-7c625ddc6a09' for executor '41d96480-fae8-44fe-bd96-7c625ddc6a09' of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:18]W: [Step 10/10] I0425 15:07:18.116268 32165 slave.cpp:904] Successfully attached file '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/slaves/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0/frameworks/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000/executors/41d96480-fae8-44fe-bd96-7c625ddc6a09/runs/dca2f70c-0fdf-42f6-afba-3cca70f28b01' [15:07:18]W: [Step 10/10] I0425 15:07:18.116515 32168 metadata_manager.cpp:159] Looking for image 'alpine' [15:07:18]W: [Step 10/10] I0425 15:07:18.116729 32166 local_puller.cpp:142] Untarring image 'alpine' from '/tmp/G2DxFl/archives/alpine.tar' to '/tmp/G2DxFl/store/staging/mHBdlv' [15:07:18]W: [Step 10/10] I0425 15:07:18.193632 32165 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 for framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:18]W: [Step 10/10] I0425 15:07:18.193694 32165 hierarchical.cpp:1488] No resources available to allocate! [15:07:18]W: [Step 10/10] I0425 15:07:18.193701 32165 hierarchical.cpp:1583] No inverse offers to send out! [15:07:18]W: [Step 10/10] I0425 15:07:18.193718 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 210907ns [15:07:19]W: [Step 10/10] I0425 15:07:19.194316 32161 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 for framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:19]W: [Step 10/10] I0425 15:07:19.194358 32161 hierarchical.cpp:1488] No resources available to allocate! [15:07:19]W: [Step 10/10] I0425 15:07:19.194365 32161 hierarchical.cpp:1583] No inverse offers to send out! [15:07:19]W: [Step 10/10] I0425 15:07:19.194381 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 180413ns [15:07:19]W: [Step 10/10] I0425 15:07:19.207705 32163 local_puller.cpp:162] The repositories JSON file for image 'alpine' is '{"alpine":{"latest":"815b809d588c80fd6ddf4d6ac244ad1c01ae4cbe0f91cc7480e306671ee9c346"}}' [15:07:19]W: [Step 10/10] I0425 15:07:19.207916 32163 local_puller.cpp:290] Extracting layer tar ball '/tmp/G2DxFl/store/staging/mHBdlv/815b809d588c80fd6ddf4d6ac244ad1c01ae4cbe0f91cc7480e306671ee9c346/layer.tar to rootfs '/tmp/G2DxFl/store/staging/mHBdlv/815b809d588c80fd6ddf4d6ac244ad1c01ae4cbe0f91cc7480e306671ee9c346/rootfs' [15:07:20]W: [Step 10/10] I0425 15:07:20.195329 32162 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 for framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:20]W: [Step 10/10] I0425 15:07:20.195376 32162 hierarchical.cpp:1488] No resources available to allocate! [15:07:20]W: [Step 10/10] I0425 15:07:20.195384 32162 hierarchical.cpp:1583] No inverse offers to send out! [15:07:20]W: [Step 10/10] I0425 15:07:20.195400 32162 hierarchical.cpp:1139] Performed allocation for 1 agents in 219707ns [15:07:21]W: [Step 10/10] I0425 15:07:21.196656 32164 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 for framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:21]W: [Step 10/10] I0425 15:07:21.196715 32164 hierarchical.cpp:1488] No resources available to allocate! [15:07:21]W: [Step 10/10] I0425 15:07:21.196722 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:07:21]W: [Step 10/10] I0425 15:07:21.196737 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 177145ns [15:07:22]W: [Step 10/10] I0425 15:07:22.197506 32165 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 for framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:07:22]W: [Step 10/10] I0425 15:07:22.197547 32165 hierarchical.cpp:1488] No resources available to allocate! [15:07:22]W: [Step 10/10] I0425 15:07:22.197553 32165 hierarchical.cpp:1583] No inverse offers to send out! [15:07:22]W: [Step 10/10] I0425 15:07:22.197567 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 168766ns [15:07:23]W: [Step 10/10] I0425 15:07:23.198818 32161 hierarchical.cpp:1583] No inverse offers to send out! [15:07:23]W: [Step 10/10] I0425 15:07:23.198860 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 195868ns [15:07:23]W: [Step 10/10] I0425 15:07:23.198932 32166 master.cpp:5632] Sending 1 offers to framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:07:23]W: [Step 10/10] I0425 15:07:23.199066 32166 sched.cpp:880] Scheduler::resourceOffers took 11062ns [15:07:24]W: [Step 10/10] I0425 15:07:24.199370 32163 hierarchical.cpp:1488] No resources available to allocate! [15:07:24]W: [Step 10/10] I0425 15:07:24.199391 32163 hierarchical.cpp:1583] No inverse offers to send out! [15:07:24]W: [Step 10/10] I0425 15:07:24.199405 32163 hierarchical.cpp:1139] Performed allocation for 1 agents in 79072ns [15:07:25]W: [Step 10/10] I0425 15:07:25.199781 32167 hierarchical.cpp:1488] No resources available to allocate! [15:07:25]W: [Step 10/10] I0425 15:07:25.199800 32167 hierarchical.cpp:1583] No inverse offers to send out! [15:07:25]W: [Step 10/10] I0425 15:07:25.199812 32167 hierarchical.cpp:1139] Performed allocation for 1 agents in 85763ns [15:07:26]W: [Step 10/10] I0425 15:07:26.200672 32164 hierarchical.cpp:1488] No resources available to allocate! [15:07:26]W: [Step 10/10] I0425 15:07:26.200696 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:07:26]W: [Step 10/10] I0425 15:07:26.200711 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 79524ns [15:07:27]W: [Step 10/10] I0425 15:07:27.201580 32161 hierarchical.cpp:1488] No resources available to allocate! [15:07:27]W: [Step 10/10] I0425 15:07:27.201609 32161 hierarchical.cpp:1583] No inverse offers to send out! [15:07:27]W: [Step 10/10] I0425 15:07:27.201627 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 94416ns [15:07:28]W: [Step 10/10] I0425 15:07:28.202420 32168 hierarchical.cpp:1488] No resources available to allocate! [15:07:28]W: [Step 10/10] I0425 15:07:28.202445 32168 hierarchical.cpp:1583] No inverse offers to send out! [15:07:28]W: [Step 10/10] I0425 15:07:28.202461 32168 hierarchical.cpp:1139] Performed allocation for 1 agents in 87566ns [15:07:29]W: [Step 10/10] I0425 15:07:29.203049 32166 hierarchical.cpp:1488] No resources available to allocate! [15:07:29]W: [Step 10/10] I0425 15:07:29.203078 32166 hierarchical.cpp:1583] No inverse offers to send out! [15:07:29]W: [Step 10/10] I0425 15:07:29.203094 32166 hierarchical.cpp:1139] Performed allocation for 1 agents in 90535ns [15:07:30]W: [Step 10/10] I0425 15:07:30.203680 32165 hierarchical.cpp:1488] No resources available to allocate! [15:07:30]W: [Step 10/10] I0425 15:07:30.203696 32165 hierarchical.cpp:1583] No inverse offers to send out! [15:07:30]W: [Step 10/10] I0425 15:07:30.203707 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 52805ns [15:07:31]W: [Step 10/10] I0425 15:07:31.204231 32164 hierarchical.cpp:1488] No resources available to allocate! [15:07:31]W: [Step 10/10] I0425 15:07:31.204257 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:07:31]W: [Step 10/10] I0425 15:07:31.204277 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 76532ns [15:07:32]W: [Step 10/10] I0425 15:07:32.204854 32163 hierarchical.cpp:1488] No resources available to allocate! [15:07:32]W: [Step 10/10] I0425 15:07:32.204867 32163 hierarchical.cpp:1583] No inverse offers to send out! [15:07:32]W: [Step 10/10] I0425 15:07:32.204877 32163 hierarchical.cpp:1139] Performed allocation for 1 agents in 45506ns [15:07:33]W: [Step 10/10] I0425 15:07:33.106377 32162 slave.cpp:4996] Querying resource estimator for oversubscribable resources [15:07:33]W: [Step 10/10] I0425 15:07:33.106546 32168 slave.cpp:5010] Received oversubscribable resources from the resource estimator [15:07:33]W: [Step 10/10] I0425 15:07:33.110666 32161 slave.cpp:3699] Received ping from slave-observer(420)@172.30.2.13:42326 [15:07:33]W: [Step 10/10] I0425 15:07:33.205027 32161 hierarchical.cpp:1488] No resources available to allocate! [15:07:33]W: [Step 10/10] I0425 15:07:33.205039 32161 hierarchical.cpp:1583] No inverse offers to send out! [15:07:33]W: [Step 10/10] I0425 15:07:33.205054 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 50604ns [15:07:34]W: [Step 10/10] I0425 15:07:34.205543 32167 hierarchical.cpp:1488] No resources available to allocate! [15:07:34]W: [Step 10/10] I0425 15:07:34.205574 32167 hierarchical.cpp:1583] No inverse offers to send out! [15:07:34]W: [Step 10/10] I0425 15:07:34.205590 32167 hierarchical.cpp:1139] Performed allocation for 1 agents in 65040ns [15:07:35]W: [Step 10/10] I0425 15:07:35.206027 32164 hierarchical.cpp:1488] No resources available to allocate! [15:07:35]W: [Step 10/10] I0425 15:07:35.206039 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:07:35]W: [Step 10/10] I0425 15:07:35.206058 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 45986ns [15:07:36]W: [Step 10/10] I0425 15:07:36.206652 32165 hierarchical.cpp:1488] No resources available to allocate! [15:07:36]W: [Step 10/10] I0425 15:07:36.206677 32165 hierarchical.cpp:1583] No inverse offers to send out! [15:07:36]W: [Step 10/10] I0425 15:07:36.206696 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 85405ns [15:07:37]W: [Step 10/10] I0425 15:07:37.207527 32168 hierarchical.cpp:1488] No resources available to allocate! [15:07:37]W: [Step 10/10] I0425 15:07:37.207556 32168 hierarchical.cpp:1583] No inverse offers to send out! [15:07:37]W: [Step 10/10] I0425 15:07:37.207572 32168 hierarchical.cpp:1139] Performed allocation for 1 agents in 92554ns [15:07:38]W: [Step 10/10] I0425 15:07:38.208175 32166 hierarchical.cpp:1488] No resources available to allocate! [15:07:38]W: [Step 10/10] I0425 15:07:38.208199 32166 hierarchical.cpp:1583] No inverse offers to send out! [15:07:38]W: [Step 10/10] I0425 15:07:38.208221 32166 hierarchical.cpp:1139] Performed allocation for 1 agents in 85233ns [15:07:39]W: [Step 10/10] I0425 15:07:39.208797 32164 hierarchical.cpp:1488] No resources available to allocate! [15:07:39]W: [Step 10/10] I0425 15:07:39.208813 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:07:39]W: [Step 10/10] I0425 15:07:39.208825 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 53630ns [15:07:40]W: [Step 10/10] I0425 15:07:40.209425 32161 hierarchical.cpp:1488] No resources available to allocate! [15:07:40]W: [Step 10/10] I0425 15:07:40.209441 32161 hierarchical.cpp:1583] No inverse offers to send out! [15:07:40]W: [Step 10/10] I0425 15:07:40.209455 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 50178ns [15:07:41]W: [Step 10/10] I0425 15:07:41.209555 32163 hierarchical.cpp:1488] No resources available to allocate! [15:07:41]W: [Step 10/10] I0425 15:07:41.209573 32163 hierarchical.cpp:1583] No inverse offers to send out! [15:07:41]W: [Step 10/10] I0425 15:07:41.209589 32163 hierarchical.cpp:1139] Performed allocation for 1 agents in 53936ns [15:07:42]W: [Step 10/10] I0425 15:07:42.210266 32167 hierarchical.cpp:1488] No resources available to allocate! [15:07:42]W: [Step 10/10] I0425 15:07:42.210279 32167 hierarchical.cpp:1583] No inverse offers to send out! [15:07:42]W: [Step 10/10] I0425 15:07:42.210297 32167 hierarchical.cpp:1139] Performed allocation for 1 agents in 45637ns [15:07:43]W: [Step 10/10] I0425 15:07:43.210948 32162 hierarchical.cpp:1488] No resources available to allocate! [15:07:43]W: [Step 10/10] I0425 15:07:43.210973 32162 hierarchical.cpp:1583] No inverse offers to send out! [15:07:43]W: [Step 10/10] I0425 15:07:43.210989 32162 hierarchical.cpp:1139] Performed allocation for 1 agents in 79689ns [15:07:44]W: [Step 10/10] I0425 15:07:44.211794 32165 hierarchical.cpp:1488] No resources available to allocate! [15:07:44]W: [Step 10/10] I0425 15:07:44.211822 32165 hierarchical.cpp:1583] No inverse offers to send out! [15:07:44]W: [Step 10/10] I0425 15:07:44.211841 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 87717ns [15:07:45]W: [Step 10/10] I0425 15:07:45.212698 32163 hierarchical.cpp:1488] No resources available to allocate! [15:07:45]W: [Step 10/10] I0425 15:07:45.212723 32163 hierarchical.cpp:1583] No inverse offers to send out! [15:07:45]W: [Step 10/10] I0425 15:07:45.212738 32163 hierarchical.cpp:1139] Performed allocation for 1 agents in 85311ns [15:07:46]W: [Step 10/10] I0425 15:07:46.213450 32167 hierarchical.cpp:1488] No resources available to allocate! [15:07:46]W: [Step 10/10] I0425 15:07:46.213477 32167 hierarchical.cpp:1583] No inverse offers to send out! [15:07:46]W: [Step 10/10] I0425 15:07:46.213493 32167 hierarchical.cpp:1139] Performed allocation for 1 agents in 87031ns [15:07:47]W: [Step 10/10] I0425 15:07:47.213908 32161 hierarchical.cpp:1488] No resources available to allocate! [15:07:47]W: [Step 10/10] I0425 15:07:47.213935 32161 hierarchical.cpp:1583] No inverse offers to send out! [15:07:47]W: [Step 10/10] I0425 15:07:47.213951 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 92524ns [15:07:48]W: [Step 10/10] I0425 15:07:48.107192 32165 slave.cpp:4996] Querying resource estimator for oversubscribable resources [15:07:48]W: [Step 10/10] I0425 15:07:48.107322 32162 slave.cpp:5010] Received oversubscribable resources from the resource estimator [15:07:48]W: [Step 10/10] I0425 15:07:48.111474 32165 slave.cpp:3699] Received ping from slave-observer(420)@172.30.2.13:42326 [15:07:48]W: [Step 10/10] I0425 15:07:48.215004 32165 hierarchical.cpp:1488] No resources available to allocate! [15:07:48]W: [Step 10/10] I0425 15:07:48.215015 32165 hierarchical.cpp:1583] No inverse offers to send out! [15:07:48]W: [Step 10/10] I0425 15:07:48.215029 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 56982ns [15:07:49]W: [Step 10/10] I0425 15:07:49.215823 32163 hierarchical.cpp:1488] No resources available to allocate! [15:07:49]W: [Step 10/10] I0425 15:07:49.215852 32163 hierarchical.cpp:1583] No inverse offers to send out! [15:07:49]W: [Step 10/10] I0425 15:07:49.215867 32163 hierarchical.cpp:1139] Performed allocation for 1 agents in 91312ns [15:07:50]W: [Step 10/10] I0425 15:07:50.216691 32166 hierarchical.cpp:1488] No resources available to allocate! [15:07:50]W: [Step 10/10] I0425 15:07:50.216719 32166 hierarchical.cpp:1583] No inverse offers to send out! [15:07:50]W: [Step 10/10] I0425 15:07:50.216740 32166 hierarchical.cpp:1139] Performed allocation for 1 agents in 89719ns [15:07:51]W: [Step 10/10] I0425 15:07:51.217478 32162 hierarchical.cpp:1488] No resources available to allocate! [15:07:51]W: [Step 10/10] I0425 15:07:51.217509 32162 hierarchical.cpp:1583] No inverse offers to send out! [15:07:51]W: [Step 10/10] I0425 15:07:51.217526 32162 hierarchical.cpp:1139] Performed allocation for 1 agents in 98430ns [15:07:52]W: [Step 10/10] I0425 15:07:52.218420 32163 hierarchical.cpp:1488] No resources available to allocate! [15:07:52]W: [Step 10/10] I0425 15:07:52.218444 32163 hierarchical.cpp:1583] No inverse offers to send out! [15:07:52]W: [Step 10/10] I0425 15:07:52.218459 32163 hierarchical.cpp:1139] Performed allocation for 1 agents in 83372ns [15:07:53]W: [Step 10/10] I0425 15:07:53.219063 32161 hierarchical.cpp:1488] No resources available to allocate! [15:07:53]W: [Step 10/10] I0425 15:07:53.219094 32161 hierarchical.cpp:1583] No inverse offers to send out! [15:07:53]W: [Step 10/10] I0425 15:07:53.219111 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 90859ns [15:07:54]W: [Step 10/10] I0425 15:07:54.220070 32164 hierarchical.cpp:1488] No resources available to allocate! [15:07:54]W: [Step 10/10] I0425 15:07:54.220095 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:07:54]W: [Step 10/10] I0425 15:07:54.220110 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 87823ns [15:07:55]W: [Step 10/10] I0425 15:07:55.221058 32168 hierarchical.cpp:1488] No resources available to allocate! [15:07:55]W: [Step 10/10] I0425 15:07:55.221086 32168 hierarchical.cpp:1583] No inverse offers to send out! [15:07:55]W: [Step 10/10] I0425 15:07:55.221107 32168 hierarchical.cpp:1139] Performed allocation for 1 agents in 87820ns [15:07:56]W: [Step 10/10] I0425 15:07:56.222067 32162 hierarchical.cpp:1488] No resources available to allocate! [15:07:56]W: [Step 10/10] I0425 15:07:56.222093 32162 hierarchical.cpp:1583] No inverse offers to send out! [15:07:56]W: [Step 10/10] I0425 15:07:56.222110 32162 hierarchical.cpp:1139] Performed allocation for 1 agents in 94072ns [15:07:57]W: [Step 10/10] I0425 15:07:57.223033 32164 hierarchical.cpp:1488] No resources available to allocate! [15:07:57]W: [Step 10/10] I0425 15:07:57.223064 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:07:57]W: [Step 10/10] I0425 15:07:57.223090 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 108270ns [15:07:58]W: [Step 10/10] I0425 15:07:58.224179 32165 hierarchical.cpp:1488] No resources available to allocate! [15:07:58]W: [Step 10/10] I0425 15:07:58.224208 32165 hierarchical.cpp:1583] No inverse offers to send out! [15:07:58]W: [Step 10/10] I0425 15:07:58.224226 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 91758ns [15:07:59]W: [Step 10/10] I0425 15:07:59.225424 32166 hierarchical.cpp:1488] No resources available to allocate! [15:07:59]W: [Step 10/10] I0425 15:07:59.225448 32166 hierarchical.cpp:1583] No inverse offers to send out! [15:07:59]W: [Step 10/10] I0425 15:07:59.225464 32166 hierarchical.cpp:1139] Performed allocation for 1 agents in 83438ns [15:08:00]W: [Step 10/10] I0425 15:08:00.226443 32164 hierarchical.cpp:1488] No resources available to allocate! [15:08:00]W: [Step 10/10] I0425 15:08:00.226474 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:08:00]W: [Step 10/10] I0425 15:08:00.226491 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 92391ns [15:08:01]W: [Step 10/10] I0425 15:08:01.227365 32167 hierarchical.cpp:1488] No resources available to allocate! [15:08:01]W: [Step 10/10] I0425 15:08:01.227387 32167 hierarchical.cpp:1583] No inverse offers to send out! [15:08:01]W: [Step 10/10] I0425 15:08:01.227402 32167 hierarchical.cpp:1139] Performed allocation for 1 agents in 76293ns [15:08:02]W: [Step 10/10] I0425 15:08:02.228199 32168 hierarchical.cpp:1488] No resources available to allocate! [15:08:02]W: [Step 10/10] I0425 15:08:02.228220 32168 hierarchical.cpp:1583] No inverse offers to send out! [15:08:02]W: [Step 10/10] I0425 15:08:02.228235 32168 hierarchical.cpp:1139] Performed allocation for 1 agents in 76278ns [15:08:03]W: [Step 10/10] I0425 15:08:03.107926 32161 slave.cpp:4996] Querying resource estimator for oversubscribable resources [15:08:03]W: [Step 10/10] I0425 15:08:03.108036 32168 slave.cpp:5010] Received oversubscribable resources from the resource estimator [15:08:03]W: [Step 10/10] I0425 15:08:03.112210 32161 slave.cpp:3699] Received ping from slave-observer(420)@172.30.2.13:42326 [15:08:03]W: [Step 10/10] I0425 15:08:03.228732 32164 hierarchical.cpp:1488] No resources available to allocate! [15:08:03]W: [Step 10/10] I0425 15:08:03.228742 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:08:03]W: [Step 10/10] I0425 15:08:03.228757 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 59596ns [15:08:04]W: [Step 10/10] I0425 15:08:04.229460 32162 hierarchical.cpp:1488] No resources available to allocate! [15:08:04]W: [Step 10/10] I0425 15:08:04.229480 32162 hierarchical.cpp:1583] No inverse offers to send out! [15:08:04]W: [Step 10/10] I0425 15:08:04.229496 32162 hierarchical.cpp:1139] Performed allocation for 1 agents in 70740ns [15:08:05]W: [Step 10/10] I0425 15:08:05.230406 32161 hierarchical.cpp:1488] No resources available to allocate! [15:08:05]W: [Step 10/10] I0425 15:08:05.230443 32161 hierarchical.cpp:1583] No inverse offers to send out! [15:08:05]W: [Step 10/10] I0425 15:08:05.230460 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 98097ns [15:08:06]W: [Step 10/10] I0425 15:08:06.231168 32166 hierarchical.cpp:1488] No resources available to allocate! [15:08:06]W: [Step 10/10] I0425 15:08:06.231191 32166 hierarchical.cpp:1583] No inverse offers to send out! [15:08:06]W: [Step 10/10] I0425 15:08:06.231206 32166 hierarchical.cpp:1139] Performed allocation for 1 agents in 80804ns [15:08:07]W: [Step 10/10] I0425 15:08:07.232044 32167 hierarchical.cpp:1488] No resources available to allocate! [15:08:07]W: [Step 10/10] I0425 15:08:07.232074 32167 hierarchical.cpp:1583] No inverse offers to send out! [15:08:07]W: [Step 10/10] I0425 15:08:07.232094 32167 hierarchical.cpp:1139] Performed allocation for 1 agents in 95337ns [15:08:08]W: [Step 10/10] I0425 15:08:08.232728 32163 hierarchical.cpp:1488] No resources available to allocate! [15:08:08]W: [Step 10/10] I0425 15:08:08.232741 32163 hierarchical.cpp:1583] No inverse offers to send out! [15:08:08]W: [Step 10/10] I0425 15:08:08.232753 32163 hierarchical.cpp:1139] Performed allocation for 1 agents in 45537ns [15:08:09]W: [Step 10/10] I0425 15:08:09.233428 32164 hierarchical.cpp:1488] No resources available to allocate! [15:08:09]W: [Step 10/10] I0425 15:08:09.233448 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:08:09]W: [Step 10/10] I0425 15:08:09.233464 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 73905ns [15:08:10]W: [Step 10/10] I0425 15:08:10.233937 32168 hierarchical.cpp:1488] No resources available to allocate! [15:08:10]W: [Step 10/10] I0425 15:08:10.233947 32168 hierarchical.cpp:1583] No inverse offers to send out! [15:08:10]W: [Step 10/10] I0425 15:08:10.233958 32168 hierarchical.cpp:1139] Performed allocation for 1 agents in 38090ns [15:08:10]W: [Step 10/10] I0425 15:08:10.972741 32167 metadata_manager.cpp:148] Successfully cached image 'alpine' [15:08:10]W: [Step 10/10] I0425 15:08:10.973219 32161 provisioner.cpp:285] Provisioning image rootfs '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/provisioner/containers/dca2f70c-0fdf-42f6-afba-3cca70f28b01/backends/copy/rootfses/f7583759-ea67-4cf2-aa56-edcf3fdcb207' for container dca2f70c-0fdf-42f6-afba-3cca70f28b01 [15:08:10]W: [Step 10/10] I0425 15:08:10.973554 32167 copy.cpp:128] Copying layer path '/tmp/G2DxFl/store/layers/815b809d588c80fd6ddf4d6ac244ad1c01ae4cbe0f91cc7480e306671ee9c346/rootfs' to rootfs '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/provisioner/containers/dca2f70c-0fdf-42f6-afba-3cca70f28b01/backends/copy/rootfses/f7583759-ea67-4cf2-aa56-edcf3fdcb207' [15:08:11]W: [Step 10/10] I0425 15:08:11.234539 32165 hierarchical.cpp:1488] No resources available to allocate! [15:08:11]W: [Step 10/10] I0425 15:08:11.234566 32165 hierarchical.cpp:1583] No inverse offers to send out! [15:08:11]W: [Step 10/10] I0425 15:08:11.234586 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 120592ns [15:08:12]W: [Step 10/10] I0425 15:08:12.235381 32168 hierarchical.cpp:1488] No resources available to allocate! [15:08:12]W: [Step 10/10] I0425 15:08:12.235411 32168 hierarchical.cpp:1583] No inverse offers to send out! [15:08:12]W: [Step 10/10] I0425 15:08:12.235432 32168 hierarchical.cpp:1139] Performed allocation for 1 agents in 103935ns [15:08:13]W: [Step 10/10] I0425 15:08:13.235791 32164 hierarchical.cpp:1488] No resources available to allocate! [15:08:13]W: [Step 10/10] I0425 15:08:13.235815 32164 hierarchical.cpp:1583] No inverse offers to send out! [15:08:13]W: [Step 10/10] I0425 15:08:13.235831 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 89328ns [15:08:14]W: [Step 10/10] I0425 15:08:14.235991 32167 hierarchical.cpp:1488] No resources available to allocate! [15:08:15]W: [Step 10/10] I0425 15:08:14.236016 32167 hierarchical.cpp:1583] No inverse offers to send out! [15:08:15]W: [Step 10/10] I0425 15:08:14.236029 32167 hierarchical.cpp:1139] Performed allocation for 1 agents in 86883ns [15:08:15]W: [Step 10/10] I0425 15:08:15.236173 32165 hierarchical.cpp:1488] No resources available to allocate! [15:08:15]W: [Step 10/10] I0425 15:08:15.236201 32165 hierarchical.cpp:1583] No inverse offers to send out! [15:08:15]W: [Step 10/10] I0425 15:08:15.236222 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 90786ns [15:08:16]W: [Step 10/10] I0425 15:08:16.237462 32162 hierarchical.cpp:1488] No resources available to allocate! [15:08:17]W: [Step 10/10] I0425 15:08:16.237489 32162 hierarchical.cpp:1583] No inverse offers to send out! [15:08:18] : [Step 10/10] ../../src/tests/containerizer/runtime_isolator_tests.cpp:231: Failure [15:08:21]W: [Step 10/10] I0425 15:08:16.237507 32162 hierarchical.cpp:1139] Performed allocation for 1 agents in 109476ns [15:08:21] : [Step 10/10] Failed to wait 1mins for statusRunning [15:08:21] : [Step 10/10] ../../src/tests/containerizer/runtime_isolator_tests.cpp:225: Failure [15:08:21]W: [Step 10/10] I0425 15:08:17.238730 32161 hierarchical.cpp:1488] No resources available to allocate! [15:08:21] : [Step 10/10] Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))... [15:08:21]W: [Step 10/10] I0425 15:08:17.238755 32161 hierarchical.cpp:1583] No inverse offers to send out! [15:08:21] : [Step 10/10] Expected: to be called twice [15:08:21] : [Step 10/10] Actual: never called - unsatisfied and active [15:08:21]W: [Step 10/10] I0425 15:08:17.238773 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 93771ns [15:08:21]W: [Step 10/10] I0425 15:08:18.103023 32166 slave.cpp:4633] Current disk usage 3.07%. Max allowed age: 6.085051962227002days [15:08:21]W: [Step 10/10] I0425 15:08:18.109217 32168 slave.cpp:4996] Querying resource estimator for oversubscribable resources [15:08:21]W: [Step 10/10] I0425 15:08:18.109316 32167 slave.cpp:5010] Received oversubscribable resources from the resource estimator [15:08:21]W: [Step 10/10] I0425 15:08:18.111702 32168 master.cpp:1375] Framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 disconnected [15:08:21]W: [Step 10/10] I0425 15:08:18.111734 32168 master.cpp:2766] Disconnecting framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:08:21]W: [Step 10/10] I0425 15:08:18.111748 32168 master.cpp:2790] Deactivating framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:08:21]W: [Step 10/10] I0425 15:08:18.111824 32164 hierarchical.cpp:375] Deactivated framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:21]W: [Step 10/10] W0425 15:08:18.111907 32168 master.hpp:1828] Master attempted to send message to disconnected framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:08:21]W: [Step 10/10] I0425 15:08:18.111946 32168 master.cpp:1399] Giving framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 0ns to failover [15:08:21]W: [Step 10/10] I0425 15:08:18.111939 32161 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):128) on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 from framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:23]W: [Step 10/10] I0425 15:08:18.112205 32162 containerizer.cpp:1481] Destroying container 'dca2f70c-0fdf-42f6-afba-3cca70f28b01' [15:08:23]W: [Step 10/10] I0425 15:08:18.112217 32162 containerizer.cpp:1484] Waiting for the provisioner to complete for container 'dca2f70c-0fdf-42f6-afba-3cca70f28b01' [15:08:23]W: [Step 10/10] I0425 15:08:18.113154 32162 master.cpp:5484] Framework failover timeout, removing framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:08:23]W: [Step 10/10] I0425 15:08:18.113168 32162 master.cpp:6212] Removing framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (default) at scheduler-c9c7be52-70eb-44d1-ad77-8a766c97ea88@172.30.2.13:42326 [15:08:23]W: [Step 10/10] I0425 15:08:18.113201 32168 slave.cpp:3699] Received ping from slave-observer(420)@172.30.2.13:42326 [15:08:23]W: [Step 10/10] I0425 15:08:18.113204 32162 master.cpp:6727] Updating the state of task 41d96480-fae8-44fe-bd96-7c625ddc6a09 of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED) [15:08:23]W: [Step 10/10] I0425 15:08:18.113246 32168 slave.cpp:2250] Asked to shut down framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 by master@172.30.2.13:42326 [15:08:23]W: [Step 10/10] I0425 15:08:18.113261 32168 slave.cpp:2275] Shutting down framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:23]W: [Step 10/10] I0425 15:08:18.113271 32168 slave.cpp:4449] Shutting down executor '41d96480-fae8-44fe-bd96-7c625ddc6a09' of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:23]W: [Step 10/10] W0425 15:08:18.113277 32168 slave.hpp:680] Unable to send event to executor '41d96480-fae8-44fe-bd96-7c625ddc6a09' of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000: unknown connection type [15:08:23]W: [Step 10/10] I0425 15:08:18.113292 32162 master.cpp:6793] Removing task 41d96480-fae8-44fe-bd96-7c625ddc6a09 with resources cpus(*):1; mem(*):128 of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 at slave(456)@172.30.2.13:42326 (ip-172-30-2-13.mesosphere.io) [15:08:23]W: [Step 10/10] I0425 15:08:18.113322 32161 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):128 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 from framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:23]W: [Step 10/10] I0425 15:08:18.113464 32165 hierarchical.cpp:326] Removed framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:23]W: [Step 10/10] I0425 15:08:18.116307 32162 slave.cpp:4552] Ignoring registration timeout for executor '41d96480-fae8-44fe-bd96-7c625ddc6a09' because the framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 is terminating [15:08:23]W: [Step 10/10] I0425 15:08:18.238991 32162 hierarchical.cpp:1488] No resources available to allocate! [15:08:23]W: [Step 10/10] I0425 15:08:18.239017 32162 hierarchical.cpp:1139] Performed allocation for 1 agents in 64918ns [15:08:23]W: [Step 10/10] I0425 15:08:19.239764 32164 hierarchical.cpp:1488] No resources available to allocate! [15:08:23]W: [Step 10/10] I0425 15:08:19.239802 32164 hierarchical.cpp:1139] Performed allocation for 1 agents in 73308ns [15:08:23]W: [Step 10/10] I0425 15:08:20.241013 32168 hierarchical.cpp:1488] No resources available to allocate! [15:08:23]W: [Step 10/10] I0425 15:08:20.241056 32168 hierarchical.cpp:1139] Performed allocation for 1 agents in 85649ns [15:08:23]W: [Step 10/10] I0425 15:08:21.241225 32161 hierarchical.cpp:1488] No resources available to allocate! [15:08:23]W: [Step 10/10] I0425 15:08:21.241264 32161 hierarchical.cpp:1139] Performed allocation for 1 agents in 73603ns [15:08:23]W: [Step 10/10] I0425 15:08:22.242439 32166 hierarchical.cpp:1488] No resources available to allocate! [15:08:23]W: [Step 10/10] I0425 15:08:22.242478 32166 hierarchical.cpp:1139] Performed allocation for 1 agents in 86831ns [15:08:23]W: [Step 10/10] I0425 15:08:23.113929 32165 slave.cpp:4522] Killing executor '41d96480-fae8-44fe-bd96-7c625ddc6a09' of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:23]W: [Step 10/10] I0425 15:08:23.243474 32165 hierarchical.cpp:1488] No resources available to allocate! [15:08:23]W: [Step 10/10] I0425 15:08:23.243494 32165 hierarchical.cpp:1139] Performed allocation for 1 agents in 49013ns [15:08:23]W: [Step 10/10] I0425 15:08:23.661591 32168 provisioner.cpp:338] Destroying container rootfs at '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/provisioner/containers/dca2f70c-0fdf-42f6-afba-3cca70f28b01/backends/copy/rootfses/f7583759-ea67-4cf2-aa56-edcf3fdcb207' for container dca2f70c-0fdf-42f6-afba-3cca70f28b01 [15:08:23]W: [Step 10/10] E0425 15:08:23.664181 32164 slave.cpp:4018] Container 'dca2f70c-0fdf-42f6-afba-3cca70f28b01' for executor '41d96480-fae8-44fe-bd96-7c625ddc6a09' of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 failed to start: Container is currently being destroyed [15:08:24]W: [Step 10/10] I0425 15:08:24.163928 32161 slave.cpp:4124] Executor '41d96480-fae8-44fe-bd96-7c625ddc6a09' of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 has terminated with unknown status [15:08:24]W: [Step 10/10] I0425 15:08:24.163964 32161 slave.cpp:4235] Cleaning up executor '41d96480-fae8-44fe-bd96-7c625ddc6a09' of framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:24]W: [Step 10/10] I0425 15:08:24.164093 32161 slave.cpp:4323] Cleaning up framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:24]W: [Step 10/10] I0425 15:08:24.164082 32166 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/slaves/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0/frameworks/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000/executors/41d96480-fae8-44fe-bd96-7c625ddc6a09/runs/dca2f70c-0fdf-42f6-afba-3cca70f28b01' for gc 6.99999810154074days in the future [15:08:24]W: [Step 10/10] I0425 15:08:24.164145 32168 status_update_manager.cpp:282] Closing status update streams for framework f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000 [15:08:24]W: [Step 10/10] I0425 15:08:24.164146 32166 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/slaves/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0/frameworks/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000/executors/41d96480-fae8-44fe-bd96-7c625ddc6a09' for gc 6.99999810096days in the future [15:08:24]W: [Step 10/10] I0425 15:08:24.164185 32161 slave.cpp:823] Agent terminating [15:08:24]W: [Step 10/10] I0425 15:08:24.164221 32166 gc.cpp:55] Scheduling '/mnt/teamcity/temp/buildTmp/DockerRuntimeIsolatorTest_ROOT_DockerDefaultEntryptLocalPuller_IzCc1S/slaves/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0/frameworks/f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-0000' for gc 6.99999810013926days in the future [15:08:24]W: [Step 10/10] I0425 15:08:24.164257 32165 master.cpp:1336] Agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 at slave(456)@172.30.2.13:42326 (ip-172-30-2-13.mesosphere.io) disconnected [15:08:24]W: [Step 10/10] I0425 15:08:24.164278 32165 master.cpp:2825] Disconnecting agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 at slave(456)@172.30.2.13:42326 (ip-172-30-2-13.mesosphere.io) [15:08:24]W: [Step 10/10] I0425 15:08:24.164324 32165 master.cpp:2844] Deactivating agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 at slave(456)@172.30.2.13:42326 (ip-172-30-2-13.mesosphere.io) [15:08:24]W: [Step 10/10] I0425 15:08:24.164429 32165 hierarchical.cpp:560] Agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 deactivated [15:08:24]W: [Step 10/10] I0425 15:08:24.166201 32147 master.cpp:1189] Master terminating [15:08:24]W: [Step 10/10] I0425 15:08:24.166317 32162 hierarchical.cpp:505] Removed agent f480c5f5-0eb6-43fe-a0c9-6bd9cd62f517-S0 [15:08:26] : [Step 10/10] [ FAILED ] DockerRuntimeIsolatorTest.ROOT_DockerDefaultEntryptLocalPuller (84810 ms) {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)