[ https://issues.apache.org/jira/browse/MESOS-5205?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15239548#comment-15239548 ]
Gilbert Song commented on MESOS-5205: ------------------------------------- Not 100% sure this flaky test is caused by MESOS-4943, but this kind of root tests which create a linux rootfs easily become flaky on centos 7, because the rootfs size of centos is almost double comparing to the others, which makes it slow. > ProvisionerDockerPullerTest.ROOT_LocalPullerSimpleCommand is flaky > ------------------------------------------------------------------ > > Key: MESOS-5205 > URL: https://issues.apache.org/jira/browse/MESOS-5205 > Project: Mesos > Issue Type: Bug > Environment: CenOS 7 with SSL > Reporter: Neil Conway > Labels: flaky, flaky-test, mesosphere > > Observed on internal Mesosphere CI. > {noformat} > [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) > {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)