Return-Path: X-Original-To: archive-asf-public-internal@cust-asf2.ponee.io Delivered-To: archive-asf-public-internal@cust-asf2.ponee.io Received: from cust-asf.ponee.io (cust-asf.ponee.io [163.172.22.183]) by cust-asf2.ponee.io (Postfix) with ESMTP id D2CA2200BE3 for ; Thu, 22 Dec 2016 13:13:01 +0100 (CET) Received: by cust-asf.ponee.io (Postfix) id D1861160B26; Thu, 22 Dec 2016 12:13:01 +0000 (UTC) Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by cust-asf.ponee.io (Postfix) with SMTP id D8EFD160B1F for ; Thu, 22 Dec 2016 13:12:59 +0100 (CET) Received: (qmail 71306 invoked by uid 500); 22 Dec 2016 12:12:59 -0000 Mailing-List: contact issues-help@mesos.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@mesos.apache.org Delivered-To: mailing list issues@mesos.apache.org Received: (qmail 71262 invoked by uid 99); 22 Dec 2016 12:12:59 -0000 Received: from arcas.apache.org (HELO arcas) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 22 Dec 2016 12:12:59 +0000 Received: from arcas.apache.org (localhost [127.0.0.1]) by arcas (Postfix) with ESMTP id CFD772C2A68 for ; Thu, 22 Dec 2016 12:12:58 +0000 (UTC) Date: Thu, 22 Dec 2016 12:12:58 +0000 (UTC) From: "Alexander Rukletsov (JIRA)" To: issues@mesos.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Updated] (MESOS-6002) The whiteout file cannot be removed correctly using aufs backend. MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 archived-at: Thu, 22 Dec 2016 12:13:02 -0000 [ https://issues.apache.org/jira/browse/MESOS-6002?page=3Dcom.atlassia= n.jira.plugin.system.issuetabpanels:all-tabpanel ] Alexander Rukletsov updated MESOS-6002: --------------------------------------- Fix Version/s: 1.2.0 > The whiteout file cannot be removed correctly using aufs backend. > ----------------------------------------------------------------- > > Key: MESOS-6002 > URL: https://issues.apache.org/jira/browse/MESOS-6002 > Project: Mesos > Issue Type: Bug > Components: containerization > Environment: Ubuntu 14, Ubuntu 12 > Or any os with aufs module > Reporter: Gilbert Song > Assignee: Qian Zhang > Labels: aufs, backend, containerizer > Fix For: 1.1.1, 1.2.0 > > Attachments: whiteout.diff > > > The whiteout file is not removed correctly when using the aufs backend in= unified containerizer. It can be verified by this unit test with the aufs = manually specified. > {noformat} > [20:11:24] :=09 [Step 10/10] [ RUN ] ProvisionerDockerPullerTest.ROO= T_INTERNET_CURL_Whiteout > [20:11:24]W:=09 [Step 10/10] I0805 20:11:24.986734 24295 cluster.cpp:155]= Creating default 'local' authorizer > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.001153 24295 leveldb.cpp:174]= Opened db in 14.308627ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.003731 24295 leveldb.cpp:181]= Compacted db in 2.558329ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.003749 24295 leveldb.cpp:196]= Created db iterator in 3086ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.003754 24295 leveldb.cpp:202]= Seeked to beginning of db in 595ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.003758 24295 leveldb.cpp:271]= Iterated through 0 keys in the db in 314ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.003769 24295 replica.cpp:776]= Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004086 24315 recover.cpp:451]= Starting replica recovery > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004251 24312 recover.cpp:477]= Replica is in EMPTY status > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004546 24314 replica.cpp:673]= Replica in EMPTY status received a broadcasted recover request from __req_= res__(5640)@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004607 24312 recover.cpp:197]= Received a recover response from a replica in EMPTY status > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004762 24313 recover.cpp:568]= Updating replica status to STARTING > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004776 24314 master.cpp:375] = Master 21665992-d47e-402f-a00c-6f8fab613019 (ip-172-30-2-105.mesosphere.io)= started on 172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004787 24314 master.cpp:377] = Flags at startup: --acls=3D"" --agent_ping_timeout=3D"15secs" --agent_rereg= ister_timeout=3D"10mins" --allocation_interval=3D"1secs" --allocator=3D"Hie= rarchicalDRF" --authenticate_agents=3D"true" --authenticate_frameworks=3D"t= rue" --authenticate_http_frameworks=3D"true" --authenticate_http_readonly= =3D"true" --authenticate_http_readwrite=3D"true" --authenticators=3D"crammd= 5" --authorizers=3D"local" --credentials=3D"/tmp/0z753P/credentials" --fram= ework_sorter=3D"drf" --help=3D"false" --hostname_lookup=3D"true" --http_aut= henticators=3D"basic" --http_framework_authenticators=3D"basic" --initializ= e_driver_logging=3D"true" --log_auto_initialize=3D"true" --logbufsecs=3D"0"= --logging_level=3D"INFO" --max_agent_ping_timeouts=3D"5" --max_completed_f= rameworks=3D"50" --max_completed_tasks_per_framework=3D"1000" --quiet=3D"fa= lse" --recovery_agent_removal_limit=3D"100%" --registry=3D"replicated_log" = --registry_fetch_timeout=3D"1mins" --registry_store_timeout=3D"100secs" --r= egistry_strict=3D"true" --root_submissions=3D"true" --user_sorter=3D"drf" -= -version=3D"false" --webui_dir=3D"/usr/local/share/mesos/webui" --work_dir= =3D"/tmp/0z753P/master" --zk_session_timeout=3D"10secs" > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004920 24314 master.cpp:427] = Master only allowing authenticated frameworks to register > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004930 24314 master.cpp:441] = Master only allowing authenticated agents to register > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004935 24314 master.cpp:454] = Master only allowing authenticated HTTP frameworks to register > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.004942 24314 credentials.hpp:= 37] Loading credentials for authentication from '/tmp/0z753P/credentials' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005018 24314 master.cpp:499] = Using default 'crammd5' authenticator > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005101 24314 http.cpp:883] Us= ing default 'basic' HTTP authenticator for realm 'mesos-master-readonly' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005152 24314 http.cpp:883] Us= ing default 'basic' HTTP authenticator for realm 'mesos-master-readwrite' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005192 24314 http.cpp:883] Us= ing default 'basic' HTTP authenticator for realm 'mesos-master-scheduler' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005230 24314 master.cpp:579] = Authorization enabled > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005297 24315 hierarchical.cpp= :151] Initialized hierarchical allocator process > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005312 24312 whitelist_watche= r.cpp:77] No whitelist given > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005820 24315 master.cpp:1851]= Elected as the leading master! > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005828 24315 master.cpp:1547]= Recovering from registrar > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.005889 24310 registrar.cpp:33= 2] Recovering registrar > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.006850 24311 leveldb.cpp:304]= Persisting metadata (8 bytes) to leveldb took 2.004066ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.006865 24311 replica.cpp:320]= Persisted replica status to STARTING > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.006913 24311 recover.cpp:477]= Replica is in STARTING status > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.007186 24310 replica.cpp:673]= Replica in STARTING status received a broadcasted recover request from __r= eq_res__(5641)@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.007289 24316 recover.cpp:197]= Received a recover response from a replica in STARTING status > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.007446 24315 recover.cpp:568]= Updating replica status to VOTING > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.009585 24309 leveldb.cpp:304]= Persisting metadata (8 bytes) to leveldb took 2.053694ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.009600 24309 replica.cpp:320]= Persisted replica status to VOTING > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.009632 24309 recover.cpp:582]= Successfully joined the Paxos group > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.009706 24309 recover.cpp:466]= Recover process terminated > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.009865 24313 log.cpp:553] Att= empting to start the writer > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.010295 24312 replica.cpp:493]= Replica received implicit promise request from __req_res__(5642)@172.30.2.= 105:36006 with proposal 1 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.012267 24312 leveldb.cpp:304]= Persisting metadata (8 bytes) to leveldb took 1.955683ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.012281 24312 replica.cpp:342]= Persisted promised to 1 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.012506 24311 coordinator.cpp:= 238] Coordinator attempting to fill missing positions > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.012964 24316 replica.cpp:388]= Replica received explicit promise request from __req_res__(5643)@172.30.2.= 105:36006 for position 0 with proposal 2 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.013638 24316 leveldb.cpp:341]= Persisting action (8 bytes) to leveldb took 654110ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.013651 24316 replica.cpp:708]= Persisted action NOP at position 0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.014034 24309 replica.cpp:537]= Replica received write request for position 0 from __req_res__(5644)@172.3= 0.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.014056 24309 leveldb.cpp:436]= Reading position from leveldb took 9338ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.016970 24309 leveldb.cpp:341]= Persisting action (14 bytes) to leveldb took 2.898601ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.016985 24309 replica.cpp:708]= Persisted action NOP at position 0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.017221 24311 replica.cpp:691]= Replica received learned notice for position 0 from @0.0.0.0:0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.019346 24311 leveldb.cpp:341]= Persisting action (16 bytes) to leveldb took 2.105458ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.019361 24311 replica.cpp:708]= Persisted action NOP at position 0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.019507 24313 log.cpp:569] Wri= ter started with ending position 0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.019839 24309 leveldb.cpp:436]= Reading position from leveldb took 10748ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.020036 24310 registrar.cpp:36= 5] Successfully fetched the registry (0B) in 14.12608ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.020072 24310 registrar.cpp:46= 4] Applied 1 operations in 3729ns; attempting to update the registry > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.020220 24313 log.cpp:577] Att= empting to append 209 bytes to the log > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.020277 24315 coordinator.cpp:= 348] Coordinator attempting to write APPEND action at position 1 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.020550 24311 replica.cpp:537]= Replica received write request for position 1 from __req_res__(5645)@172.3= 0.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.021132 24311 leveldb.cpp:341]= Persisting action (228 bytes) to leveldb took 565494ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.021144 24311 replica.cpp:708]= Persisted action APPEND at position 1 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.021389 24310 replica.cpp:691]= Replica received learned notice for position 1 from @0.0.0.0:0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.023318 24310 leveldb.cpp:341]= Persisting action (230 bytes) to leveldb took 1.911548ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.023332 24310 replica.cpp:708]= Persisted action APPEND at position 1 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.023541 24315 registrar.cpp:50= 9] Successfully updated the registry in 3.454976ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.023597 24315 registrar.cpp:39= 5] Successfully recovered registrar > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.023643 24313 log.cpp:596] Att= empting to truncate the log to 1 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.023706 24312 coordinator.cpp:= 348] Coordinator attempting to write TRUNCATE action at position 2 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.023710 24315 master.cpp:1655]= Recovered 0 agents from the registry (170B); allowing 10mins for agents to= re-register > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.023783 24310 hierarchical.cpp= :178] Skipping recovery of hierarchical allocator: nothing to recover > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.025234 24315 replica.cpp:537]= Replica received write request for position 2 from __req_res__(5646)@172.3= 0.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.027144 24315 leveldb.cpp:341]= Persisting action (16 bytes) to leveldb took 1.892058ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.027158 24315 replica.cpp:708]= Persisted action TRUNCATE at position 2 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.027400 24316 replica.cpp:691]= Replica received learned notice for position 2 from @0.0.0.0:0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.028108 24316 leveldb.cpp:341]= Persisting action (18 bytes) to leveldb took 692102ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.028131 24316 leveldb.cpp:399]= Deleting ~1 keys from leveldb took 10051ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.028139 24316 replica.cpp:708]= Persisted action TRUNCATE at position 2 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.029505 24295 containerizer.cp= p:200] Using isolation: docker/runtime,filesystem/linux,network/cni > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.032551 24295 linux_launcher.c= pp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux= launcher > [20:11:25]W:=09 [Step 10/10] E0805 20:11:25.035212 24295 shell.hpp:106] C= ommand 'hadoop version 2>&1' failed; this is the output: > [20:11:25]W:=09 [Step 10/10] sh: 1: hadoop: not found > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.035234 24295 fetcher.cpp:62] = 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 wa= s either not found or exited with a non-zero exit status: 127 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.035277 24295 registry_puller.= cpp:111] Creating registry puller with docker registry 'https://registry-1.= docker.io' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.036067 24295 linux.cpp:148] B= ind mounting '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_= INTERNET_CURL_Whiteout_Aqlqpf' and making it a shared mount > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.041409 24295 cluster.cpp:434]= Creating default 'local' authorizer > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.041822 24309 slave.cpp:198] M= esos agent started on (480)@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.041838 24309 slave.cpp:199] F= lags at startup: --acls=3D"" --appc_simple_discovery_uri_prefix=3D"http://"= --appc_store_dir=3D"/tmp/mesos/store/appc" --authenticate_http_readonly=3D= "true" --authenticate_http_readwrite=3D"true" --authenticatee=3D"crammd5" -= -authentication_backoff_factor=3D"1secs" --authorizer=3D"local" --cgroups_c= pu_enable_pids_and_tids_count=3D"false" --cgroups_enable_cfs=3D"false" --cg= roups_hierarchy=3D"/sys/fs/cgroup" --cgroups_limit_swap=3D"false" --cgroups= _root=3D"mesos" --container_disk_watch_interval=3D"15secs" --containerizers= =3D"mesos" --credential=3D"/mnt/teamcity/temp/buildTmp/ProvisionerDockerPul= lerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/credential" --default_role=3D"*"= --disk_watch_interval=3D"1mins" --docker=3D"docker" --docker_kill_orphans= =3D"true" --docker_registry=3D"https://registry-1.docker.io" --docker_remov= e_delay=3D"6hrs" --docker_socket=3D"/var/run/docker.sock" --docker_stop_tim= eout=3D"0ns" --docker_store_dir=3D"/tmp/mesos/store/docker" --docker_volume= _checkpoint_dir=3D"/var/run/mesos/isolators/docker/volume" --enforce_contai= ner_disk_quota=3D"false" --executor_registration_timeout=3D"1mins" --execut= or_shutdown_grace_period=3D"5secs" --fetcher_cache_dir=3D"/mnt/teamcity/tem= p/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/f= etch" --fetcher_cache_size=3D"2GB" --frameworks_home=3D"" --gc_delay=3D"1we= eks" --gc_disk_headroom=3D"0.1" --hadoop_home=3D"" --help=3D"false" --hostn= ame_lookup=3D"true" --http_authenticators=3D"basic" --http_command_executor= =3D"false" --http_credentials=3D"/mnt/teamcity/temp/buildTmp/ProvisionerDoc= kerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/http_credentials" --image_= providers=3D"docker" --initialize_driver_logging=3D"true" --isolation=3D"do= cker/runtime,filesystem/linux" --launcher_dir=3D"/mnt/teamcity/work/4240ba9= ddd0997c3/build/src" --logbufsecs=3D"0" --logging_level=3D"INFO" --oversubs= cribed_resources_interval=3D"15secs" --perf_duration=3D"10secs" --perf_inte= rval=3D"1mins" --qos_correction_interval_min=3D"0ns" --quiet=3D"false" --re= cover=3D"reconnect" --recovery_timeout=3D"15mins" --registration_backoff_fa= ctor=3D"10ms" --resources=3D"cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-= 32000]" --revocable_cpu_low_priority=3D"true" --sandbox_directory=3D"/mnt/m= esos/sandbox" --strict=3D"true" --switch_user=3D"true" --systemd_enable_sup= port=3D"true" --systemd_runtime_directory=3D"/run/systemd/system" --version= =3D"false" --work_dir=3D"/mnt/teamcity/temp/buildTmp/ProvisionerDockerPulle= rTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf" > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042037 24309 credentials.hpp:= 86] Loading credential for authentication from '/mnt/teamcity/temp/buildTmp= /ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/credential' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042135 24309 slave.cpp:336] A= gent using credential for: test-principal > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042145 24309 credentials.hpp:= 37] Loading credentials for authentication from '/mnt/teamcity/temp/buildTm= p/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/http_crede= ntials' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042207 24309 http.cpp:883] Us= ing default 'basic' HTTP authenticator for realm 'mesos-agent-readonly' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042326 24309 http.cpp:883] Us= ing default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042444 24295 sched.cpp:226] V= ersion: 1.1.0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042582 24313 sched.cpp:330] N= ew master detected at master@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042618 24313 sched.cpp:396] A= uthenticating with master master@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042628 24313 sched.cpp:403] U= sing default CRAM-MD5 authenticatee > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042681 24309 slave.cpp:519] A= gent resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000= ] > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042712 24309 slave.cpp:527] A= gent attributes: [ ] > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042721 24309 slave.cpp:532] A= gent hostname: ip-172-30-2-105.mesosphere.io > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.042774 24314 authenticatee.cp= p:121] Creating new client SASL connection > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043064 24309 state.cpp:57] Re= covering state from '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTes= t_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/meta' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043093 24315 master.cpp:5900]= Authenticating scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2.105= :36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043184 24311 authenticator.cp= p:414] Starting authentication session for crammd5-authenticatee(980)@172.3= 0.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043272 24316 status_update_ma= nager.cpp:203] Recovering status update manager > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043310 24309 authenticator.cp= p:98] Creating new server SASL connection > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043362 24313 containerizer.cp= p:527] Recovering containerizer > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043468 24309 authenticatee.cp= p:213] Received SASL authentication mechanisms: CRAM-MD5 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043488 24309 authenticatee.cp= p:239] Attempting to authenticate with mechanism 'CRAM-MD5' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043536 24309 authenticator.cp= p:204] Received SASL authentication start > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043567 24309 authenticator.cp= p:326] Authentication requires more steps > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043597 24309 authenticatee.cp= p:259] Received SASL authentication step > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043700 24312 authenticator.cp= p:232] Received SASL authentication step > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043716 24312 auxprop.cpp:109]= Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-= 2-105.mesosphere.io' server FQDN: 'ip-172-30-2-105.mesosphere.io' SASL_AUXP= ROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AU= THZID: false=20 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043721 24312 auxprop.cpp:181]= Looking up auxiliary property '*userPassword' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043730 24312 auxprop.cpp:181]= Looking up auxiliary property '*cmusaslsecretCRAM-MD5' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043735 24312 auxprop.cpp:109]= Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-= 2-105.mesosphere.io' server FQDN: 'ip-172-30-2-105.mesosphere.io' SASL_AUXP= ROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AU= THZID: true=20 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043740 24312 auxprop.cpp:131]= Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID =3D= =3D true > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043742 24312 auxprop.cpp:131]= Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AU= THZID =3D=3D true > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043751 24312 authenticator.cp= p:318] Authentication success > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043804 24311 authenticatee.cp= p:299] Authentication success > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043828 24316 authenticator.cp= p:432] Authentication session cleanup for crammd5-authenticatee(980)@172.30= .2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043894 24312 master.cpp:5930]= Successfully authenticated principal 'test-principal' at scheduler-447125e= d-5188-4af9-bc1d-1693d81f82e6@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.043998 24311 sched.cpp:502] S= uccessfully authenticated with master master@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044008 24311 sched.cpp:820] S= ending SUBSCRIBE call to master@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044054 24311 sched.cpp:853] W= ill retry registration in 598.967375ms if necessary > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044087 24315 master.cpp:2425]= Received SUBSCRIBE call for framework 'default' at scheduler-447125ed-5188= -4af9-bc1d-1693d81f82e6@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044102 24315 master.cpp:1887]= Authorizing framework principal 'test-principal' to receive offers for rol= e '*' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044196 24315 master.cpp:2501]= Subscribing framework default with checkpointing disabled and capabilities= [ ] > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044319 24309 hierarchical.cpp= :271] Added framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044335 24309 hierarchical.cpp= :1548] No allocations performed > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044339 24309 hierarchical.cpp= :1643] No inverse offers to send out! > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044337 24315 sched.cpp:743] F= ramework registered with 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044356 24309 hierarchical.cpp= :1192] Performed allocation for 0 agents in 26622ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044387 24315 sched.cpp:757] S= cheduler::registered took 13681ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044664 24313 metadata_manager= .cpp:248] Successfully loaded image 'alpine' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044682 24313 metadata_manager= .cpp:248] Successfully loaded image 'library/alpine' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044685 24313 metadata_manager= .cpp:251] Successfully loaded 2 Docker images > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044770 24316 provisioner.cpp:= 255] Provisioner recovery complete > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.044936 24309 slave.cpp:4872] = Finished recovery > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045084 24309 slave.cpp:5044] = Querying resource estimator for oversubscribable resources > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045176 24309 slave.cpp:895] N= ew master detected at master@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045186 24309 slave.cpp:954] A= uthenticating with master master@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045192 24315 status_update_ma= nager.cpp:177] Pausing sending status updates > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045195 24309 slave.cpp:965] U= sing default CRAM-MD5 authenticatee > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045246 24309 slave.cpp:927] D= etecting new master > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045272 24312 authenticatee.cp= p:121] Creating new client SASL connection > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045307 24309 slave.cpp:5058] = Received oversubscribable resources from the resource estimator > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045445 24312 master.cpp:5900]= Authenticating slave(480)@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045506 24310 authenticator.cp= p:414] Starting authentication session for crammd5-authenticatee(981)@172.3= 0.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045573 24316 authenticator.cp= p:98] Creating new server SASL connection > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045722 24316 authenticatee.cp= p:213] Received SASL authentication mechanisms: CRAM-MD5 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045733 24316 authenticatee.cp= p:239] Attempting to authenticate with mechanism 'CRAM-MD5' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045786 24313 authenticator.cp= p:204] Received SASL authentication start > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045814 24313 authenticator.cp= p:326] Authentication requires more steps > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045845 24313 authenticatee.cp= p:259] Received SASL authentication step > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045876 24313 authenticator.cp= p:232] Received SASL authentication step > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045891 24313 auxprop.cpp:109]= Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-= 2-105.mesosphere.io' server FQDN: 'ip-172-30-2-105.mesosphere.io' SASL_AUXP= ROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AU= THZID: false=20 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045899 24313 auxprop.cpp:181]= Looking up auxiliary property '*userPassword' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045909 24313 auxprop.cpp:181]= Looking up auxiliary property '*cmusaslsecretCRAM-MD5' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045919 24313 auxprop.cpp:109]= Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-= 2-105.mesosphere.io' server FQDN: 'ip-172-30-2-105.mesosphere.io' SASL_AUXP= ROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AU= THZID: true=20 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045923 24313 auxprop.cpp:131]= Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID =3D= =3D true > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045927 24313 auxprop.cpp:131]= Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AU= THZID =3D=3D true > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045933 24313 authenticator.cp= p:318] Authentication success > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045964 24313 authenticatee.cp= p:299] Authentication success > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.045986 24310 master.cpp:5930]= Successfully authenticated principal 'test-principal' at slave(480)@172.30= .2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.046007 24313 authenticator.cp= p:432] Authentication session cleanup for crammd5-authenticatee(981)@172.30= .2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.046118 24316 slave.cpp:1049] = Successfully authenticated with master master@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.046165 24316 slave.cpp:1455] = Will retry registration in 13.54989ms if necessary > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.046214 24314 master.cpp:4554]= Registering agent at slave(480)@172.30.2.105:36006 (ip-172-30-2-105.mesosp= here.io) with id 21665992-d47e-402f-a00c-6f8fab613019-S0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.046315 24309 registrar.cpp:46= 4] Applied 1 operations in 11551ns; attempting to update the registry > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.046525 24315 log.cpp:577] Att= empting to append 395 bytes to the log > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.046561 24315 coordinator.cpp:= 348] Coordinator attempting to write APPEND action at position 3 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.046823 24311 replica.cpp:537]= Replica received write request for position 3 from __req_res__(5647)@172.3= 0.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.047461 24311 leveldb.cpp:341]= Persisting action (414 bytes) to leveldb took 621763ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.047473 24311 replica.cpp:708]= Persisted action APPEND at position 3 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.047700 24311 replica.cpp:691]= Replica received learned notice for position 3 from @0.0.0.0:0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.049839 24311 leveldb.cpp:341]= Persisting action (416 bytes) to leveldb took 2.121721ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.049860 24311 replica.cpp:708]= Persisted action APPEND at position 3 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050199 24315 registrar.cpp:50= 9] Successfully updated the registry in 3.862016ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050240 24311 log.cpp:596] Att= empting to truncate the log to 3 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050288 24315 coordinator.cpp:= 348] Coordinator attempting to write TRUNCATE action at position 4 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050401 24310 slave.cpp:3739] = Received ping from slave-observer(439)@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050425 24314 master.cpp:4623]= Registered agent 21665992-d47e-402f-a00c-6f8fab613019-S0 at slave(480)@172= .30.2.105:36006 (ip-172-30-2-105.mesosphere.io) with cpus(*):2; mem(*):1024= ; disk(*):1024; ports(*):[31000-32000] > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050448 24310 slave.cpp:1095] = Registered with master master@172.30.2.105:36006; given agent ID 21665992-d= 47e-402f-a00c-6f8fab613019-S0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050472 24310 fetcher.cpp:86] = Clearing fetcher cache > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050478 24313 hierarchical.cpp= :478] Added agent 21665992-d47e-402f-a00c-6f8fab613019-S0 (ip-172-30-2-105.= mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-3= 2000] (allocated: ) > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050585 24316 status_update_ma= nager.cpp:184] Resuming sending status updates > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050616 24310 slave.cpp:1118] = Checkpointing SlaveInfo to '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPu= llerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/meta/slaves/21665992-d47e-402f-= a00c-6f8fab613019-S0/slave.info' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050631 24311 replica.cpp:537]= Replica received write request for position 4 from __req_res__(5648)@172.3= 0.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050671 24313 hierarchical.cpp= :1643] No inverse offers to send out! > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050694 24313 hierarchical.cpp= :1215] Performed allocation for agent 21665992-d47e-402f-a00c-6f8fab613019-= S0 in 191764ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050732 24310 slave.cpp:1155] = Forwarding total oversubscribed resources=20 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050765 24312 master.cpp:5729]= Sending 1 offers to framework 21665992-d47e-402f-a00c-6f8fab613019-0000 (d= efault) at scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2.105:3600= 6 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050825 24312 master.cpp:5006]= Received update of agent 21665992-d47e-402f-a00c-6f8fab613019-S0 at slave(= 480)@172.30.2.105:36006 (ip-172-30-2-105.mesosphere.io) with total oversubs= cribed resources=20 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050896 24309 sched.cpp:917] S= cheduler::resourceOffers took 20825ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050904 24312 hierarchical.cpp= :542] Agent 21665992-d47e-402f-a00c-6f8fab613019-S0 (ip-172-30-2-105.mesosp= here.io) updated with oversubscribed resources (total: cpus(*):2; mem(*):1= 024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):102= 4; disk(*):1024; ports(*):[31000-32000]) > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050941 24312 hierarchical.cpp= :1548] No allocations performed > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050951 24312 hierarchical.cpp= :1643] No inverse offers to send out! > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.050963 24312 hierarchical.cpp= :1215] Performed allocation for agent 21665992-d47e-402f-a00c-6f8fab613019-= S0 in 39673ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.051311 24312 master.cpp:3346]= Processing ACCEPT call for offers: [ 21665992-d47e-402f-a00c-6f8fab613019-= O0 ] on agent 21665992-d47e-402f-a00c-6f8fab613019-S0 at slave(480)@172.30.= 2.105:36006 (ip-172-30-2-105.mesosphere.io) for framework 21665992-d47e-402= f-a00c-6f8fab613019-0000 (default) at scheduler-447125ed-5188-4af9-bc1d-169= 3d81f82e6@172.30.2.105:36006 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.051332 24312 master.cpp:2981]= Authorizing framework principal 'test-principal' to launch task 3b9069a1-a= be8-4c37-ba1d-a84db1ee95c2 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.051690 24309 master.cpp:7451]= Adding task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 with resources cpus(*):1;= mem(*):128 on agent 21665992-d47e-402f-a00c-6f8fab613019-S0 (ip-172-30-2-1= 05.mesosphere.io) > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.051717 24309 master.cpp:3835]= Launching task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992-= d47e-402f-a00c-6f8fab613019-0000 (default) at scheduler-447125ed-5188-4af9-= bc1d-1693d81f82e6@172.30.2.105:36006 with resources cpus(*):1; mem(*):128 o= n agent 21665992-d47e-402f-a00c-6f8fab613019-S0 at slave(480)@172.30.2.105:= 36006 (ip-172-30-2-105.mesosphere.io) > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.051810 24315 slave.cpp:1495] = Got assigned task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 for framework 216659= 92-d47e-402f-a00c-6f8fab613019-0000 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.051861 24314 hierarchical.cpp= :924] Recovered cpus(*):1; mem(*):896; disk(*):1024; ports(*):[31000-32000]= (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allo= cated: cpus(*):1; mem(*):128) on agent 21665992-d47e-402f-a00c-6f8fab613019= -S0 from framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.051882 24314 hierarchical.cpp= :961] Framework 21665992-d47e-402f-a00c-6f8fab613019-0000 filtered agent 21= 665992-d47e-402f-a00c-6f8fab613019-S0 for 5secs > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.052016 24315 slave.cpp:1614] = Launching task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 for framework 21665992-= d47e-402f-a00c-6f8fab613019-0000 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.052245 24315 paths.cpp:536] T= rying to chown '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROO= T_INTERNET_CURL_Whiteout_Aqlqpf/slaves/21665992-d47e-402f-a00c-6f8fab613019= -S0/frameworks/21665992-d47e-402f-a00c-6f8fab613019-0000/executors/3b9069a1= -abe8-4c37-ba1d-a84db1ee95c2/runs/cb771051-d88d-428a-8c0b-cca24f477811' to = user 'root' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.053449 24311 leveldb.cpp:341]= Persisting action (16 bytes) to leveldb took 2.663453ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.053488 24311 replica.cpp:708]= Persisted action TRUNCATE at position 4 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.054006 24313 replica.cpp:691]= Replica received learned notice for position 4 from @0.0.0.0:0 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.055517 24315 slave.cpp:5764] = Launching executor '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' of framework 2166= 5992-d47e-402f-a00c-6f8fab613019-0000 with resources cpus(*):0.1; mem(*):32= in work directory '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest= _ROOT_INTERNET_CURL_Whiteout_Aqlqpf/slaves/21665992-d47e-402f-a00c-6f8fab61= 3019-S0/frameworks/21665992-d47e-402f-a00c-6f8fab613019-0000/executors/3b90= 69a1-abe8-4c37-ba1d-a84db1ee95c2/runs/cb771051-d88d-428a-8c0b-cca24f477811' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.055673 24315 slave.cpp:1840] = Queuing task '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' for executor '3b9069a1-= abe8-4c37-ba1d-a84db1ee95c2' of framework 21665992-d47e-402f-a00c-6f8fab613= 019-0000 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.055687 24310 containerizer.cp= p:786] Starting container 'cb771051-d88d-428a-8c0b-cca24f477811' for execut= or '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' of framework 21665992-d47e-402f-a= 00c-6f8fab613019-0000 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.055707 24315 slave.cpp:848] S= uccessfully attached file '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPul= lerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/slaves/21665992-d47e-402f-a00c-6= f8fab613019-S0/frameworks/21665992-d47e-402f-a00c-6f8fab613019-0000/executo= rs/3b9069a1-abe8-4c37-ba1d-a84db1ee95c2/runs/cb771051-d88d-428a-8c0b-cca24f= 477811' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.055882 24315 metadata_manager= .cpp:167] Looking for image 'cirros' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.056037 24311 registry_puller.= cpp:236] Pulling image 'library/cirros' from 'docker-manifest://registry-1.= docker.io:443library/cirros?latest#https' to '/tmp/mesos/store/docker/stagi= ng/rRyODt' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.057193 24313 leveldb.cpp:341]= Persisting action (18 bytes) to leveldb took 2.141869ms > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.057449 24313 leveldb.cpp:399]= Deleting ~2 keys from leveldb took 146047ns > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.057476 24313 replica.cpp:708]= Persisted action TRUNCATE at position 4 > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.438024 24316 registry_puller.= cpp:259] The manifest for image 'library/cirros' is '{ > [20:11:25]W:=09 [Step 10/10] "schemaVersion": 1, > [20:11:25]W:=09 [Step 10/10] "name": "library/cirros", > [20:11:25]W:=09 [Step 10/10] "tag": "latest", > [20:11:25]W:=09 [Step 10/10] "architecture": "amd64", > [20:11:25]W:=09 [Step 10/10] "fsLayers": [ > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "blobSum": "sha256:a3ed95caeb02ffe6= 8cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "blobSum": "sha256:b5a1edf1e076b8cd= 0a1befe7124b256c5757da5497a188c908d53643262047e1" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "blobSum": "sha256:e6cc72aea3e6702f= 07dc862041195b47deb7def56984860d1b4ff912fb458333" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "blobSum": "sha256:8c4568d4063684a7= 2abcc5dbf16b74750d74ee600d4f520a5fad77308de9e195" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "blobSum": "sha256:a3ed95caeb02ffe6= 8cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4" > [20:11:25]W:=09 [Step 10/10] } > [20:11:25]W:=09 [Step 10/10] ], > [20:11:25]W:=09 [Step 10/10] "history": [ > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "v1Compatibility": "{\"architecture= \":\"amd64\",\"author\":\"Eric Windisch \\u003ceric@windisch.us\\u003e\",\"= config\":{\"Hostname\":\"8586a1739f82\",\"Domainname\":\"\",\"User\":\"\",\= "AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":= false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":null,\"Cmd\":[\"/sbin= /init\"],\"Image\":\"7725b0aea0a1124fba2a0ee33cd6c73822cfdb78ab14fdb6c61232= 5f5ed7e8e4\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnB= uild\":null,\"Labels\":null},\"container\":\"08616e5819c6aab371bfd9ede6159b= c2bb832911f50e3d88fcdb9057327361d4\",\"container_config\":{\"Hostname\":\"8= 586a1739f82\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"Att= achStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,= \"StdinOnce\":false,\"Env\":null,\"Cmd\":[\"/bin/sh\",\"-c\",\"#(nop) CMD [= \\\"/sbin/init\\\"]\"],\"Image\":\"7725b0aea0a1124fba2a0ee33cd6c73822cfdb78= ab14fdb6c612325f5ed7e8e4\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoin= t\":null,\"OnBuild\":null,\"Labels\":null},\"created\":\"2016-01-04T21:25:0= 7.075919325Z\",\"docker_version\":\"1.8.3\",\"id\":\"d8ca8144dee347ab43f012= 3099cc5c8d1b64b96c17da9637769519257006617e\",\"os\":\"linux\",\"parent\":\"= 500e7eced838c4822a111abdb64fce8e7f3c0ecaf3d47157331b0cd30ebac4dc\"}" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "v1Compatibility": "{\"id\":\"500e7= eced838c4822a111abdb64fce8e7f3c0ecaf3d47157331b0cd30ebac4dc\",\"parent\":\"= c42d375c72b4e709bc0eeda368591277fa73836dfd5597fe98e2524c8587536e\",\"create= d\":\"2016-01-04T21:25:06.327404242Z\",\"container_config\":{\"Cmd\":[\"/bi= n/sh -c sed -i '/is_lxc \\u0026\\u0026 lxc_netdown/d' /etc/init.d/rc.sysini= t\"]},\"author\":\"Eric Windisch \\u003ceric@windisch.us\\u003e\"}" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "v1Compatibility": "{\"id\":\"c42d3= 75c72b4e709bc0eeda368591277fa73836dfd5597fe98e2524c8587536e\",\"parent\":\"= 34fa5867b8b0888ea3b718df9ad2925b8f7f50b6583b7cbdfabd826bfe5c6de8\",\"create= d\":\"2016-01-04T21:25:04.222498861Z\",\"container_config\":{\"Cmd\":[\"/bi= n/sh -c rm /etc/rc3.d/S40-network\"]},\"author\":\"Eric Windisch \\u003ceri= c@windisch.us\\u003e\"}" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "v1Compatibility": "{\"id\":\"34fa5= 867b8b0888ea3b718df9ad2925b8f7f50b6583b7cbdfabd826bfe5c6de8\",\"parent\":\"= 3690474eb5b4b26fdfbd89c6e159e8cc376ca76ef48032a30fa6aafd56337880\",\"create= d\":\"2016-01-04T21:25:01.412759058Z\",\"container_config\":{\"Cmd\":[\"/bi= n/sh -c #(nop) ADD file:65515284d0bebdd40442eb13bb6a9e6596ff52e7a6c847363d8= 2844ed88a169e in /\"]},\"author\":\"Eric Windisch \\u003ceric@windisch.us\\= u003e\"}" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "v1Compatibility": "{\"id\":\"36904= 74eb5b4b26fdfbd89c6e159e8cc376ca76ef48032a30fa6aafd56337880\",\"created\":\= "2016-01-04T21:25:00.01231519Z\",\"container_config\":{\"Cmd\":[\"/bin/sh -= c #(nop) MAINTAINER Eric Windisch \\u003ceric@windisch.us\\u003e\"]},\"auth= or\":\"Eric Windisch \\u003ceric@windisch.us\\u003e\"}" > [20:11:25]W:=09 [Step 10/10] } > [20:11:25]W:=09 [Step 10/10] ], > [20:11:25]W:=09 [Step 10/10] "signatures": [ > [20:11:25]W:=09 [Step 10/10] { > [20:11:25]W:=09 [Step 10/10] "header": { > [20:11:25]W:=09 [Step 10/10] "jwk": { > [20:11:25]W:=09 [Step 10/10] "crv": "P-256", > [20:11:25]W:=09 [Step 10/10] "kid": "Z3VA:KNRP:DUR5:ZGOH:Y= BO6:UTHO:V56S:XKQF:ZHQ4:OCYL:STK4:QFUZ", > [20:11:25]W:=09 [Step 10/10] "kty": "EC", > [20:11:25]W:=09 [Step 10/10] "x": "t9C-E0_BCULU0WzXFtKSDBn= G1mNmoBurH4aFv7Y7QPw", > [20:11:25]W:=09 [Step 10/10] "y": "tYhiPXODH2tgNPDrl_ScfZU= Dh6KL1Xl1wUAprIN8urM" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] "alg": "ES256" > [20:11:25]W:=09 [Step 10/10] }, > [20:11:25]W:=09 [Step 10/10] "signature": "Vm2dYcwRmiJLmLIWHZF8y= x9f32JykG9qWDLP4nVNT_8x_3QF3CLG8g0wBIOLc85gR-I6kqB_4Ryhca6O1XNuaQ", > [20:11:25]W:=09 [Step 10/10] "protected": "eyJmb3JtYXRMZW5ndGgiO= jM2MzEsImZvcm1hdFRhaWwiOiJDbjAiLCJ0aW1lIjoiMjAxNi0wOC0wNVQyMDoxMToyNVoifQ" > [20:11:25]W:=09 [Step 10/10] } > [20:11:25]W:=09 [Step 10/10] ] > [20:11:25]W:=09 [Step 10/10] }' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.438086 24316 registry_puller.= cpp:369] Fetching blob 'sha256:a3ed95caeb02ffe68cdd9fd84406680ae93d633cb164= 22d00e8a7c22955b46d4' for layer 'd8ca8144dee347ab43f0123099cc5c8d1b64b96c17= da9637769519257006617e' of image 'library/cirros' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.438100 24316 registry_puller.= cpp:369] Fetching blob 'sha256:b5a1edf1e076b8cd0a1befe7124b256c5757da5497a1= 88c908d53643262047e1' for layer '500e7eced838c4822a111abdb64fce8e7f3c0ecaf3= d47157331b0cd30ebac4dc' of image 'library/cirros' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.438109 24316 registry_puller.= cpp:369] Fetching blob 'sha256:e6cc72aea3e6702f07dc862041195b47deb7def56984= 860d1b4ff912fb458333' for layer 'c42d375c72b4e709bc0eeda368591277fa73836dfd= 5597fe98e2524c8587536e' of image 'library/cirros' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.438118 24316 registry_puller.= cpp:369] Fetching blob 'sha256:8c4568d4063684a72abcc5dbf16b74750d74ee600d4f= 520a5fad77308de9e195' for layer '34fa5867b8b0888ea3b718df9ad2925b8f7f50b658= 3b7cbdfabd826bfe5c6de8' of image 'library/cirros' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.438127 24316 registry_puller.= cpp:369] Fetching blob 'sha256:a3ed95caeb02ffe68cdd9fd84406680ae93d633cb164= 22d00e8a7c22955b46d4' for layer '3690474eb5b4b26fdfbd89c6e159e8cc376ca76ef4= 8032a30fa6aafd56337880' of image 'library/cirros' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.942389 24309 registry_puller.= cpp:306] Extracting layer tar ball '/tmp/mesos/store/docker/staging/rRyODt/= sha256:a3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4 to = rootfs '/tmp/mesos/store/docker/staging/rRyODt/d8ca8144dee347ab43f0123099cc= 5c8d1b64b96c17da9637769519257006617e/rootfs' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.944542 24309 registry_puller.= cpp:306] Extracting layer tar ball '/tmp/mesos/store/docker/staging/rRyODt/= sha256:b5a1edf1e076b8cd0a1befe7124b256c5757da5497a188c908d53643262047e1 to = rootfs '/tmp/mesos/store/docker/staging/rRyODt/500e7eced838c4822a111abdb64f= ce8e7f3c0ecaf3d47157331b0cd30ebac4dc/rootfs' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.946662 24309 registry_puller.= cpp:306] Extracting layer tar ball '/tmp/mesos/store/docker/staging/rRyODt/= sha256:e6cc72aea3e6702f07dc862041195b47deb7def56984860d1b4ff912fb458333 to = rootfs '/tmp/mesos/store/docker/staging/rRyODt/c42d375c72b4e709bc0eeda36859= 1277fa73836dfd5597fe98e2524c8587536e/rootfs' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.948341 24309 registry_puller.= cpp:306] Extracting layer tar ball '/tmp/mesos/store/docker/staging/rRyODt/= sha256:8c4568d4063684a72abcc5dbf16b74750d74ee600d4f520a5fad77308de9e195 to = rootfs '/tmp/mesos/store/docker/staging/rRyODt/34fa5867b8b0888ea3b718df9ad2= 925b8f7f50b6583b7cbdfabd826bfe5c6de8/rootfs' > [20:11:25]W:=09 [Step 10/10] I0805 20:11:25.950039 24309 registry_puller.= cpp:306] Extracting layer tar ball '/tmp/mesos/store/docker/staging/rRyODt/= sha256:a3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4 to = rootfs '/tmp/mesos/store/docker/staging/rRyODt/3690474eb5b4b26fdfbd89c6e159= e8cc376ca76ef48032a30fa6aafd56337880/rootfs' > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.006029 24313 hierarchical.cpp= :1734] Filtered offer with cpus(*):1; mem(*):896; disk(*):1024; ports(*):[3= 1000-32000] on agent 21665992-d47e-402f-a00c-6f8fab613019-S0 for framework = 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.006069 24313 hierarchical.cpp= :1548] No allocations performed > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.006075 24313 hierarchical.cpp= :1643] No inverse offers to send out! > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.006089 24313 hierarchical.cpp= :1192] Performed allocation for 1 agents in 196593ns > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.044724 24314 metadata_manager= .cpp:155] Successfully cached image 'cirros' > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.045126 24314 provisioner.cpp:= 312] Provisioning image rootfs '/mnt/teamcity/temp/buildTmp/ProvisionerDock= erPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/provisioner/containers/cb77= 1051-d88d-428a-8c0b-cca24f477811/backends/aufs/rootfses/6541ef43-5e41-4151-= ad78-68d8b8542ed4' for container cb771051-d88d-428a-8c0b-cca24f477811 using= the 'aufs' backend > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.045382 24315 aufs.cpp:152] Pr= ovisioning image rootfs with aufs: 'dirs=3D/mnt/teamcity/temp/buildTmp/Prov= isionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/provisioner/cont= ainers/cb771051-d88d-428a-8c0b-cca24f477811/backends/aufs/scratch/6541ef43-= 5e41-4151-ad78-68d8b8542ed4/workdir:/tmp/mesos/store/docker/layers/d8ca8144= dee347ab43f0123099cc5c8d1b64b96c17da9637769519257006617e/rootfs:/tmp/mesos/= store/docker/layers/500e7eced838c4822a111abdb64fce8e7f3c0ecaf3d47157331b0cd= 30ebac4dc/rootfs:/tmp/mesos/store/docker/layers/c42d375c72b4e709bc0eeda3685= 91277fa73836dfd5597fe98e2524c8587536e/rootfs:/tmp/mesos/store/docker/layers= /34fa5867b8b0888ea3b718df9ad2925b8f7f50b6583b7cbdfabd826bfe5c6de8/rootfs:/t= mp/mesos/store/docker/layers/3690474eb5b4b26fdfbd89c6e159e8cc376ca76ef48032= a30fa6aafd56337880/rootfs' > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.052793 24316 containerizer.cp= p:1299] Launching 'mesos-containerizer' with flags '--command=3D"{"argument= s":["mesos-executor","--launcher_dir=3D\/mnt\/teamcity\/work\/4240ba9ddd099= 7c3\/build\/src","--sandbox_directory=3D\/mnt\/mesos\/sandbox","--user=3Dro= ot","--rootfs=3D\/mnt\/teamcity\/temp\/buildTmp\/ProvisionerDockerPullerTes= t_ROOT_INTERNET_CURL_Whiteout_Aqlqpf\/provisioner\/containers\/cb771051-d88= d-428a-8c0b-cca24f477811\/backends\/aufs\/rootfses\/6541ef43-5e41-4151-ad78= -68d8b8542ed4"],"shell":false,"user":"root","value":"\/mnt\/teamcity\/work\= /4240ba9ddd0997c3\/build\/src\/mesos-executor"}" --help=3D"false" --pipe_re= ad=3D"31" --pipe_write=3D"109" --pre_exec_commands=3D"[{"arguments":["mesos= -containerizer","mount","--help=3Dfalse","--operation=3Dmake-rslave","--pat= h=3D\/"],"shell":false,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/bu= ild\/src\/mesos-containerizer"},{"arguments":["mount","-n","--rbind","\/mnt= \/teamcity\/temp\/buildTmp\/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_= Whiteout_Aqlqpf\/slaves\/21665992-d47e-402f-a00c-6f8fab613019-S0\/framework= s\/21665992-d47e-402f-a00c-6f8fab613019-0000\/executors\/3b9069a1-abe8-4c37= -ba1d-a84db1ee95c2\/runs\/cb771051-d88d-428a-8c0b-cca24f477811","\/mnt\/tea= mcity\/temp\/buildTmp\/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_White= out_Aqlqpf\/provisioner\/containers\/cb771051-d88d-428a-8c0b-cca24f477811\/= backends\/aufs\/rootfses\/6541ef43-5e41-4151-ad78-68d8b8542ed4\/mnt\/mesos\= /sandbox"],"shell":false,"value":"mount"}]" --unshare_namespace_mnt=3D"fals= e" --user=3D"root" --working_directory=3D"/mnt/teamcity/temp/buildTmp/Provi= sionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/slaves/21665992-d= 47e-402f-a00c-6f8fab613019-S0/frameworks/21665992-d47e-402f-a00c-6f8fab6130= 19-0000/executors/3b9069a1-abe8-4c37-ba1d-a84db1ee95c2/runs/cb771051-d88d-4= 28a-8c0b-cca24f477811"' > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.052883 24316 linux_launcher.c= pp:281] Cloning child process with flags =3D CLONE_NEWNS > [20:11:26] :=09 [Step 10/10] Executing pre-exec command '{"arguments":["m= esos-containerizer","mount","--help=3Dfalse","--operation=3Dmake-rslave","-= -path=3D\/"],"shell":false,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3= \/build\/src\/mesos-containerizer"}' > [20:11:26] :=09 [Step 10/10] Executing pre-exec command '{"arguments":["m= ount","-n","--rbind","\/mnt\/teamcity\/temp\/buildTmp\/ProvisionerDockerPul= lerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf\/slaves\/21665992-d47e-402f-a00c= -6f8fab613019-S0\/frameworks\/21665992-d47e-402f-a00c-6f8fab613019-0000\/ex= ecutors\/3b9069a1-abe8-4c37-ba1d-a84db1ee95c2\/runs\/cb771051-d88d-428a-8c0= b-cca24f477811","\/mnt\/teamcity\/temp\/buildTmp\/ProvisionerDockerPullerTe= st_ROOT_INTERNET_CURL_Whiteout_Aqlqpf\/provisioner\/containers\/cb771051-d8= 8d-428a-8c0b-cca24f477811\/backends\/aufs\/rootfses\/6541ef43-5e41-4151-ad7= 8-68d8b8542ed4\/mnt\/mesos\/sandbox"],"shell":false,"value":"mount"}' > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.379375 9819 exec.cpp:162] Ve= rsion: 1.1.0 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.379905 24309 slave.cpp:2881] = Got registration for executor '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' of fra= mework 21665992-d47e-402f-a00c-6f8fab613019-0000 from executor(1)@172.30.2.= 105:45519 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.380353 9824 exec.cpp:237] Ex= ecutor registered on agent 21665992-d47e-402f-a00c-6f8fab613019-S0 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.380439 24316 slave.cpp:2005] = Sending queued task '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' to executor '3b9= 069a1-abe8-4c37-ba1d-a84db1ee95c2' of framework 21665992-d47e-402f-a00c-6f8= fab613019-0000 at executor(1)@172.30.2.105:45519 > [20:11:26] :=09 [Step 10/10] Received SUBSCRIBED event > [20:11:26] :=09 [Step 10/10] Subscribed executor on ip-172-30-2-105.mesos= phere.io > [20:11:26] :=09 [Step 10/10] Received LAUNCH event > [20:11:26] :=09 [Step 10/10] Starting task 3b9069a1-abe8-4c37-ba1d-a84db1= ee95c2 > [20:11:26] :=09 [Step 10/10] /mnt/teamcity/work/4240ba9ddd0997c3/build/sr= c/mesos-containerizer launch --command=3D"{"arguments":["test","!","-f","\/= etc\/rc3.d\/S40-network"],"shell":false,"value":"\/usr\/bin\/test"}" --help= =3D"false" --rootfs=3D"/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerT= est_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/provisioner/containers/cb771051-d88d= -428a-8c0b-cca24f477811/backends/aufs/rootfses/6541ef43-5e41-4151-ad78-68d8= b8542ed4" --unshare_namespace_mnt=3D"false" --user=3D"root" --working_direc= tory=3D"/mnt/mesos/sandbox" > [20:11:26] :=09 [Step 10/10] Forked command at 9828 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.385869 24310 slave.cpp:3264] = Handling status update TASK_RUNNING (UUID: 0f5f19fa-2bfa-45cd-9855-c3473730= 4f52) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992-d= 47e-402f-a00c-6f8fab613019-0000 from executor(1)@172.30.2.105:45519 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386337 24315 status_update_ma= nager.cpp:323] Received status update TASK_RUNNING (UUID: 0f5f19fa-2bfa-45c= d-9855-c34737304f52) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of frame= work 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386355 24315 status_update_ma= nager.cpp:500] Creating StatusUpdate stream for task 3b9069a1-abe8-4c37-ba1= d-a84db1ee95c2 of framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386513 24315 status_update_ma= nager.cpp:377] Forwarding update TASK_RUNNING (UUID: 0f5f19fa-2bfa-45cd-985= 5-c34737304f52) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework = 21665992-d47e-402f-a00c-6f8fab613019-0000 to the agent > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386613 24314 slave.cpp:3657] = Forwarding the update TASK_RUNNING (UUID: 0f5f19fa-2bfa-45cd-9855-c34737304= f52) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992-d4= 7e-402f-a00c-6f8fab613019-0000 to master@172.30.2.105:36006 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386684 24314 slave.cpp:3551] = Status update manager successfully handled status update TASK_RUNNING (UUID= : 0f5f19fa-2bfa-45cd-9855-c34737304f52) for task 3b9069a1-abe8-4c37-ba1d-a8= 4db1ee95c2 of framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386706 24314 slave.cpp:3567] = Sending acknowledgement for status update TASK_RUNNING (UUID: 0f5f19fa-2bfa= -45cd-9855-c34737304f52) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of f= ramework 21665992-d47e-402f-a00c-6f8fab613019-0000 to executor(1)@172.30.2.= 105:45519 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386802 24311 master.cpp:5141]= Status update TASK_RUNNING (UUID: 0f5f19fa-2bfa-45cd-9855-c34737304f52) fo= r task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992-d47e-402f= -a00c-6f8fab613019-0000 from agent 21665992-d47e-402f-a00c-6f8fab613019-S0 = at slave(480)@172.30.2.105:36006 (ip-172-30-2-105.mesosphere.io) > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386826 24311 master.cpp:5203]= Forwarding status update TASK_RUNNING (UUID: 0f5f19fa-2bfa-45cd-9855-c3473= 7304f52) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 2166599= 2-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386890 24311 master.cpp:6845]= Updating the state of task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framewo= rk 21665992-d47e-402f-a00c-6f8fab613019-0000 (latest state: TASK_RUNNING, s= tatus update state: TASK_RUNNING) > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.386998 24315 sched.cpp:1025] = Scheduler::statusUpdate took 50116ns > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.387138 24315 master.cpp:4266]= Processing ACKNOWLEDGE call 0f5f19fa-2bfa-45cd-9855-c34737304f52 for task = 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992-d47e-402f-a00c-6= f8fab613019-0000 (default) at scheduler-447125ed-5188-4af9-bc1d-1693d81f82e= 6@172.30.2.105:36006 on agent 21665992-d47e-402f-a00c-6f8fab613019-S0 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.388357 24313 status_update_ma= nager.cpp:395] Received status update acknowledgement (UUID: 0f5f19fa-2bfa-= 45cd-9855-c34737304f52) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of fr= amework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.388425 24313 slave.cpp:2650] = Status update manager successfully handled status update acknowledgement (U= UID: 0f5f19fa-2bfa-45cd-9855-c34737304f52) for task 3b9069a1-abe8-4c37-ba1d= -a84db1ee95c2 of framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26] :=09 [Step 10/10] Changing root to /mnt/teamcity/temp/buildTmp= /ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/provisioner= /containers/cb771051-d88d-428a-8c0b-cca24f477811/backends/aufs/rootfses/654= 1ef43-5e41-4151-ad78-68d8b8542ed4 > [20:11:26] :=09 [Step 10/10] Command exited with status 1 (pid: 9828) > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.486747 24311 slave.cpp:3264] = Handling status update TASK_FAILED (UUID: 9a8b3240-f4f2-4457-a90f-16cbf09d1= 34d) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992-d4= 7e-402f-a00c-6f8fab613019-0000 from executor(1)@172.30.2.105:45519 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487098 24313 slave.cpp:6104] = Terminating task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487478 24315 status_update_ma= nager.cpp:323] Received status update TASK_FAILED (UUID: 9a8b3240-f4f2-4457= -a90f-16cbf09d134d) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framew= ork 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487525 24315 status_update_ma= nager.cpp:377] Forwarding update TASK_FAILED (UUID: 9a8b3240-f4f2-4457-a90f= -16cbf09d134d) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 2= 1665992-d47e-402f-a00c-6f8fab613019-0000 to the agent > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487591 24314 slave.cpp:3657] = Forwarding the update TASK_FAILED (UUID: 9a8b3240-f4f2-4457-a90f-16cbf09d13= 4d) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992-d47= e-402f-a00c-6f8fab613019-0000 to master@172.30.2.105:36006 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487664 24314 slave.cpp:3551] = Status update manager successfully handled status update TASK_FAILED (UUID:= 9a8b3240-f4f2-4457-a90f-16cbf09d134d) for task 3b9069a1-abe8-4c37-ba1d-a84= db1ee95c2 of framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26] :=09 [Step 10/10] ../../src/tests/containerizer/provisioner_do= cker_tests.cpp:625: Failure > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487684 24314 slave.cpp:3567] = Sending acknowledgement for status update TASK_FAILED (UUID: 9a8b3240-f4f2-= 4457-a90f-16cbf09d134d) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of fr= amework 21665992-d47e-402f-a00c-6f8fab613019-0000 to executor(1)@172.30.2.1= 05:45519 > [20:11:26] :=09 [Step 10/10] Value of: statusFinished->state() > [20:11:26] :=09 [Step 10/10] Actual: TASK_FAILED > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487730 24309 master.cpp:5141]= Status update TASK_FAILED (UUID: 9a8b3240-f4f2-4457-a90f-16cbf09d134d) for= task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992-d47e-402f-= a00c-6f8fab613019-0000 from agent 21665992-d47e-402f-a00c-6f8fab613019-S0 a= t slave(480)@172.30.2.105:36006 (ip-172-30-2-105.mesosphere.io) > [20:11:26] :=09 [Step 10/10] Expected: TASK_FINISHED > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487756 24309 master.cpp:5203]= Forwarding status update TASK_FAILED (UUID: 9a8b3240-f4f2-4457-a90f-16cbf0= 9d134d) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992= -d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487802 24309 master.cpp:6845]= Updating the state of task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framewo= rk 21665992-d47e-402f-a00c-6f8fab613019-0000 (latest state: TASK_FAILED, st= atus update state: TASK_FAILED) > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487908 24310 sched.cpp:1025] = Scheduler::statusUpdate took 44522ns > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.487980 24312 hierarchical.cpp= :924] Recovered cpus(*):1; mem(*):128 (total: cpus(*):2; mem(*):1024; disk(= *):1024; ports(*):[31000-32000], allocated: ) on agent 21665992-d47e-402f-a= 00c-6f8fab613019-S0 from framework 21665992-d47e-402f-a00c-6f8fab613019-000= 0 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488000 24313 master.cpp:4266]= Processing ACKNOWLEDGE call 9a8b3240-f4f2-4457-a90f-16cbf09d134d for task = 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 21665992-d47e-402f-a00c-6= f8fab613019-0000 (default) at scheduler-447125ed-5188-4af9-bc1d-1693d81f82e= 6@172.30.2.105:36006 on agent 21665992-d47e-402f-a00c-6f8fab613019-S0 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488028 24313 master.cpp:6911]= Removing task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 with resources cpus(*):= 1; mem(*):128 of framework 21665992-d47e-402f-a00c-6f8fab613019-0000 on age= nt 21665992-d47e-402f-a00c-6f8fab613019-S0 at slave(480)@172.30.2.105:36006= (ip-172-30-2-105.mesosphere.io) > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488126 24295 sched.cpp:1987] = Asked to stop the driver > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488155 24310 status_update_ma= nager.cpp:395] Received status update acknowledgement (UUID: 9a8b3240-f4f2-= 4457-a90f-16cbf09d134d) for task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of fr= amework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488179 24312 sched.cpp:1187] = Stopping framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488198 24310 status_update_ma= nager.cpp:531] Cleaning up status update stream for task 3b9069a1-abe8-4c37= -ba1d-a84db1ee95c2 of framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488283 24314 master.cpp:6304]= Processing TEARDOWN call for framework 21665992-d47e-402f-a00c-6f8fab61301= 9-0000 (default) at scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2= .105:36006 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488302 24314 master.cpp:6316]= Removing framework 21665992-d47e-402f-a00c-6f8fab613019-0000 (default) at = scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2.105:36006 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488351 24313 hierarchical.cpp= :382] Deactivated framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488355 24309 slave.cpp:2650] = Status update manager successfully handled status update acknowledgement (U= UID: 9a8b3240-f4f2-4457-a90f-16cbf09d134d) for task 3b9069a1-abe8-4c37-ba1d= -a84db1ee95c2 of framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488371 24309 slave.cpp:6145] = Completing task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488409 24309 slave.cpp:2218] = Asked to shut down framework 21665992-d47e-402f-a00c-6f8fab613019-0000 by m= aster@172.30.2.105:36006 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488425 24309 slave.cpp:2243] = Shutting down framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488436 24309 slave.cpp:4460] = Shutting down executor '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' of framework = 21665992-d47e-402f-a00c-6f8fab613019-0000 at executor(1)@172.30.2.105:45519 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488445 24314 hierarchical.cpp= :333] Removed framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.488981 24309 containerizer.cp= p:1637] Destroying container 'cb771051-d88d-428a-8c0b-cca24f477811' > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.489099 9822 exec.cpp:414] Ex= ecutor asked to shutdown > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.490057 24310 cgroups.cpp:2678= ] Freezing cgroup /sys/fs/cgroup/freezer/mesos/cb771051-d88d-428a-8c0b-cca2= 4f477811 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.491039 24313 cgroups.cpp:1412= ] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/cb771051-d88d-428a= -8c0b-cca24f477811 after 958976ns > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.492154 24311 cgroups.cpp:2696= ] Thawing cgroup /sys/fs/cgroup/freezer/mesos/cb771051-d88d-428a-8c0b-cca24= f477811 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.493185 24314 cgroups.cpp:1441= ] Successfully thawed cgroup /sys/fs/cgroup/freezer/mesos/cb771051-d88d-428= a-8c0b-cca24f477811 after 1.014016ms > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.505236 24311 slave.cpp:3785] = Got exited event for executor(1)@172.30.2.105:45519 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.545552 24313 containerizer.cp= p:1878] Executor for container 'cb771051-d88d-428a-8c0b-cca24f477811' has e= xited > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.545567 24313 containerizer.cp= p:1633] Destroy has already been initiated for 'cb771051-d88d-428a-8c0b-cca= 24f477811' > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.546809 24314 provisioner.cpp:= 455] Destroying container rootfs at '/mnt/teamcity/temp/buildTmp/Provisione= rDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/provisioner/containers= /cb771051-d88d-428a-8c0b-cca24f477811/backends/aufs/rootfses/6541ef43-5e41-= 4151-ad78-68d8b8542ed4' for container cb771051-d88d-428a-8c0b-cca24f477811 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581281 24312 slave.cpp:4142] = Executor '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' of framework 21665992-d47e-= 402f-a00c-6f8fab613019-0000 terminated with signal Killed > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581300 24312 slave.cpp:4246] = Cleaning up executor '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' of framework 21= 665992-d47e-402f-a00c-6f8fab613019-0000 at executor(1)@172.30.2.105:45519 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581406 24309 gc.cpp:55] Sched= uling '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNE= T_CURL_Whiteout_Aqlqpf/slaves/21665992-d47e-402f-a00c-6f8fab613019-S0/frame= works/21665992-d47e-402f-a00c-6f8fab613019-0000/executors/3b9069a1-abe8-4c3= 7-ba1d-a84db1ee95c2/runs/cb771051-d88d-428a-8c0b-cca24f477811' for gc 6.999= 99327130667days in the future > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581437 24312 slave.cpp:4334] = Cleaning up framework 21665992-d47e-402f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581456 24309 gc.cpp:55] Sched= uling '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNE= T_CURL_Whiteout_Aqlqpf/slaves/21665992-d47e-402f-a00c-6f8fab613019-S0/frame= works/21665992-d47e-402f-a00c-6f8fab613019-0000/executors/3b9069a1-abe8-4c3= 7-ba1d-a84db1ee95c2' for gc 6.99999327068148days in the future > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581508 24310 status_update_ma= nager.cpp:285] Closing status update streams for framework 21665992-d47e-40= 2f-a00c-6f8fab613019-0000 > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581571 24316 gc.cpp:55] Sched= uling '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNE= T_CURL_Whiteout_Aqlqpf/slaves/21665992-d47e-402f-a00c-6f8fab613019-S0/frame= works/21665992-d47e-402f-a00c-6f8fab613019-0000' for gc 6.99999326983704day= s in the future > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581689 24295 slave.cpp:767] A= gent terminating > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581763 24309 master.cpp:1245]= Agent 21665992-d47e-402f-a00c-6f8fab613019-S0 at slave(480)@172.30.2.105:3= 6006 (ip-172-30-2-105.mesosphere.io) disconnected > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581775 24309 master.cpp:2785]= Disconnecting agent 21665992-d47e-402f-a00c-6f8fab613019-S0 at slave(480)@= 172.30.2.105:36006 (ip-172-30-2-105.mesosphere.io) > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581810 24309 master.cpp:2804]= Deactivating agent 21665992-d47e-402f-a00c-6f8fab613019-S0 at slave(480)@1= 72.30.2.105:36006 (ip-172-30-2-105.mesosphere.io) > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.581904 24309 hierarchical.cpp= :571] Agent 21665992-d47e-402f-a00c-6f8fab613019-S0 deactivated > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.583799 24295 master.cpp:1092]= Master terminating > [20:11:26]W:=09 [Step 10/10] I0805 20:11:26.583896 24315 hierarchical.cpp= :510] Removed agent 21665992-d47e-402f-a00c-6f8fab613019-S0 > [20:11:26] :=09 [Step 10/10] [ FAILED ] ProvisionerDockerPullerTest.ROO= T_INTERNET_CURL_Whiteout (1599 ms) > {noformat} -- This message was sent by Atlassian JIRA (v6.3.4#6332)