Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Duplicate
-
None
-
None
-
None
-
Mesosphere Sprint 37
Description
Observed on Mesosphere internal CI:
[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)
Attachments
Issue Links
- depends upon
-
MESOS-4943 Reduce the size of LinuxRootfs in tests.
-
- Resolved
-