Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Duplicate
-
None
-
None
-
None
-
CenOS 7 with SSL
-
Mesosphere Sprint 37
Description
Observed on internal Mesosphere CI.
[11:18:57] : [Step 11/11] [ RUN ] ProvisionerDockerPullerTest.ROOT_LocalPullerSimpleCommand
[11:18:57]W: [Step 11/11] I0413 11:18:57.220163 32157 cluster.cpp:149] Creating default 'local' authorizer
[11:18:57]W: [Step 11/11] I0413 11:18:57.224773 32157 leveldb.cpp:174] Opened db in 4.401501ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.226209 32157 leveldb.cpp:181] Compacted db in 1.40845ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.226251 32157 leveldb.cpp:196] Created db iterator in 17537ns
[11:18:57]W: [Step 11/11] I0413 11:18:57.226263 32157 leveldb.cpp:202] Seeked to beginning of db in 1431ns
[11:18:57]W: [Step 11/11] I0413 11:18:57.226270 32157 leveldb.cpp:271] Iterated through 0 keys in the db in 322ns
[11:18:57]W: [Step 11/11] I0413 11:18:57.226307 32157 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[11:18:57]W: [Step 11/11] I0413 11:18:57.226737 32177 recover.cpp:447] Starting replica recovery
[11:18:57]W: [Step 11/11] I0413 11:18:57.226979 32177 recover.cpp:473] Replica is in EMPTY status
[11:18:57]W: [Step 11/11] I0413 11:18:57.227885 32178 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (16514)@172.30.2.185:48536
[11:18:57]W: [Step 11/11] I0413 11:18:57.228308 32176 recover.cpp:193] Received a recover response from a replica in EMPTY status
[11:18:57]W: [Step 11/11] I0413 11:18:57.228730 32178 recover.cpp:564] Updating replica status to STARTING
[11:18:57]W: [Step 11/11] I0413 11:18:57.229454 32177 master.cpp:382] Master 6cc0332e-c8aa-4649-b347-fd20899bed17 (ip-172-30-2-185.mesosphere.io) started on 172.30.2.185:48536
[11:18:57]W: [Step 11/11] I0413 11:18:57.229473 32177 master.cpp:384] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/8BsojJ/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_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/8BsojJ/master" --zk_session_timeout="10secs"
[11:18:57]W: [Step 11/11] I0413 11:18:57.229740 32177 master.cpp:433] Master only allowing authenticated frameworks to register
[11:18:57]W: [Step 11/11] I0413 11:18:57.229748 32177 master.cpp:438] Master only allowing authenticated agents to register
[11:18:57]W: [Step 11/11] I0413 11:18:57.229754 32177 credentials.hpp:37] Loading credentials for authentication from '/tmp/8BsojJ/credentials'
[11:18:57]W: [Step 11/11] I0413 11:18:57.229998 32177 master.cpp:480] Using default 'crammd5' authenticator
[11:18:57]W: [Step 11/11] I0413 11:18:57.230111 32177 master.cpp:551] Using default 'basic' HTTP authenticator
[11:18:57]W: [Step 11/11] I0413 11:18:57.230113 32172 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.208794ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.230136 32172 replica.cpp:320] Persisted replica status to STARTING
[11:18:57]W: [Step 11/11] I0413 11:18:57.230247 32177 master.cpp:589] Authorization enabled
[11:18:57]W: [Step 11/11] I0413 11:18:57.230312 32176 recover.cpp:473] Replica is in STARTING status
[11:18:57]W: [Step 11/11] I0413 11:18:57.230422 32174 whitelist_watcher.cpp:77] No whitelist given
[11:18:57]W: [Step 11/11] I0413 11:18:57.230469 32171 hierarchical.cpp:142] Initialized hierarchical allocator process
[11:18:57]W: [Step 11/11] I0413 11:18:57.231092 32172 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (16516)@172.30.2.185:48536
[11:18:57]W: [Step 11/11] I0413 11:18:57.231503 32175 recover.cpp:193] Received a recover response from a replica in STARTING status
[11:18:57]W: [Step 11/11] I0413 11:18:57.231995 32174 recover.cpp:564] Updating replica status to VOTING
[11:18:57]W: [Step 11/11] I0413 11:18:57.232906 32174 master.cpp:1832] The newly elected leader is master@172.30.2.185:48536 with id 6cc0332e-c8aa-4649-b347-fd20899bed17
[11:18:57]W: [Step 11/11] I0413 11:18:57.232933 32174 master.cpp:1845] Elected as the leading master!
[11:18:57]W: [Step 11/11] I0413 11:18:57.232947 32174 master.cpp:1532] Recovering from registrar
[11:18:57]W: [Step 11/11] I0413 11:18:57.233206 32175 registrar.cpp:331] Recovering registrar
[11:18:57]W: [Step 11/11] I0413 11:18:57.233384 32172 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.15033ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.233414 32172 replica.cpp:320] Persisted replica status to VOTING
[11:18:57]W: [Step 11/11] I0413 11:18:57.233505 32177 recover.cpp:578] Successfully joined the Paxos group
[11:18:57]W: [Step 11/11] I0413 11:18:57.233683 32177 recover.cpp:462] Recover process terminated
[11:18:57]W: [Step 11/11] I0413 11:18:57.234077 32173 log.cpp:659] Attempting to start the writer
[11:18:57]W: [Step 11/11] I0413 11:18:57.235116 32176 replica.cpp:493] Replica received implicit promise request from (16517)@172.30.2.185:48536 with proposal 1
[11:18:57]W: [Step 11/11] I0413 11:18:57.236361 32176 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.219834ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.236383 32176 replica.cpp:342] Persisted promised to 1
[11:18:57]W: [Step 11/11] I0413 11:18:57.236866 32171 coordinator.cpp:238] Coordinator attempting to fill missing positions
[11:18:57]W: [Step 11/11] I0413 11:18:57.237869 32174 replica.cpp:388] Replica received explicit promise request from (16518)@172.30.2.185:48536 for position 0 with proposal 2
[11:18:57]W: [Step 11/11] I0413 11:18:57.238976 32174 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.074663ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.238997 32174 replica.cpp:712] Persisted action at 0
[11:18:57]W: [Step 11/11] I0413 11:18:57.239826 32172 replica.cpp:537] Replica received write request for position 0 from (16519)@172.30.2.185:48536
[11:18:57]W: [Step 11/11] I0413 11:18:57.239874 32172 leveldb.cpp:436] Reading position from leveldb took 24992ns
[11:18:57]W: [Step 11/11] I0413 11:18:57.240962 32172 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.054495ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.240983 32172 replica.cpp:712] Persisted action at 0
[11:18:57]W: [Step 11/11] I0413 11:18:57.241643 32171 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[11:18:57]W: [Step 11/11] I0413 11:18:57.242774 32171 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.103367ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.242795 32171 replica.cpp:712] Persisted action at 0
[11:18:57]W: [Step 11/11] I0413 11:18:57.242810 32171 replica.cpp:697] Replica learned NOP action at position 0
[11:18:57]W: [Step 11/11] I0413 11:18:57.243263 32171 log.cpp:675] Writer started with ending position 0
[11:18:57]W: [Step 11/11] I0413 11:18:57.244233 32171 leveldb.cpp:436] Reading position from leveldb took 23816ns
[11:18:57]W: [Step 11/11] I0413 11:18:57.245132 32175 registrar.cpp:364] Successfully fetched the registry (0B) in 11.883008ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.245244 32175 registrar.cpp:463] Applied 1 operations in 30499ns; attempting to update the 'registry'
[11:18:57]W: [Step 11/11] I0413 11:18:57.245870 32174 log.cpp:683] Attempting to append 210 bytes to the log
[11:18:57]W: [Step 11/11] I0413 11:18:57.245985 32177 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[11:18:57]W: [Step 11/11] I0413 11:18:57.246618 32173 replica.cpp:537] Replica received write request for position 1 from (16520)@172.30.2.185:48536
[11:18:57]W: [Step 11/11] I0413 11:18:57.247835 32173 leveldb.cpp:341] Persisting action (229 bytes) to leveldb took 1.164074ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.247859 32173 replica.cpp:712] Persisted action at 1
[11:18:57]W: [Step 11/11] I0413 11:18:57.248417 32176 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[11:18:57]W: [Step 11/11] I0413 11:18:57.249536 32176 leveldb.cpp:341] Persisting action (231 bytes) to leveldb took 1.092573ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.249557 32176 replica.cpp:712] Persisted action at 1
[11:18:57]W: [Step 11/11] I0413 11:18:57.249572 32176 replica.cpp:697] Replica learned APPEND action at position 1
[11:18:57]W: [Step 11/11] I0413 11:18:57.250424 32175 registrar.cpp:508] Successfully updated the 'registry' in 5.126912ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.250545 32175 registrar.cpp:394] Successfully recovered registrar
[11:18:57]W: [Step 11/11] I0413 11:18:57.250633 32171 log.cpp:702] Attempting to truncate the log to 1
[11:18:57]W: [Step 11/11] I0413 11:18:57.250874 32173 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[11:18:57]W: [Step 11/11] I0413 11:18:57.250954 32176 master.cpp:1640] Recovered 0 agents from the Registry (171B) ; allowing 10mins for agents to re-register
[11:18:57]W: [Step 11/11] I0413 11:18:57.250975 32172 hierarchical.cpp:169] Skipping recovery of hierarchical allocator: nothing to recover
[11:18:57]W: [Step 11/11] I0413 11:18:57.251510 32171 replica.cpp:537] Replica received write request for position 2 from (16521)@172.30.2.185:48536
[11:18:57]W: [Step 11/11] I0413 11:18:57.252676 32171 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.138233ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.252697 32171 replica.cpp:712] Persisted action at 2
[11:18:57]W: [Step 11/11] I0413 11:18:57.253207 32177 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[11:18:57]W: [Step 11/11] I0413 11:18:57.254407 32177 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.172651ms
[11:18:57]W: [Step 11/11] I0413 11:18:57.254458 32177 leveldb.cpp:399] Deleting ~1 keys from leveldb took 27995ns
[11:18:57]W: [Step 11/11] I0413 11:18:57.254473 32177 replica.cpp:712] Persisted action at 2
[11:18:57]W: [Step 11/11] I0413 11:18:57.254487 32177 replica.cpp:697] Replica learned TRUNCATE action at position 2
[11:18:58]W: [Step 11/11] I0413 11:18:58.231709 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:18:58]W: [Step 11/11] I0413 11:18:58.231796 32177 hierarchical.cpp:1139] Performed allocation for 0 agents in 196420ns
[11:18:59]W: [Step 11/11] I0413 11:18:59.232925 32172 hierarchical.cpp:1488] No resources available to allocate!
[11:18:59]W: [Step 11/11] I0413 11:18:59.233017 32172 hierarchical.cpp:1139] Performed allocation for 0 agents in 213327ns
[11:19:00]W: [Step 11/11] I0413 11:19:00.233564 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:00]W: [Step 11/11] I0413 11:19:00.233652 32175 hierarchical.cpp:1139] Performed allocation for 0 agents in 224642ns
[11:19:01]W: [Step 11/11] I0413 11:19:01.234108 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:01]W: [Step 11/11] I0413 11:19:01.234196 32175 hierarchical.cpp:1139] Performed allocation for 0 agents in 174845ns
[11:19:02]W: [Step 11/11] I0413 11:19:02.234753 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:02]W: [Step 11/11] I0413 11:19:02.234846 32173 hierarchical.cpp:1139] Performed allocation for 0 agents in 206565ns
[11:19:03]W: [Step 11/11] I0413 11:19:03.236143 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:03]W: [Step 11/11] I0413 11:19:03.236230 32177 hierarchical.cpp:1139] Performed allocation for 0 agents in 182408ns
[11:19:04]W: [Step 11/11] I0413 11:19:04.237282 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:04]W: [Step 11/11] I0413 11:19:04.237383 32175 hierarchical.cpp:1139] Performed allocation for 0 agents in 181010ns
[11:19:05]W: [Step 11/11] I0413 11:19:05.237661 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:05]W: [Step 11/11] I0413 11:19:05.237747 32173 hierarchical.cpp:1139] Performed allocation for 0 agents in 177628ns
[11:19:06]W: [Step 11/11] I0413 11:19:06.238034 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:06]W: [Step 11/11] I0413 11:19:06.238129 32177 hierarchical.cpp:1139] Performed allocation for 0 agents in 177462ns
[11:19:07]W: [Step 11/11] I0413 11:19:07.239210 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:07]W: [Step 11/11] I0413 11:19:07.239317 32175 hierarchical.cpp:1139] Performed allocation for 0 agents in 193171ns
[11:19:08]W: [Step 11/11] I0413 11:19:08.240380 32171 hierarchical.cpp:1488] No resources available to allocate!
[11:19:08]W: [Step 11/11] I0413 11:19:08.240473 32171 hierarchical.cpp:1139] Performed allocation for 0 agents in 219393ns
[11:19:09]W: [Step 11/11] I0413 11:19:09.241842 32174 hierarchical.cpp:1488] No resources available to allocate!
[11:19:09]W: [Step 11/11] I0413 11:19:09.241931 32174 hierarchical.cpp:1139] Performed allocation for 0 agents in 204420ns
[11:19:10]W: [Step 11/11] I0413 11:19:10.243119 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:10]W: [Step 11/11] I0413 11:19:10.243206 32175 hierarchical.cpp:1139] Performed allocation for 0 agents in 166937ns
[11:19:11]W: [Step 11/11] I0413 11:19:11.244473 32176 hierarchical.cpp:1488] No resources available to allocate!
[11:19:11]W: [Step 11/11] I0413 11:19:11.244561 32176 hierarchical.cpp:1139] Performed allocation for 0 agents in 184758ns
[11:19:12]W: [Step 11/11] I0413 11:19:12.245858 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:12]W: [Step 11/11] I0413 11:19:12.245949 32177 hierarchical.cpp:1139] Performed allocation for 0 agents in 181579ns
[11:19:13]W: [Step 11/11] I0413 11:19:13.246592 32178 hierarchical.cpp:1488] No resources available to allocate!
[11:19:13]W: [Step 11/11] I0413 11:19:13.246691 32178 hierarchical.cpp:1139] Performed allocation for 0 agents in 224714ns
[11:19:14]W: [Step 11/11] I0413 11:19:14.247139 32174 hierarchical.cpp:1488] No resources available to allocate!
[11:19:14]W: [Step 11/11] I0413 11:19:14.247230 32174 hierarchical.cpp:1139] Performed allocation for 0 agents in 188089ns
[11:19:14]W: [Step 11/11] I0413 11:19:14.310032 32157 containerizer.cpp:159] Using isolation: docker/runtime,filesystem/linux
[11:19:14]W: [Step 11/11] I0413 11:19:14.317421 32157 linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
[11:19:14]W: [Step 11/11] E0413 11:19:14.322706 32157 shell.hpp:106] Command 'hadoop version 2>&1' failed; this is the output:
[11:19:14]W: [Step 11/11] sh: hadoop: command not found
[11:19:14]W: [Step 11/11] I0413 11:19:14.322770 32157 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
[11:19:14]W: [Step 11/11] I0413 11:19:14.322949 32157 local_puller.cpp:90] Creating local puller with docker registry '/tmp/8BsojJ/archives'
[11:19:14]W: [Step 11/11] I0413 11:19:14.325043 32157 linux.cpp:81] Making '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM' a shared mount
[11:19:14]W: [Step 11/11] I0413 11:19:14.335857 32173 slave.cpp:201] Agent started on 449)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.335898 32173 slave.cpp:202] 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/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="/tmp/8BsojJ/archives" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/8BsojJ/store" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/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_credentials="/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/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/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM"
[11:19:14]W: [Step 11/11] I0413 11:19:14.336303 32173 credentials.hpp:86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/credential'
[11:19:14]W: [Step 11/11] I0413 11:19:14.336511 32173 slave.cpp:339] Agent using credential for: test-principal
[11:19:14]W: [Step 11/11] I0413 11:19:14.336535 32173 credentials.hpp:37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/http_credentials'
[11:19:14]W: [Step 11/11] I0413 11:19:14.336756 32173 slave.cpp:391] Using default 'basic' HTTP authenticator
[11:19:14]W: [Step 11/11] I0413 11:19:14.337069 32173 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
[11:19:14]W: [Step 11/11] Trying semicolon-delimited string format instead
[11:19:14]W: [Step 11/11] I0413 11:19:14.337260 32157 sched.cpp:224] Version: 0.29.0
[11:19:14]W: [Step 11/11] I0413 11:19:14.337543 32173 slave.cpp:590] Agent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[11:19:14]W: [Step 11/11] I0413 11:19:14.337600 32173 slave.cpp:598] Agent attributes: [ ]
[11:19:14]W: [Step 11/11] I0413 11:19:14.337610 32173 slave.cpp:603] Agent hostname: ip-172-30-2-185.mesosphere.io
[11:19:14]W: [Step 11/11] I0413 11:19:14.337968 32178 sched.cpp:328] New master detected at master@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.338058 32178 sched.cpp:384] Authenticating with master master@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.338078 32178 sched.cpp:391] Using default CRAM-MD5 authenticatee
[11:19:14]W: [Step 11/11] I0413 11:19:14.338299 32174 authenticatee.cpp:121] Creating new client SASL connection
[11:19:14]W: [Step 11/11] I0413 11:19:14.338652 32178 master.cpp:5695] Authenticating scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.338753 32174 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(916)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.338944 32178 authenticator.cpp:98] Creating new server SASL connection
[11:19:14]W: [Step 11/11] I0413 11:19:14.339174 32177 state.cpp:57] Recovering state from '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/meta'
[11:19:14]W: [Step 11/11] I0413 11:19:14.339231 32176 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[11:19:14]W: [Step 11/11] I0413 11:19:14.339256 32176 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[11:19:14]W: [Step 11/11] I0413 11:19:14.339349 32173 authenticator.cpp:203] Received SASL authentication start
[11:19:14]W: [Step 11/11] I0413 11:19:14.339445 32173 authenticator.cpp:325] Authentication requires more steps
[11:19:14]W: [Step 11/11] I0413 11:19:14.339457 32174 status_update_manager.cpp:200] Recovering status update manager
[11:19:14]W: [Step 11/11] I0413 11:19:14.339526 32173 authenticatee.cpp:258] Received SASL authentication step
[11:19:14]W: [Step 11/11] I0413 11:19:14.339623 32173 authenticator.cpp:231] Received SASL authentication step
[11:19:14]W: [Step 11/11] I0413 11:19:14.339644 32173 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-185.mesosphere.io' server FQDN: 'ip-172-30-2-185.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
[11:19:14]W: [Step 11/11] I0413 11:19:14.339653 32173 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[11:19:14]W: [Step 11/11] I0413 11:19:14.339653 32176 containerizer.cpp:423] Recovering containerizer
[11:19:14]W: [Step 11/11] I0413 11:19:14.339696 32173 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[11:19:14]W: [Step 11/11] I0413 11:19:14.339726 32173 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-185.mesosphere.io' server FQDN: 'ip-172-30-2-185.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
[11:19:14]W: [Step 11/11] I0413 11:19:14.339735 32173 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[11:19:14]W: [Step 11/11] I0413 11:19:14.339740 32173 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[11:19:14]W: [Step 11/11] I0413 11:19:14.339751 32173 authenticator.cpp:317] Authentication success
[11:19:14]W: [Step 11/11] I0413 11:19:14.339843 32171 authenticatee.cpp:298] Authentication success
[11:19:14]W: [Step 11/11] I0413 11:19:14.339866 32172 master.cpp:5725] Successfully authenticated principal 'test-principal' at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.339905 32178 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(916)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.340154 32173 sched.cpp:474] Successfully authenticated with master master@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.340170 32173 sched.cpp:779] Sending SUBSCRIBE call to master@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.340262 32173 sched.cpp:812] Will retry registration in 828.650447ms if necessary
[11:19:14]W: [Step 11/11] I0413 11:19:14.340378 32175 master.cpp:2362] Received SUBSCRIBE call for framework 'default' at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.340432 32175 master.cpp:1871] Authorizing framework principal 'test-principal' to receive offers for role '*'
[11:19:14]W: [Step 11/11] I0413 11:19:14.340695 32175 master.cpp:2433] Subscribing framework default with checkpointing disabled and capabilities [ ]
[11:19:14]W: [Step 11/11] I0413 11:19:14.341214 32175 sched.cpp:706] Framework registered with 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:14]W: [Step 11/11] I0413 11:19:14.341259 32175 sched.cpp:720] Scheduler::registered took 20654ns
[11:19:14]W: [Step 11/11] I0413 11:19:14.341266 32172 hierarchical.cpp:264] Added framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:14]W: [Step 11/11] I0413 11:19:14.341372 32172 hierarchical.cpp:1488] No resources available to allocate!
[11:19:14]W: [Step 11/11] I0413 11:19:14.341403 32172 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:14]W: [Step 11/11] I0413 11:19:14.341461 32172 hierarchical.cpp:1139] Performed allocation for 0 agents in 158635ns
[11:19:14]W: [Step 11/11] I0413 11:19:14.342557 32173 metadata_manager.cpp:192] No images to load from disk. Docker provisioner image storage path '/tmp/8BsojJ/store/storedImages' does not exist
[11:19:14]W: [Step 11/11] I0413 11:19:14.342850 32172 provisioner.cpp:245] Provisioner recovery complete
[11:19:14]W: [Step 11/11] I0413 11:19:14.343174 32177 slave.cpp:4786] Finished recovery
[11:19:14]W: [Step 11/11] I0413 11:19:14.343546 32177 slave.cpp:4958] Querying resource estimator for oversubscribable resources
[11:19:14]W: [Step 11/11] I0413 11:19:14.343785 32175 slave.cpp:941] New master detected at master@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.343788 32173 status_update_manager.cpp:174] Pausing sending status updates
[11:19:14]W: [Step 11/11] I0413 11:19:14.343852 32175 slave.cpp:1004] Authenticating with master master@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.343868 32175 slave.cpp:1009] Using default CRAM-MD5 authenticatee
[11:19:14]W: [Step 11/11] I0413 11:19:14.343988 32175 slave.cpp:977] Detecting new master
[11:19:14]W: [Step 11/11] I0413 11:19:14.344041 32171 authenticatee.cpp:121] Creating new client SASL connection
[11:19:14]W: [Step 11/11] I0413 11:19:14.344113 32175 slave.cpp:4972] Received oversubscribable resources from the resource estimator
[11:19:14]W: [Step 11/11] I0413 11:19:14.344358 32176 master.cpp:5695] Authenticating slave(449)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.344466 32178 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(917)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.344679 32174 authenticator.cpp:98] Creating new server SASL connection
[11:19:14]W: [Step 11/11] I0413 11:19:14.344933 32171 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[11:19:14]W: [Step 11/11] I0413 11:19:14.344952 32171 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[11:19:14]W: [Step 11/11] I0413 11:19:14.345036 32171 authenticator.cpp:203] Received SASL authentication start
[11:19:14]W: [Step 11/11] I0413 11:19:14.345079 32171 authenticator.cpp:325] Authentication requires more steps
[11:19:14]W: [Step 11/11] I0413 11:19:14.345155 32171 authenticatee.cpp:258] Received SASL authentication step
[11:19:14]W: [Step 11/11] I0413 11:19:14.345266 32171 authenticator.cpp:231] Received SASL authentication step
[11:19:14]W: [Step 11/11] I0413 11:19:14.345300 32171 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-185.mesosphere.io' server FQDN: 'ip-172-30-2-185.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
[11:19:14]W: [Step 11/11] I0413 11:19:14.345312 32171 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[11:19:14]W: [Step 11/11] I0413 11:19:14.345355 32171 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[11:19:14]W: [Step 11/11] I0413 11:19:14.345376 32171 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-185.mesosphere.io' server FQDN: 'ip-172-30-2-185.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
[11:19:14]W: [Step 11/11] I0413 11:19:14.345386 32171 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[11:19:14]W: [Step 11/11] I0413 11:19:14.345391 32171 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[11:19:14]W: [Step 11/11] I0413 11:19:14.345401 32171 authenticator.cpp:317] Authentication success
[11:19:14]W: [Step 11/11] I0413 11:19:14.345470 32176 authenticatee.cpp:298] Authentication success
[11:19:14]W: [Step 11/11] I0413 11:19:14.345515 32174 master.cpp:5725] Successfully authenticated principal 'test-principal' at slave(449)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.345564 32178 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(917)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.345804 32173 slave.cpp:1074] Successfully authenticated with master master@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.345926 32173 slave.cpp:1470] Will retry registration in 10.899804ms if necessary
[11:19:14]W: [Step 11/11] I0413 11:19:14.346091 32175 master.cpp:4406] Registering agent at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io) with id 6cc0332e-c8aa-4649-b347-fd20899bed17-S0
[11:19:14]W: [Step 11/11] I0413 11:19:14.346500 32174 registrar.cpp:463] Applied 1 operations in 64746ns; attempting to update the 'registry'
[11:19:14]W: [Step 11/11] I0413 11:19:14.347363 32175 log.cpp:683] Attempting to append 396 bytes to the log
[11:19:14]W: [Step 11/11] I0413 11:19:14.347477 32171 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
[11:19:14]W: [Step 11/11] I0413 11:19:14.348143 32174 replica.cpp:537] Replica received write request for position 3 from (16544)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.357599 32171 slave.cpp:1470] Will retry registration in 5.442025ms if necessary
[11:19:14]W: [Step 11/11] I0413 11:19:14.357764 32172 master.cpp:4394] Ignoring register agent message from slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io) as admission is already in progress
[11:19:14]W: [Step 11/11] I0413 11:19:14.364148 32178 slave.cpp:1470] Will retry registration in 16.051902ms if necessary
[11:19:14]W: [Step 11/11] I0413 11:19:14.364310 32177 master.cpp:4394] Ignoring register agent message from slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io) as admission is already in progress
[11:19:14]W: [Step 11/11] I0413 11:19:14.380800 32175 slave.cpp:1470] Will retry registration in 91.784594ms if necessary
[11:19:14]W: [Step 11/11] I0413 11:19:14.380957 32176 master.cpp:4394] Ignoring register agent message from slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io) as admission is already in progress
[11:19:14]W: [Step 11/11] I0413 11:19:14.425426 32174 leveldb.cpp:341] Persisting action (415 bytes) to leveldb took 77.234362ms
[11:19:14]W: [Step 11/11] I0413 11:19:14.425495 32174 replica.cpp:712] Persisted action at 3
[11:19:14]W: [Step 11/11] I0413 11:19:14.426288 32176 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
[11:19:14]W: [Step 11/11] I0413 11:19:14.434526 32176 leveldb.cpp:341] Persisting action (417 bytes) to leveldb took 8.204085ms
[11:19:14]W: [Step 11/11] I0413 11:19:14.434558 32176 replica.cpp:712] Persisted action at 3
[11:19:14]W: [Step 11/11] I0413 11:19:14.434577 32176 replica.cpp:697] Replica learned APPEND action at position 3
[11:19:14]W: [Step 11/11] I0413 11:19:14.436028 32175 registrar.cpp:508] Successfully updated the 'registry' in 89.45792ms
[11:19:14]W: [Step 11/11] I0413 11:19:14.436228 32171 log.cpp:702] Attempting to truncate the log to 3
[11:19:14]W: [Step 11/11] I0413 11:19:14.436338 32177 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
[11:19:14]W: [Step 11/11] I0413 11:19:14.436774 32178 slave.cpp:3677] Received ping from slave-observer(417)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.436921 32174 master.cpp:4474] Registered agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
[11:19:14]W: [Step 11/11] I0413 11:19:14.436997 32175 slave.cpp:1118] Registered with master master@172.30.2.185:48536; given agent ID 6cc0332e-c8aa-4649-b347-fd20899bed17-S0
[11:19:14]W: [Step 11/11] I0413 11:19:14.437024 32175 fetcher.cpp:81] Clearing fetcher cache
[11:19:14]W: [Step 11/11] I0413 11:19:14.437080 32177 replica.cpp:537] Replica received write request for position 4 from (16545)@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.437161 32174 status_update_manager.cpp:181] Resuming sending status updates
[11:19:14]W: [Step 11/11] I0413 11:19:14.437151 32173 hierarchical.cpp:473] Added agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 (ip-172-30-2-185.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
[11:19:14]W: [Step 11/11] I0413 11:19:14.437347 32175 slave.cpp:1141] Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/meta/slaves/6cc0332e-c8aa-4649-b347-fd20899bed17-S0/slave.info'
[11:19:14]W: [Step 11/11] I0413 11:19:14.437572 32175 slave.cpp:1178] Forwarding total oversubscribed resources
[11:19:14]W: [Step 11/11] I0413 11:19:14.437710 32175 master.cpp:4818] Received update of agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io) with total oversubscribed resources
[11:19:14]W: [Step 11/11] I0413 11:19:14.437898 32173 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:14]W: [Step 11/11] I0413 11:19:14.437965 32173 hierarchical.cpp:1162] Performed allocation for agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 in 768158ns
[11:19:14]W: [Step 11/11] I0413 11:19:14.438221 32173 hierarchical.cpp:531] Agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 (ip-172-30-2-185.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])
[11:19:14]W: [Step 11/11] I0413 11:19:14.438324 32177 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.211988ms
[11:19:14]W: [Step 11/11] I0413 11:19:14.438346 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:14]W: [Step 11/11] I0413 11:19:14.438352 32172 master.cpp:5524] Sending 1 offers to framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (default) at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.438375 32173 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:14]W: [Step 11/11] I0413 11:19:14.438369 32177 replica.cpp:712] Persisted action at 4
[11:19:14]W: [Step 11/11] I0413 11:19:14.438415 32173 hierarchical.cpp:1162] Performed allocation for agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 in 162949ns
[11:19:14]W: [Step 11/11] I0413 11:19:14.438875 32171 sched.cpp:876] Scheduler::resourceOffers took 165827ns
[11:19:14]W: [Step 11/11] I0413 11:19:14.438922 32173 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
[11:19:14]W: [Step 11/11] I0413 11:19:14.439180 32157 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:128
[11:19:14]W: [Step 11/11] Trying semicolon-delimited string format instead
[11:19:14]W: [Step 11/11] I0413 11:19:14.439565 32173 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 616493ns
[11:19:14]W: [Step 11/11] I0413 11:19:14.439633 32173 leveldb.cpp:399] Deleting ~2 keys from leveldb took 45616ns
[11:19:14]W: [Step 11/11] I0413 11:19:14.439657 32173 replica.cpp:712] Persisted action at 4
[11:19:14]W: [Step 11/11] I0413 11:19:14.439679 32173 replica.cpp:697] Replica learned TRUNCATE action at position 4
[11:19:14]W: [Step 11/11] I0413 11:19:14.440459 32178 master.cpp:3304] Processing ACCEPT call for offers: [ 6cc0332e-c8aa-4649-b347-fd20899bed17-O0 ] on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io) for framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (default) at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536
[11:19:14]W: [Step 11/11] I0413 11:19:14.440496 32178 master.cpp:2907] Authorizing framework principal 'test-principal' to launch task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 as user 'root'
[11:19:14]W: [Step 11/11] I0413 11:19:14.441710 32173 master.hpp:177] Adding task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 with resources cpus(*):1; mem(*):128 on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 (ip-172-30-2-185.mesosphere.io)
[11:19:14]W: [Step 11/11] I0413 11:19:14.441797 32173 master.cpp:3789] Launching task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (default) at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536 with resources cpus(*):1; mem(*):128 on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io)
[11:19:14]W: [Step 11/11] I0413 11:19:14.442081 32174 slave.cpp:1510] Got assigned task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 for framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:14]W: [Step 11/11] I0413 11:19:14.442245 32174 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[11:19:14]W: [Step 11/11] Trying semicolon-delimited string format instead
[11:19:14]W: [Step 11/11] I0413 11:19:14.442361 32171 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 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 from framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:14]W: [Step 11/11] I0413 11:19:14.442404 32171 hierarchical.cpp:928] Framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 filtered agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 for 5secs
[11:19:14]W: [Step 11/11] I0413 11:19:14.442673 32174 slave.cpp:1629] Launching task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 for framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:14]W: [Step 11/11] I0413 11:19:14.442742 32174 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[11:19:14]W: [Step 11/11] Trying semicolon-delimited string format instead
[11:19:14]W: [Step 11/11] I0413 11:19:14.443244 32174 paths.cpp:528] Trying to chown '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/slaves/6cc0332e-c8aa-4649-b347-fd20899bed17-S0/frameworks/6cc0332e-c8aa-4649-b347-fd20899bed17-0000/executors/e0e9a03f-3d39-49e3-8815-04ebdb8f27a4/runs/64db7716-2750-4e3a-a4ee-a5d2d3773a7c' to user 'root'
[11:19:14]W: [Step 11/11] I0413 11:19:14.448338 32174 slave.cpp:5606] Launching executor e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/slaves/6cc0332e-c8aa-4649-b347-fd20899bed17-S0/frameworks/6cc0332e-c8aa-4649-b347-fd20899bed17-0000/executors/e0e9a03f-3d39-49e3-8815-04ebdb8f27a4/runs/64db7716-2750-4e3a-a4ee-a5d2d3773a7c'
[11:19:14]W: [Step 11/11] I0413 11:19:14.448930 32172 containerizer.cpp:682] Starting container '64db7716-2750-4e3a-a4ee-a5d2d3773a7c' for executor 'e0e9a03f-3d39-49e3-8815-04ebdb8f27a4' of framework '6cc0332e-c8aa-4649-b347-fd20899bed17-0000'
[11:19:14]W: [Step 11/11] I0413 11:19:14.448937 32174 slave.cpp:1847] Queuing task 'e0e9a03f-3d39-49e3-8815-04ebdb8f27a4' for executor 'e0e9a03f-3d39-49e3-8815-04ebdb8f27a4' of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:14]W: [Step 11/11] I0413 11:19:14.449035 32174 slave.cpp:894] Successfully attached file '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/slaves/6cc0332e-c8aa-4649-b347-fd20899bed17-S0/frameworks/6cc0332e-c8aa-4649-b347-fd20899bed17-0000/executors/e0e9a03f-3d39-49e3-8815-04ebdb8f27a4/runs/64db7716-2750-4e3a-a4ee-a5d2d3773a7c'
[11:19:14]W: [Step 11/11] I0413 11:19:14.449573 32178 metadata_manager.cpp:159] Looking for image 'alpine'
[11:19:14]W: [Step 11/11] I0413 11:19:14.450001 32171 local_puller.cpp:142] Untarring image 'alpine' from '/tmp/8BsojJ/archives/alpine.tar' to '/tmp/8BsojJ/store/staging/5uPLLX'
[11:19:15]W: [Step 11/11] I0413 11:19:15.248986 32174 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 for framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:15]W: [Step 11/11] I0413 11:19:15.249073 32174 hierarchical.cpp:1488] No resources available to allocate!
[11:19:15]W: [Step 11/11] I0413 11:19:15.249109 32174 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:15]W: [Step 11/11] I0413 11:19:15.249181 32174 hierarchical.cpp:1139] Performed allocation for 1 agents in 756071ns
[11:19:15]W: [Step 11/11] I0413 11:19:15.491052 32177 local_puller.cpp:162] The repositories JSON file for image 'alpine' is '{"alpine":{"latest":"815b809d588c80fd6ddf4d6ac244ad1c01ae4cbe0f91cc7480e306671ee9c346"}}'
[11:19:15]W: [Step 11/11] I0413 11:19:15.491544 32177 local_puller.cpp:290] Extracting layer tar ball '/tmp/8BsojJ/store/staging/5uPLLX/815b809d588c80fd6ddf4d6ac244ad1c01ae4cbe0f91cc7480e306671ee9c346/layer.tar to rootfs '/tmp/8BsojJ/store/staging/5uPLLX/815b809d588c80fd6ddf4d6ac244ad1c01ae4cbe0f91cc7480e306671ee9c346/rootfs'
[11:19:16]W: [Step 11/11] I0413 11:19:16.250809 32177 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 for framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:17]W: [Step 11/11] I0413 11:19:16.250892 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:17]W: [Step 11/11] I0413 11:19:16.250927 32177 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:17]W: [Step 11/11] I0413 11:19:16.250999 32177 hierarchical.cpp:1139] Performed allocation for 1 agents in 761954ns
[11:19:19]W: [Step 11/11] I0413 11:19:17.252462 32171 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 for framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:22]W: [Step 11/11] I0413 11:19:17.252532 32171 hierarchical.cpp:1488] No resources available to allocate!
[11:19:22]W: [Step 11/11] I0413 11:19:17.252565 32171 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:22]W: [Step 11/11] I0413 11:19:17.252629 32171 hierarchical.cpp:1139] Performed allocation for 1 agents in 749868ns
[11:19:22]W: [Step 11/11] I0413 11:19:18.253867 32173 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 for framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:22]W: [Step 11/11] I0413 11:19:18.253939 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:22]W: [Step 11/11] I0413 11:19:18.253973 32173 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:22]W: [Step 11/11] I0413 11:19:18.254036 32173 hierarchical.cpp:1139] Performed allocation for 1 agents in 758913ns
[11:19:22]W: [Step 11/11] I0413 11:19:19.255507 32176 hierarchical.cpp:1674] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 for framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:22]W: [Step 11/11] I0413 11:19:19.255578 32176 hierarchical.cpp:1488] No resources available to allocate!
[11:19:22]W: [Step 11/11] I0413 11:19:19.255611 32176 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:22]W: [Step 11/11] I0413 11:19:19.255676 32176 hierarchical.cpp:1139] Performed allocation for 1 agents in 744744ns
[11:19:22]W: [Step 11/11] I0413 11:19:20.256892 32173 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:22]W: [Step 11/11] I0413 11:19:20.256988 32173 hierarchical.cpp:1139] Performed allocation for 1 agents in 889256ns
[11:19:22]W: [Step 11/11] I0413 11:19:20.257236 32174 master.cpp:5524] Sending 1 offers to framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (default) at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536
[11:19:22]W: [Step 11/11] I0413 11:19:20.257618 32177 sched.cpp:876] Scheduler::resourceOffers took 23381ns
[11:19:22]W: [Step 11/11] I0413 11:19:21.257756 32171 hierarchical.cpp:1488] No resources available to allocate!
[11:19:22]W: [Step 11/11] I0413 11:19:21.257819 32171 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:22]W: [Step 11/11] I0413 11:19:21.257887 32171 hierarchical.cpp:1139] Performed allocation for 1 agents in 338051ns
[11:19:22]W: [Step 11/11] I0413 11:19:22.259382 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:22]W: [Step 11/11] I0413 11:19:22.259443 32175 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:22]W: [Step 11/11] I0413 11:19:22.259507 32175 hierarchical.cpp:1139] Performed allocation for 1 agents in 354790ns
[11:19:23]W: [Step 11/11] I0413 11:19:23.260628 32176 hierarchical.cpp:1488] No resources available to allocate!
[11:19:23]W: [Step 11/11] I0413 11:19:23.260690 32176 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:23]W: [Step 11/11] I0413 11:19:23.260756 32176 hierarchical.cpp:1139] Performed allocation for 1 agents in 327434ns
[11:19:24]W: [Step 11/11] I0413 11:19:24.262153 32178 hierarchical.cpp:1488] No resources available to allocate!
[11:19:24]W: [Step 11/11] I0413 11:19:24.262218 32178 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:24]W: [Step 11/11] I0413 11:19:24.262308 32178 hierarchical.cpp:1139] Performed allocation for 1 agents in 374578ns
[11:19:25]W: [Step 11/11] I0413 11:19:25.263633 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:25]W: [Step 11/11] I0413 11:19:25.263692 32177 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:25]W: [Step 11/11] I0413 11:19:25.263757 32177 hierarchical.cpp:1139] Performed allocation for 1 agents in 330253ns
[11:19:26]W: [Step 11/11] I0413 11:19:26.265207 32171 hierarchical.cpp:1488] No resources available to allocate!
[11:19:26]W: [Step 11/11] I0413 11:19:26.265286 32171 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:26]W: [Step 11/11] I0413 11:19:26.265357 32171 hierarchical.cpp:1139] Performed allocation for 1 agents in 352019ns
[11:19:27]W: [Step 11/11] I0413 11:19:27.266607 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:27]W: [Step 11/11] I0413 11:19:27.266666 32175 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:27]W: [Step 11/11] I0413 11:19:27.266732 32175 hierarchical.cpp:1139] Performed allocation for 1 agents in 319281ns
[11:19:28]W: [Step 11/11] I0413 11:19:28.268013 32176 hierarchical.cpp:1488] No resources available to allocate!
[11:19:28]W: [Step 11/11] I0413 11:19:28.268074 32176 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:28]W: [Step 11/11] I0413 11:19:28.268139 32176 hierarchical.cpp:1139] Performed allocation for 1 agents in 321980ns
[11:19:29]W: [Step 11/11] I0413 11:19:29.268868 32172 hierarchical.cpp:1488] No resources available to allocate!
[11:19:29]W: [Step 11/11] I0413 11:19:29.268931 32172 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:29]W: [Step 11/11] I0413 11:19:29.268997 32172 hierarchical.cpp:1139] Performed allocation for 1 agents in 352937ns
[11:19:29]W: [Step 11/11] I0413 11:19:29.345216 32178 slave.cpp:4958] Querying resource estimator for oversubscribable resources
[11:19:29]W: [Step 11/11] I0413 11:19:29.345504 32173 slave.cpp:4972] Received oversubscribable resources from the resource estimator
[11:19:29]W: [Step 11/11] I0413 11:19:29.437883 32176 slave.cpp:3677] Received ping from slave-observer(417)@172.30.2.185:48536
[11:19:30]W: [Step 11/11] I0413 11:19:30.270481 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:30]W: [Step 11/11] I0413 11:19:30.270544 32173 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:30]W: [Step 11/11] I0413 11:19:30.270611 32173 hierarchical.cpp:1139] Performed allocation for 1 agents in 348248ns
[11:19:31]W: [Step 11/11] I0413 11:19:31.271857 32176 hierarchical.cpp:1488] No resources available to allocate!
[11:19:31]W: [Step 11/11] I0413 11:19:31.271917 32176 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:31]W: [Step 11/11] I0413 11:19:31.271982 32176 hierarchical.cpp:1139] Performed allocation for 1 agents in 335078ns
[11:19:32]W: [Step 11/11] I0413 11:19:32.272989 32178 hierarchical.cpp:1488] No resources available to allocate!
[11:19:32]W: [Step 11/11] I0413 11:19:32.273051 32178 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:32]W: [Step 11/11] I0413 11:19:32.273116 32178 hierarchical.cpp:1139] Performed allocation for 1 agents in 318291ns
[11:19:33]W: [Step 11/11] I0413 11:19:33.274336 32174 hierarchical.cpp:1488] No resources available to allocate!
[11:19:33]W: [Step 11/11] I0413 11:19:33.274399 32174 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:33]W: [Step 11/11] I0413 11:19:33.274466 32174 hierarchical.cpp:1139] Performed allocation for 1 agents in 341423ns
[11:19:34]W: [Step 11/11] I0413 11:19:34.275717 32171 hierarchical.cpp:1488] No resources available to allocate!
[11:19:34]W: [Step 11/11] I0413 11:19:34.275780 32171 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:34]W: [Step 11/11] I0413 11:19:34.275849 32171 hierarchical.cpp:1139] Performed allocation for 1 agents in 330658ns
[11:19:35]W: [Step 11/11] I0413 11:19:35.277062 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:35]W: [Step 11/11] I0413 11:19:35.277122 32175 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:35]W: [Step 11/11] I0413 11:19:35.277187 32175 hierarchical.cpp:1139] Performed allocation for 1 agents in 316077ns
[11:19:36]W: [Step 11/11] I0413 11:19:36.278585 32176 hierarchical.cpp:1488] No resources available to allocate!
[11:19:36]W: [Step 11/11] I0413 11:19:36.278646 32176 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:36]W: [Step 11/11] I0413 11:19:36.278712 32176 hierarchical.cpp:1139] Performed allocation for 1 agents in 319597ns
[11:19:37]W: [Step 11/11] I0413 11:19:37.280123 32172 hierarchical.cpp:1488] No resources available to allocate!
[11:19:37]W: [Step 11/11] I0413 11:19:37.280184 32172 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:37]W: [Step 11/11] I0413 11:19:37.280251 32172 hierarchical.cpp:1139] Performed allocation for 1 agents in 322723ns
[11:19:38]W: [Step 11/11] I0413 11:19:38.281677 32174 hierarchical.cpp:1488] No resources available to allocate!
[11:19:38]W: [Step 11/11] I0413 11:19:38.281740 32174 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:38]W: [Step 11/11] I0413 11:19:38.281805 32174 hierarchical.cpp:1139] Performed allocation for 1 agents in 317583ns
[11:19:39]W: [Step 11/11] I0413 11:19:39.283340 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:39]W: [Step 11/11] I0413 11:19:39.283402 32177 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:39]W: [Step 11/11] I0413 11:19:39.283469 32177 hierarchical.cpp:1139] Performed allocation for 1 agents in 346131ns
[11:19:40]W: [Step 11/11] I0413 11:19:40.284847 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:40]W: [Step 11/11] I0413 11:19:40.284906 32175 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:40]W: [Step 11/11] I0413 11:19:40.284973 32175 hierarchical.cpp:1139] Performed allocation for 1 agents in 326894ns
[11:19:41]W: [Step 11/11] I0413 11:19:41.286427 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:41]W: [Step 11/11] I0413 11:19:41.286487 32173 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:41]W: [Step 11/11] I0413 11:19:41.286551 32173 hierarchical.cpp:1139] Performed allocation for 1 agents in 338231ns
[11:19:42]W: [Step 11/11] I0413 11:19:42.287811 32171 hierarchical.cpp:1488] No resources available to allocate!
[11:19:42]W: [Step 11/11] I0413 11:19:42.287875 32171 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:42]W: [Step 11/11] I0413 11:19:42.287943 32171 hierarchical.cpp:1139] Performed allocation for 1 agents in 330408ns
[11:19:42]W: [Step 11/11] I0413 11:19:42.915001 32173 metadata_manager.cpp:148] Successfully cached image 'alpine'
[11:19:42]W: [Step 11/11] I0413 11:19:42.916044 32175 provisioner.cpp:285] Provisioning image rootfs '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/provisioner/containers/64db7716-2750-4e3a-a4ee-a5d2d3773a7c/backends/copy/rootfses/e5852056-f3b5-40a7-96ad-9fb73073f719' for container 64db7716-2750-4e3a-a4ee-a5d2d3773a7c
[11:19:42]W: [Step 11/11] I0413 11:19:42.916702 32174 copy.cpp:128] Copying layer path '/tmp/8BsojJ/store/layers/815b809d588c80fd6ddf4d6ac244ad1c01ae4cbe0f91cc7480e306671ee9c346/rootfs' to rootfs '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/provisioner/containers/64db7716-2750-4e3a-a4ee-a5d2d3773a7c/backends/copy/rootfses/e5852056-f3b5-40a7-96ad-9fb73073f719'
[11:19:43]W: [Step 11/11] I0413 11:19:43.289360 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:43]W: [Step 11/11] I0413 11:19:43.289441 32177 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:43]W: [Step 11/11] I0413 11:19:43.289516 32177 hierarchical.cpp:1139] Performed allocation for 1 agents in 413443ns
[11:19:44]W: [Step 11/11] I0413 11:19:44.290920 32174 hierarchical.cpp:1488] No resources available to allocate!
[11:19:44]W: [Step 11/11] I0413 11:19:44.290980 32174 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:44]W: [Step 11/11] I0413 11:19:44.291052 32174 hierarchical.cpp:1139] Performed allocation for 1 agents in 334160ns
[11:19:44]W: [Step 11/11] I0413 11:19:44.346406 32178 slave.cpp:4958] Querying resource estimator for oversubscribable resources
[11:19:44]W: [Step 11/11] I0413 11:19:44.346671 32178 slave.cpp:4972] Received oversubscribable resources from the resource estimator
[11:19:44]W: [Step 11/11] I0413 11:19:44.439091 32173 slave.cpp:3677] Received ping from slave-observer(417)@172.30.2.185:48536
[11:19:45]W: [Step 11/11] I0413 11:19:45.292065 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:45]W: [Step 11/11] I0413 11:19:45.292126 32173 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:45]W: [Step 11/11] I0413 11:19:45.292193 32173 hierarchical.cpp:1139] Performed allocation for 1 agents in 319505ns
[11:19:46]W: [Step 11/11] I0413 11:19:46.293602 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:46]W: [Step 11/11] I0413 11:19:46.293664 32177 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:46]W: [Step 11/11] I0413 11:19:46.293731 32177 hierarchical.cpp:1139] Performed allocation for 1 agents in 335770ns
[11:19:47]W: [Step 11/11] I0413 11:19:47.295181 32176 hierarchical.cpp:1488] No resources available to allocate!
[11:19:47]W: [Step 11/11] I0413 11:19:47.295243 32176 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:47]W: [Step 11/11] I0413 11:19:47.295336 32176 hierarchical.cpp:1139] Performed allocation for 1 agents in 367893ns
[11:19:48]W: [Step 11/11] I0413 11:19:48.076742 32175 linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWNS
[11:19:48]W: [Step 11/11] + /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer mount --help=false --operation=make-rslave --path=/
[11:19:48]W: [Step 11/11] + grep -E /mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/.+ /proc/self/mountinfo
[11:19:48]W: [Step 11/11] + grep -v 64db7716-2750-4e3a-a4ee-a5d2d3773a7c
[11:19:48]W: [Step 11/11] + cut '-d ' -f5
[11:19:48]W: [Step 11/11] + xargs --no-run-if-empty umount -l
[11:19:48]W: [Step 11/11] + mount -n --rbind /mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/provisioner/containers/64db7716-2750-4e3a-a4ee-a5d2d3773a7c/backends/copy/rootfses/e5852056-f3b5-40a7-96ad-9fb73073f719 /mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/slaves/6cc0332e-c8aa-4649-b347-fd20899bed17-S0/frameworks/6cc0332e-c8aa-4649-b347-fd20899bed17-0000/executors/e0e9a03f-3d39-49e3-8815-04ebdb8f27a4/runs/64db7716-2750-4e3a-a4ee-a5d2d3773a7c/.rootfs
[11:19:48]W: [Step 11/11] WARNING: Logging before InitGoogleLogging() is written to STDERR
[11:19:48]W: [Step 11/11] I0413 11:19:48.235680 15556 process.cpp:985] libprocess is initialized on 172.30.2.185:37787 with 8 worker threads
[11:19:48]W: [Step 11/11] I0413 11:19:48.236423 15556 logging.cpp:195] Logging to STDERR
[11:19:48]W: [Step 11/11] I0413 11:19:48.237893 15556 exec.cpp:150] Version: 0.29.0
[11:19:48]W: [Step 11/11] I0413 11:19:48.244459 15603 exec.cpp:200] Executor started at: executor(1)@172.30.2.185:37787 with pid 15556
[11:19:48]W: [Step 11/11] I0413 11:19:48.246498 32173 slave.cpp:2838] Got registration for executor 'e0e9a03f-3d39-49e3-8815-04ebdb8f27a4' of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 from executor(1)@172.30.2.185:37787
[11:19:48]W: [Step 11/11] I0413 11:19:48.248229 32177 slave.cpp:2012] Sending queued task 'e0e9a03f-3d39-49e3-8815-04ebdb8f27a4' to executor 'e0e9a03f-3d39-49e3-8815-04ebdb8f27a4' of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 at executor(1)@172.30.2.185:37787
[11:19:48]W: [Step 11/11] I0413 11:19:48.248355 15607 exec.cpp:225] Executor registered on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0
[11:19:48]W: [Step 11/11] I0413 11:19:48.249754 15607 exec.cpp:237] Executor::registered took 299676ns
[11:19:48] : [Step 11/11] Registered executor on ip-172-30-2-185.mesosphere.io
[11:19:48]W: [Step 11/11] I0413 11:19:48.250011 15607 exec.cpp:312] Executor asked to run task 'e0e9a03f-3d39-49e3-8815-04ebdb8f27a4'
[11:19:48]W: [Step 11/11] I0413 11:19:48.250108 15607 exec.cpp:321] Executor::launchTask took 79657ns
[11:19:48] : [Step 11/11] Starting task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4
[11:19:48] : [Step 11/11] Forked command at 15611
[11:19:48]W: [Step 11/11] I0413 11:19:48.253438 15607 exec.cpp:535] Executor sending status update TASK_RUNNING (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.254658 32174 slave.cpp:3197] Handling status update TASK_RUNNING (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 from executor(1)@172.30.2.185:37787
[11:19:48] : [Step 11/11] sh -c 'ls -al /'
[11:19:48]W: [Step 11/11] I0413 11:19:48.255951 32178 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.255990 32178 status_update_manager.cpp:497] Creating StatusUpdate stream for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.256407 32178 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 to the agent
[11:19:48]W: [Step 11/11] I0413 11:19:48.256623 32177 slave.cpp:3595] Forwarding the update TASK_RUNNING (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 to master@172.30.2.185:48536
[11:19:48]W: [Step 11/11] I0413 11:19:48.256793 32177 slave.cpp:3489] Status update manager successfully handled status update TASK_RUNNING (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.256835 32177 slave.cpp:3505] Sending acknowledgement for status update TASK_RUNNING (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 to executor(1)@172.30.2.185:37787
[11:19:48]W: [Step 11/11] I0413 11:19:48.256956 32176 master.cpp:4963] Status update TASK_RUNNING (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 from agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io)
[11:19:48]W: [Step 11/11] I0413 11:19:48.256989 32176 master.cpp:5011] Forwarding status update TASK_RUNNING (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.257128 32176 master.cpp:6624] Updating the state of task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
[11:19:48]W: [Step 11/11] I0413 11:19:48.257315 32173 sched.cpp:984] Scheduler::statusUpdate took 114851ns
[11:19:48]W: [Step 11/11] I0413 11:19:48.257541 15602 exec.cpp:358] Executor received status update acknowledgement 4b8a6835-2b19-4d02-96fb-66326ed69b9b for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.257650 32173 master.cpp:4118] Processing ACKNOWLEDGE call 4b8a6835-2b19-4d02-96fb-66326ed69b9b for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (default) at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536 on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0
[11:19:48]W: [Step 11/11] I0413 11:19:48.258005 32178 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.258244 32177 slave.cpp:2607] Status update manager successfully handled status update acknowledgement (UUID: 4b8a6835-2b19-4d02-96fb-66326ed69b9b) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48] : [Step 11/11] total 24
[11:19:48] : [Step 11/11] drwxr-xr-x. 9 root root 4096 Apr 13 11:19 .
[11:19:48] : [Step 11/11] drwxr-xr-x. 9 root root 4096 Apr 13 11:19 ..
[11:19:48] : [Step 11/11] lrwxrwxrwx. 1 root root 7 Apr 13 11:18 bin -> usr/bin
[11:19:48] : [Step 11/11] drwxr-xr-x. 4 root root 280 Apr 13 11:19 dev
[11:19:48] : [Step 11/11] drwxr-xr-x. 88 root root 4096 Apr 13 11:18 etc
[11:19:48] : [Step 11/11] lrwxrwxrwx. 1 root root 7 Apr 13 11:18 lib -> usr/lib
[11:19:48] : [Step 11/11] lrwxrwxrwx. 1 root root 9 Apr 13 11:18 lib64 -> usr/lib64
[11:19:48] : [Step 11/11] drwxr-xr-x. 3 root root 4096 Apr 13 11:19 mnt
[11:19:48] : [Step 11/11] dr-xr-xr-x. 188 root root 0 Apr 13 10:47 proc
[11:19:48] : [Step 11/11] dr-xr-xr-x. 13 root root 0 Apr 13 10:47 sys
[11:19:48] : [Step 11/11] drwxr-xr-x. 2 root root 4096 Apr 13 11:18 tmp
[11:19:48] : [Step 11/11] drwxr-xr-x. 5 root root 4096 Apr 13 11:18 usr
[11:19:48]W: [Step 11/11] I0413 11:19:48.296083 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:48]W: [Step 11/11] I0413 11:19:48.296144 32173 hierarchical.cpp:1583] No inverse offers to send out!
[11:19:48]W: [Step 11/11] I0413 11:19:48.296214 32173 hierarchical.cpp:1139] Performed allocation for 1 agents in 340038ns
[11:19:48] : [Step 11/11] Command exited with status 0 (pid: 15611)
[11:19:48]W: [Step 11/11] I0413 11:19:48.355677 15603 exec.cpp:535] Executor sending status update TASK_FINISHED (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.356652 32171 slave.cpp:3197] Handling status update TASK_FINISHED (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 from executor(1)@172.30.2.185:37787
[11:19:48]W: [Step 11/11] I0413 11:19:48.357671 32174 slave.cpp:5916] Terminating task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4
[11:19:48]W: [Step 11/11] I0413 11:19:48.358654 32172 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.358813 32172 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 to the agent
[11:19:48]W: [Step 11/11] I0413 11:19:48.359033 32171 slave.cpp:3595] Forwarding the update TASK_FINISHED (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 to master@172.30.2.185:48536
[11:19:48]W: [Step 11/11] I0413 11:19:48.359236 32171 slave.cpp:3489] Status update manager successfully handled status update TASK_FINISHED (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.359284 32171 slave.cpp:3505] Sending acknowledgement for status update TASK_FINISHED (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 to executor(1)@172.30.2.185:37787
[11:19:48]W: [Step 11/11] I0413 11:19:48.359356 32176 master.cpp:4963] Status update TASK_FINISHED (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 from agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io)
[11:19:48]W: [Step 11/11] I0413 11:19:48.359390 32176 master.cpp:5011] Forwarding status update TASK_FINISHED (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.359527 32176 master.cpp:6624] Updating the state of task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
[11:19:48]W: [Step 11/11] I0413 11:19:48.359791 32178 sched.cpp:984] Scheduler::statusUpdate took 134379ns
[11:19:48]W: [Step 11/11] I0413 11:19:48.359853 32171 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):128 (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000]) on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 from framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.360016 15606 exec.cpp:358] Executor received status update acknowledgement 51ed067a-7f68-4168-8082-551a3c0d6212 for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.360075 32173 master.cpp:4118] Processing ACKNOWLEDGE call 51ed067a-7f68-4168-8082-551a3c0d6212 for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (default) at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536 on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0
[11:19:48]W: [Step 11/11] I0413 11:19:48.360131 32157 sched.cpp:1907] Asked to stop the driver
[11:19:48]W: [Step 11/11] I0413 11:19:48.360126 32173 master.cpp:6690] Removing task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 with resources cpus(*):1; mem(*):128 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io)
[11:19:48]W: [Step 11/11] I0413 11:19:48.360234 32175 sched.cpp:1146] Stopping framework '6cc0332e-c8aa-4649-b347-fd20899bed17-0000'
[11:19:48]W: [Step 11/11] I0413 11:19:48.360487 32173 master.cpp:6097] Processing TEARDOWN call for framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (default) at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536
[11:19:48]W: [Step 11/11] I0413 11:19:48.360517 32173 master.cpp:6109] Removing framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 (default) at scheduler-fffa3f42-c007-4135-b30c-e2ea4a6d18dc@172.30.2.185:48536
[11:19:48]W: [Step 11/11] I0413 11:19:48.360633 32176 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.360687 32174 hierarchical.cpp:375] Deactivated framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.360721 32171 slave.cpp:2228] Asked to shut down framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 by master@172.30.2.185:48536
[11:19:48]W: [Step 11/11] I0413 11:19:48.360756 32171 slave.cpp:2253] Shutting down framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.360818 32176 status_update_manager.cpp:528] Cleaning up status update stream for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.360821 32171 slave.cpp:4411] Shutting down executor 'e0e9a03f-3d39-49e3-8815-04ebdb8f27a4' of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 at executor(1)@172.30.2.185:37787
[11:19:48]W: [Step 11/11] I0413 11:19:48.361249 32175 slave.cpp:2607] Status update manager successfully handled status update acknowledgement (UUID: 51ed067a-7f68-4168-8082-551a3c0d6212) for task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4 of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.361315 32175 slave.cpp:5957] Completing task e0e9a03f-3d39-49e3-8815-04ebdb8f27a4
[11:19:48]W: [Step 11/11] I0413 11:19:48.361479 32174 hierarchical.cpp:891] Recovered cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 from framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.361636 32177 containerizer.cpp:1439] Destroying container '64db7716-2750-4e3a-a4ee-a5d2d3773a7c'
[11:19:48]W: [Step 11/11] I0413 11:19:48.361692 15604 exec.cpp:399] Executor asked to shutdown
[11:19:48]W: [Step 11/11] I0413 11:19:48.361737 32174 hierarchical.cpp:326] Removed framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000
[11:19:48]W: [Step 11/11] I0413 11:19:48.361812 15604 exec.cpp:414] Executor::shutdown took 15790ns
[11:19:48]W: [Step 11/11] I0413 11:19:48.361922 15604 exec.cpp:91] Scheduling shutdown of the executor in 5secs
[11:19:48]W: [Step 11/11] I0413 11:19:48.364131 32171 cgroups.cpp:2676] Freezing cgroup /sys/fs/cgroup/freezer/mesos/64db7716-2750-4e3a-a4ee-a5d2d3773a7c
[11:19:48]W: [Step 11/11] I0413 11:19:48.366315 32173 cgroups.cpp:1409] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/64db7716-2750-4e3a-a4ee-a5d2d3773a7c after 2.132992ms
[11:19:48]W: [Step 11/11] I0413 11:19:48.368613 32177 cgroups.cpp:2694] Thawing cgroup /sys/fs/cgroup/freezer/mesos/64db7716-2750-4e3a-a4ee-a5d2d3773a7c
[11:19:48]W: [Step 11/11] I0413 11:19:48.370679 32177 cgroups.cpp:1438] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos/64db7716-2750-4e3a-a4ee-a5d2d3773a7c after 2.029056ms
[11:19:48]W: [Step 11/11] I0413 11:19:48.384817 32172 slave.cpp:3723] executor(1)@172.30.2.185:37787 exited
[11:19:48]W: [Step 11/11] I0413 11:19:48.474711 32172 containerizer.cpp:1674] Executor for container '64db7716-2750-4e3a-a4ee-a5d2d3773a7c' has exited
[11:19:48]W: [Step 11/11] I0413 11:19:48.477654 32175 linux.cpp:814] Ignoring unmounting sandbox/work directory for container 64db7716-2750-4e3a-a4ee-a5d2d3773a7c
[11:19:48]W: [Step 11/11] I0413 11:19:48.478108 32172 provisioner.cpp:338] Destroying container rootfs at '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_LocalPullerSimpleCommand_lJl2GM/provisioner/containers/64db7716-2750-4e3a-a4ee-a5d2d3773a7c/backends/copy/rootfses/e5852056-f3b5-40a7-96ad-9fb73073f719' for container 64db7716-2750-4e3a-a4ee-a5d2d3773a7c
[11:19:49]W: [Step 11/11] I0413 11:19:49.297487 32171 hierarchical.cpp:1488] No resources available to allocate!
[11:19:49]W: [Step 11/11] I0413 11:19:49.297590 32171 hierarchical.cpp:1139] Performed allocation for 1 agents in 338712ns
[11:19:50]W: [Step 11/11] I0413 11:19:50.298933 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:50]W: [Step 11/11] I0413 11:19:50.299026 32177 hierarchical.cpp:1139] Performed allocation for 1 agents in 291324ns
[11:19:51]W: [Step 11/11] I0413 11:19:51.299477 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:51]W: [Step 11/11] I0413 11:19:51.299568 32173 hierarchical.cpp:1139] Performed allocation for 1 agents in 274496ns
[11:19:52]W: [Step 11/11] I0413 11:19:52.301009 32178 hierarchical.cpp:1488] No resources available to allocate!
[11:19:52]W: [Step 11/11] I0413 11:19:52.301100 32178 hierarchical.cpp:1139] Performed allocation for 1 agents in 357990ns
[11:19:53]W: [Step 11/11] I0413 11:19:53.302446 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:53]W: [Step 11/11] I0413 11:19:53.302541 32175 hierarchical.cpp:1139] Performed allocation for 1 agents in 332300ns
[11:19:53]W: [Step 11/11] I0413 11:19:53.361649 32172 slave.cpp:4484] Killing executor 'e0e9a03f-3d39-49e3-8815-04ebdb8f27a4' of framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 at executor(1)@172.30.2.185:37787
[11:19:54]W: [Step 11/11] I0413 11:19:54.303851 32173 hierarchical.cpp:1488] No resources available to allocate!
[11:19:54]W: [Step 11/11] I0413 11:19:54.303942 32173 hierarchical.cpp:1139] Performed allocation for 1 agents in 269540ns
[11:19:55]W: [Step 11/11] I0413 11:19:55.305240 32172 hierarchical.cpp:1488] No resources available to allocate!
[11:19:55]W: [Step 11/11] I0413 11:19:55.305354 32172 hierarchical.cpp:1139] Performed allocation for 1 agents in 296775ns
[11:19:56]W: [Step 11/11] I0413 11:19:56.306686 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:19:56]W: [Step 11/11] I0413 11:19:56.306782 32175 hierarchical.cpp:1139] Performed allocation for 1 agents in 264591ns
[11:19:57]W: [Step 11/11] I0413 11:19:57.308100 32171 hierarchical.cpp:1488] No resources available to allocate!
[11:19:57]W: [Step 11/11] I0413 11:19:57.308192 32171 hierarchical.cpp:1139] Performed allocation for 1 agents in 269869ns
[11:19:58]W: [Step 11/11] I0413 11:19:58.308847 32177 hierarchical.cpp:1488] No resources available to allocate!
[11:19:58]W: [Step 11/11] I0413 11:19:58.308936 32177 hierarchical.cpp:1139] Performed allocation for 1 agents in 264484ns
[11:19:59]W: [Step 11/11] I0413 11:19:59.309675 32174 hierarchical.cpp:1488] No resources available to allocate!
[11:19:59]W: [Step 11/11] I0413 11:19:59.309768 32174 hierarchical.cpp:1139] Performed allocation for 1 agents in 294828ns
[11:19:59]W: [Step 11/11] I0413 11:19:59.347118 32172 slave.cpp:4958] Querying resource estimator for oversubscribable resources
[11:19:59]W: [Step 11/11] I0413 11:19:59.347367 32172 slave.cpp:4972] Received oversubscribable resources from the resource estimator
[11:19:59]W: [Step 11/11] I0413 11:19:59.439790 32175 slave.cpp:3677] Received ping from slave-observer(417)@172.30.2.185:48536
[11:20:00]W: [Step 11/11] I0413 11:20:00.310467 32178 hierarchical.cpp:1488] No resources available to allocate!
[11:20:00]W: [Step 11/11] I0413 11:20:00.310561 32178 hierarchical.cpp:1139] Performed allocation for 1 agents in 290213ns
[11:20:01]W: [Step 11/11] I0413 11:20:01.312059 32171 hierarchical.cpp:1488] No resources available to allocate!
[11:20:01]W: [Step 11/11] I0413 11:20:01.312150 32171 hierarchical.cpp:1139] Performed allocation for 1 agents in 285614ns
[11:20:02]W: [Step 11/11] I0413 11:20:02.313652 32172 hierarchical.cpp:1488] No resources available to allocate!
[11:20:02]W: [Step 11/11] I0413 11:20:02.313743 32172 hierarchical.cpp:1139] Performed allocation for 1 agents in 275636ns
[11:20:03]W: [Step 11/11] I0413 11:20:03.315335 32175 hierarchical.cpp:1488] No resources available to allocate!
[11:20:03]W: [Step 11/11] I0413 11:20:03.315425 32175 hierarchical.cpp:1139] Performed allocation for 1 agents in 299237ns
[11:20:03]W: [Step 11/11] I0413 11:20:03.363260 32174 slave.cpp:813] Agent terminating
[11:20:03]W: [Step 11/11] I0413 11:20:03.363358 32174 slave.cpp:2228] Asked to shut down framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 by @0.0.0.0:0
[11:20:03]W: [Step 11/11] W0413 11:20:03.363384 32174 slave.cpp:2249] Ignoring shutdown framework 6cc0332e-c8aa-4649-b347-fd20899bed17-0000 because it is terminating
[11:20:03]W: [Step 11/11] I0413 11:20:03.363592 32177 master.cpp:1236] Agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io) disconnected
[11:20:03]W: [Step 11/11] I0413 11:20:03.363618 32177 master.cpp:2717] Disconnecting agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io)
[11:20:03]W: [Step 11/11] I0413 11:20:03.363690 32177 master.cpp:2736] Deactivating agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 at slave(449)@172.30.2.185:48536 (ip-172-30-2-185.mesosphere.io)
[11:20:03]W: [Step 11/11] I0413 11:20:03.363814 32175 hierarchical.cpp:560] Agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0 deactivated
[11:20:03] : [Step 11/11] ../../src/tests/cluster.cpp:468: Failure
[11:20:03] : [Step 11/11] Failed to wait 15secs for wait
[11:20:03]W: [Step 11/11] I0413 11:20:03.368327 32157 master.cpp:1089] Master terminating
[11:20:03]W: [Step 11/11] I0413 11:20:03.368736 32173 hierarchical.cpp:505] Removed agent 6cc0332e-c8aa-4649-b347-fd20899bed17-S0
[11:20:11] : [Step 11/11] [ FAILED ] ProvisionerDockerPullerTest.ROOT_LocalPullerSimpleCommand (66969 ms)
Attachments
Issue Links
- is related to
-
-
- Resolved
-
- relates to
-
MESOS-4943 Reduce the size of LinuxRootfs in tests.
-
- Resolved
-