[ 
https://issues.apache.org/jira/browse/MESOS-6002?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

St├ęphane Cottin updated MESOS-6002:
-----------------------------------
    Attachment: whiteout.diff

This simple workaround, testing is file exists before trying to delete it, 
works for me.
Off course this is just a temporary hack, a proper whiteout opaque dirs 
handling should be added.

> 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
>              Labels: aufs, backend, containerizer
>         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] :   [Step 10/10] [ RUN      ] 
> ProvisionerDockerPullerTest.ROOT_INTERNET_CURL_Whiteout
> [20:11:24]W:   [Step 10/10] I0805 20:11:24.986734 24295 cluster.cpp:155] 
> Creating default 'local' authorizer
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.001153 24295 leveldb.cpp:174] 
> Opened db in 14.308627ms
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.003731 24295 leveldb.cpp:181] 
> Compacted db in 2.558329ms
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.003749 24295 leveldb.cpp:196] 
> Created db iterator in 3086ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.003754 24295 leveldb.cpp:202] 
> Seeked to beginning of db in 595ns
> [20:11:25]W:   [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:   [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:   [Step 10/10] I0805 20:11:25.004086 24315 recover.cpp:451] 
> Starting replica recovery
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.004251 24312 recover.cpp:477] 
> Replica is in EMPTY status
> [20:11:25]W:   [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:   [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:   [Step 10/10] I0805 20:11:25.004762 24313 recover.cpp:568] 
> Updating replica status to STARTING
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.004787 24314 master.cpp:377] Flags 
> at startup: --acls="" --agent_ping_timeout="15secs" 
> --agent_reregister_timeout="10mins" --allocation_interval="1secs" 
> --allocator="HierarchicalDRF" --authenticate_agents="true" 
> --authenticate_frameworks="true" --authenticate_http_frameworks="true" 
> --authenticate_http_readonly="true" --authenticate_http_readwrite="true" 
> --authenticators="crammd5" --authorizers="local" 
> --credentials="/tmp/0z753P/credentials" --framework_sorter="drf" 
> --help="false" --hostname_lookup="true" --http_authenticators="basic" 
> --http_framework_authenticators="basic" --initialize_driver_logging="true" 
> --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" 
> --max_agent_ping_timeouts="5" --max_completed_frameworks="50" 
> --max_completed_tasks_per_framework="1000" --quiet="false" 
> --recovery_agent_removal_limit="100%" --registry="replicated_log" 
> --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" 
> --registry_strict="true" --root_submissions="true" --user_sorter="drf" 
> --version="false" --webui_dir="/usr/local/share/mesos/webui" 
> --work_dir="/tmp/0z753P/master" --zk_session_timeout="10secs"
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.004920 24314 master.cpp:427] 
> Master only allowing authenticated frameworks to register
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.004930 24314 master.cpp:441] 
> Master only allowing authenticated agents to register
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.004935 24314 master.cpp:454] 
> Master only allowing authenticated HTTP frameworks to register
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.004942 24314 credentials.hpp:37] 
> Loading credentials for authentication from '/tmp/0z753P/credentials'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005018 24314 master.cpp:499] Using 
> default 'crammd5' authenticator
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005101 24314 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005152 24314 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005192 24314 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005230 24314 master.cpp:579] 
> Authorization enabled
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005297 24315 hierarchical.cpp:151] 
> Initialized hierarchical allocator process
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005312 24312 
> whitelist_watcher.cpp:77] No whitelist given
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005820 24315 master.cpp:1851] 
> Elected as the leading master!
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005828 24315 master.cpp:1547] 
> Recovering from registrar
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.005889 24310 registrar.cpp:332] 
> Recovering registrar
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.006865 24311 replica.cpp:320] 
> Persisted replica status to STARTING
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.006913 24311 recover.cpp:477] 
> Replica is in STARTING status
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.007186 24310 replica.cpp:673] 
> Replica in STARTING status received a broadcasted recover request from 
> __req_res__(5641)@172.30.2.105:36006
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.007446 24315 recover.cpp:568] 
> Updating replica status to VOTING
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.009600 24309 replica.cpp:320] 
> Persisted replica status to VOTING
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.009632 24309 recover.cpp:582] 
> Successfully joined the Paxos group
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.009706 24309 recover.cpp:466] 
> Recover process terminated
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.009865 24313 log.cpp:553] 
> Attempting to start the writer
> [20:11:25]W:   [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:   [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:   [Step 10/10] I0805 20:11:25.012281 24312 replica.cpp:342] 
> Persisted promised to 1
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.012506 24311 coordinator.cpp:238] 
> Coordinator attempting to fill missing positions
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.013638 24316 leveldb.cpp:341] 
> Persisting action (8 bytes) to leveldb took 654110ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.013651 24316 replica.cpp:708] 
> Persisted action NOP at position 0
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.014034 24309 replica.cpp:537] 
> Replica received write request for position 0 from 
> __req_res__(5644)@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.014056 24309 leveldb.cpp:436] 
> Reading position from leveldb took 9338ns
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.016985 24309 replica.cpp:708] 
> Persisted action NOP at position 0
> [20:11:25]W:   [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:   [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:   [Step 10/10] I0805 20:11:25.019361 24311 replica.cpp:708] 
> Persisted action NOP at position 0
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.019507 24313 log.cpp:569] Writer 
> started with ending position 0
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.019839 24309 leveldb.cpp:436] 
> Reading position from leveldb took 10748ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.020036 24310 registrar.cpp:365] 
> Successfully fetched the registry (0B) in 14.12608ms
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.020072 24310 registrar.cpp:464] 
> Applied 1 operations in 3729ns; attempting to update the registry
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.020220 24313 log.cpp:577] 
> Attempting to append 209 bytes to the log
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.020550 24311 replica.cpp:537] 
> Replica received write request for position 1 from 
> __req_res__(5645)@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.021132 24311 leveldb.cpp:341] 
> Persisting action (228 bytes) to leveldb took 565494ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.021144 24311 replica.cpp:708] 
> Persisted action APPEND at position 1
> [20:11:25]W:   [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:   [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:   [Step 10/10] I0805 20:11:25.023332 24310 replica.cpp:708] 
> Persisted action APPEND at position 1
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.023541 24315 registrar.cpp:509] 
> Successfully updated the registry in 3.454976ms
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.023597 24315 registrar.cpp:395] 
> Successfully recovered registrar
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.023643 24313 log.cpp:596] 
> Attempting to truncate the log to 1
> [20:11:25]W:   [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:   [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:   [Step 10/10] I0805 20:11:25.023783 24310 hierarchical.cpp:178] 
> Skipping recovery of hierarchical allocator: nothing to recover
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.025234 24315 replica.cpp:537] 
> Replica received write request for position 2 from 
> __req_res__(5646)@172.30.2.105:36006
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.027158 24315 replica.cpp:708] 
> Persisted action TRUNCATE at position 2
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.028108 24316 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 692102ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.028131 24316 leveldb.cpp:399] 
> Deleting ~1 keys from leveldb took 10051ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.028139 24316 replica.cpp:708] 
> Persisted action TRUNCATE at position 2
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.029505 24295 
> containerizer.cpp:200] Using isolation: 
> docker/runtime,filesystem/linux,network/cni
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.032551 24295 
> linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy 
> for the Linux launcher
> [20:11:25]W:   [Step 10/10] E0805 20:11:25.035212 24295 shell.hpp:106] 
> Command 'hadoop version 2>&1' failed; this is the output:
> [20:11:25]W:   [Step 10/10] sh: 1: hadoop: not found
> [20:11:25]W:   [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 was 
> either not found or exited with a non-zero exit status: 127
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.036067 24295 linux.cpp:148] Bind 
> mounting 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf'
>  and making it a shared mount
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.041409 24295 cluster.cpp:434] 
> Creating default 'local' authorizer
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.041822 24309 slave.cpp:198] Mesos 
> agent started on (480)@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.041838 24309 slave.cpp:199] Flags 
> at startup: --acls="" --appc_simple_discovery_uri_prefix="http://"; 
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_readonly="true" 
> --authenticate_http_readwrite="true" --authenticatee="crammd5" 
> --authentication_backoff_factor="1secs" --authorizer="local" 
> --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_INTERNET_CURL_Whiteout_Aqlqpf/credential"
>  --default_role="*" --disk_watch_interval="1mins" --docker="docker" 
> --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io"; 
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" 
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" 
> --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" 
> --enforce_container_disk_quota="false" 
> --executor_registration_timeout="1mins" 
> --executor_shutdown_grace_period="5secs" 
> --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/fetch"
>  --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" 
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false" 
> --hostname_lookup="true" --http_authenticators="basic" 
> --http_command_executor="false" 
> --http_credentials="/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/http_credentials"
>  --image_providers="docker" --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;gpus:0;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_INTERNET_CURL_Whiteout_Aqlqpf"
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.042135 24309 slave.cpp:336] Agent 
> using credential for: test-principal
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042145 24309 credentials.hpp:37] 
> Loading credentials for authentication from 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/http_credentials'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042207 24309 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042326 24309 http.cpp:883] Using 
> default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042444 24295 sched.cpp:226] 
> Version: 1.1.0
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042582 24313 sched.cpp:330] New 
> master detected at master@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042618 24313 sched.cpp:396] 
> Authenticating with master master@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042628 24313 sched.cpp:403] Using 
> default CRAM-MD5 authenticatee
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042681 24309 slave.cpp:519] Agent 
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042712 24309 slave.cpp:527] Agent 
> attributes: [  ]
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042721 24309 slave.cpp:532] Agent 
> hostname: ip-172-30-2-105.mesosphere.io
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.042774 24314 
> authenticatee.cpp:121] Creating new client SASL connection
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043064 24309 state.cpp:57] 
> Recovering state from 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/meta'
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.043184 24311 
> authenticator.cpp:414] Starting authentication session for 
> crammd5-authenticatee(980)@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043272 24316 
> status_update_manager.cpp:203] Recovering status update manager
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043310 24309 authenticator.cpp:98] 
> Creating new server SASL connection
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043362 24313 
> containerizer.cpp:527] Recovering containerizer
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043468 24309 
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043488 24309 
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043536 24309 
> authenticator.cpp:204] Received SASL authentication start
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043567 24309 
> authenticator.cpp:326] Authentication requires more steps
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043597 24309 
> authenticatee.cpp:259] Received SASL authentication step
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043700 24312 
> authenticator.cpp:232] Received SASL authentication step
> [20:11:25]W:   [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_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043721 24312 auxprop.cpp:181] 
> Looking up auxiliary property '*userPassword'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043730 24312 auxprop.cpp:181] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [20:11:25]W:   [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_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043740 24312 auxprop.cpp:131] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043742 24312 auxprop.cpp:131] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043751 24312 
> authenticator.cpp:318] Authentication success
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043804 24311 
> authenticatee.cpp:299] Authentication success
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043828 24316 
> authenticator.cpp:432] Authentication session cleanup for 
> crammd5-authenticatee(980)@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043894 24312 master.cpp:5930] 
> Successfully authenticated principal 'test-principal' at 
> scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.043998 24311 sched.cpp:502] 
> Successfully authenticated with master master@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044008 24311 sched.cpp:820] 
> Sending SUBSCRIBE call to master@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044054 24311 sched.cpp:853] Will 
> retry registration in 598.967375ms if necessary
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.044102 24315 master.cpp:1887] 
> Authorizing framework principal 'test-principal' to receive offers for role 
> '*'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044196 24315 master.cpp:2501] 
> Subscribing framework default with checkpointing disabled and capabilities [  
> ]
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044319 24309 hierarchical.cpp:271] 
> Added framework 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044335 24309 
> hierarchical.cpp:1548] No allocations performed
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044339 24309 
> hierarchical.cpp:1643] No inverse offers to send out!
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044337 24315 sched.cpp:743] 
> Framework registered with 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044356 24309 
> hierarchical.cpp:1192] Performed allocation for 0 agents in 26622ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044387 24315 sched.cpp:757] 
> Scheduler::registered took 13681ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044664 24313 
> metadata_manager.cpp:248] Successfully loaded image 'alpine'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044682 24313 
> metadata_manager.cpp:248] Successfully loaded image 'library/alpine'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044685 24313 
> metadata_manager.cpp:251] Successfully loaded 2 Docker images
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044770 24316 provisioner.cpp:255] 
> Provisioner recovery complete
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.044936 24309 slave.cpp:4872] 
> Finished recovery
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045084 24309 slave.cpp:5044] 
> Querying resource estimator for oversubscribable resources
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045176 24309 slave.cpp:895] New 
> master detected at master@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045186 24309 slave.cpp:954] 
> Authenticating with master master@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045192 24315 
> status_update_manager.cpp:177] Pausing sending status updates
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045195 24309 slave.cpp:965] Using 
> default CRAM-MD5 authenticatee
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045246 24309 slave.cpp:927] 
> Detecting new master
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045272 24312 
> authenticatee.cpp:121] Creating new client SASL connection
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045307 24309 slave.cpp:5058] 
> Received oversubscribable resources  from the resource estimator
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045445 24312 master.cpp:5900] 
> Authenticating slave(480)@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045506 24310 
> authenticator.cpp:414] Starting authentication session for 
> crammd5-authenticatee(981)@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045573 24316 authenticator.cpp:98] 
> Creating new server SASL connection
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045722 24316 
> authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045733 24316 
> authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045786 24313 
> authenticator.cpp:204] Received SASL authentication start
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045814 24313 
> authenticator.cpp:326] Authentication requires more steps
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045845 24313 
> authenticatee.cpp:259] Received SASL authentication step
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045876 24313 
> authenticator.cpp:232] Received SASL authentication step
> [20:11:25]W:   [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_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045899 24313 auxprop.cpp:181] 
> Looking up auxiliary property '*userPassword'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045909 24313 auxprop.cpp:181] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [20:11:25]W:   [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_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045923 24313 auxprop.cpp:131] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045927 24313 auxprop.cpp:131] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045933 24313 
> authenticator.cpp:318] Authentication success
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.045964 24313 
> authenticatee.cpp:299] Authentication success
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.046007 24313 
> authenticator.cpp:432] Authentication session cleanup for 
> crammd5-authenticatee(981)@172.30.2.105:36006
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.046165 24316 slave.cpp:1455] Will 
> retry registration in 13.54989ms if necessary
> [20:11:25]W:   [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.mesosphere.io) with id 
> 21665992-d47e-402f-a00c-6f8fab613019-S0
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.046315 24309 registrar.cpp:464] 
> Applied 1 operations in 11551ns; attempting to update the registry
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.046525 24315 log.cpp:577] 
> Attempting to append 395 bytes to the log
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.046823 24311 replica.cpp:537] 
> Replica received write request for position 3 from 
> __req_res__(5647)@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.047461 24311 leveldb.cpp:341] 
> Persisting action (414 bytes) to leveldb took 621763ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.047473 24311 replica.cpp:708] 
> Persisted action APPEND at position 3
> [20:11:25]W:   [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:   [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:   [Step 10/10] I0805 20:11:25.049860 24311 replica.cpp:708] 
> Persisted action APPEND at position 3
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050199 24315 registrar.cpp:509] 
> Successfully updated the registry in 3.862016ms
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050240 24311 log.cpp:596] 
> Attempting to truncate the log to 3
> [20:11:25]W:   [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:   [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:   [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:   [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-d47e-402f-a00c-6f8fab613019-S0
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050472 24310 fetcher.cpp:86] 
> Clearing fetcher cache
> [20:11:25]W:   [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-32000] (allocated: )
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050585 24316 
> status_update_manager.cpp:184] Resuming sending status updates
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050616 24310 slave.cpp:1118] 
> Checkpointing SlaveInfo to 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/meta/slaves/21665992-d47e-402f-a00c-6f8fab613019-S0/slave.info'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050631 24311 replica.cpp:537] 
> Replica received write request for position 4 from 
> __req_res__(5648)@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050671 24313 
> hierarchical.cpp:1643] No inverse offers to send out!
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.050732 24310 slave.cpp:1155] 
> Forwarding total oversubscribed resources 
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050765 24312 master.cpp:5729] 
> Sending 1 offers to framework 21665992-d47e-402f-a00c-6f8fab613019-0000 
> (default) at scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2.105:36006
> [20:11:25]W:   [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 
> oversubscribed resources 
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050896 24309 sched.cpp:917] 
> Scheduler::resourceOffers took 20825ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050904 24312 hierarchical.cpp:542] 
> Agent 21665992-d47e-402f-a00c-6f8fab613019-S0 (ip-172-30-2-105.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])
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050941 24312 
> hierarchical.cpp:1548] No allocations performed
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.050951 24312 
> hierarchical.cpp:1643] No inverse offers to send out!
> [20:11:25]W:   [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:   [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-402f-a00c-6f8fab613019-0000 (default) at 
> scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2.105:36006
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.051332 24312 master.cpp:2981] 
> Authorizing framework principal 'test-principal' to launch task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2
> [20:11:25]W:   [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-105.mesosphere.io)
> [20:11:25]W:   [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 on 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:   [Step 10/10] I0805 20:11:25.051810 24315 slave.cpp:1495] Got 
> assigned task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 for framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:25]W:   [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], allocated: 
> cpus(*):1; mem(*):128) on agent 21665992-d47e-402f-a00c-6f8fab613019-S0 from 
> framework 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.051882 24314 hierarchical.cpp:961] 
> Framework 21665992-d47e-402f-a00c-6f8fab613019-0000 filtered agent 
> 21665992-d47e-402f-a00c-6f8fab613019-S0 for 5secs
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.052245 24315 paths.cpp:536] Trying 
> to chown 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_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:   [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:   [Step 10/10] I0805 20:11:25.053488 24311 replica.cpp:708] 
> Persisted action TRUNCATE at position 4
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.055517 24315 slave.cpp:5764] 
> Launching executor '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' of framework 
> 21665992-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-6f8fab613019-S0/frameworks/21665992-d47e-402f-a00c-6f8fab613019-0000/executors/3b9069a1-abe8-4c37-ba1d-a84db1ee95c2/runs/cb771051-d88d-428a-8c0b-cca24f477811'
> [20:11:25]W:   [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-6f8fab613019-0000
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.055687 24310 
> containerizer.cpp:786] Starting container 
> 'cb771051-d88d-428a-8c0b-cca24f477811' for executor 
> '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.055707 24315 slave.cpp:848] 
> Successfully attached file 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_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'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.055882 24315 
> metadata_manager.cpp:167] Looking for image 'cirros'
> [20:11:25]W:   [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/staging/rRyODt'
> [20:11:25]W:   [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:   [Step 10/10] I0805 20:11:25.057449 24313 leveldb.cpp:399] 
> Deleting ~2 keys from leveldb took 146047ns
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.057476 24313 replica.cpp:708] 
> Persisted action TRUNCATE at position 4
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.438024 24316 
> registry_puller.cpp:259] The manifest for image 'library/cirros' is '{
> [20:11:25]W:   [Step 10/10]    "schemaVersion": 1,
> [20:11:25]W:   [Step 10/10]    "name": "library/cirros",
> [20:11:25]W:   [Step 10/10]    "tag": "latest",
> [20:11:25]W:   [Step 10/10]    "architecture": "amd64",
> [20:11:25]W:   [Step 10/10]    "fsLayers": [
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "blobSum": 
> "sha256:a3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4"
> [20:11:25]W:   [Step 10/10]       },
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "blobSum": 
> "sha256:b5a1edf1e076b8cd0a1befe7124b256c5757da5497a188c908d53643262047e1"
> [20:11:25]W:   [Step 10/10]       },
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "blobSum": 
> "sha256:e6cc72aea3e6702f07dc862041195b47deb7def56984860d1b4ff912fb458333"
> [20:11:25]W:   [Step 10/10]       },
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "blobSum": 
> "sha256:8c4568d4063684a72abcc5dbf16b74750d74ee600d4f520a5fad77308de9e195"
> [20:11:25]W:   [Step 10/10]       },
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "blobSum": 
> "sha256:a3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4"
> [20:11:25]W:   [Step 10/10]       }
> [20:11:25]W:   [Step 10/10]    ],
> [20:11:25]W:   [Step 10/10]    "history": [
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "v1Compatibility": 
> "{\"architecture\":\"amd64\",\"author\":\"Eric Windisch 
> \\u003ce...@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\":\"7725b0aea0a1124fba2a0ee33cd6c73822cfdb78ab14fdb6c612325f5ed7e8e4\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnBuild\":null,\"Labels\":null},\"container\":\"08616e5819c6aab371bfd9ede6159bc2bb832911f50e3d88fcdb9057327361d4\",\"container_config\":{\"Hostname\":\"8586a1739f82\",\"Domainname\":\"\",\"User\":\"\",\"AttachStdin\":false,\"AttachStdout\":false,\"AttachStderr\":false,\"Tty\":false,\"OpenStdin\":false,\"StdinOnce\":false,\"Env\":null,\"Cmd\":[\"/bin/sh\",\"-c\",\"#(nop)
>  CMD 
> [\\\"/sbin/init\\\"]\"],\"Image\":\"7725b0aea0a1124fba2a0ee33cd6c73822cfdb78ab14fdb6c612325f5ed7e8e4\",\"Volumes\":null,\"WorkingDir\":\"\",\"Entrypoint\":null,\"OnBuild\":null,\"Labels\":null},\"created\":\"2016-01-04T21:25:07.075919325Z\",\"docker_version\":\"1.8.3\",\"id\":\"d8ca8144dee347ab43f0123099cc5c8d1b64b96c17da9637769519257006617e\",\"os\":\"linux\",\"parent\":\"500e7eced838c4822a111abdb64fce8e7f3c0ecaf3d47157331b0cd30ebac4dc\"}"
> [20:11:25]W:   [Step 10/10]       },
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "v1Compatibility": 
> "{\"id\":\"500e7eced838c4822a111abdb64fce8e7f3c0ecaf3d47157331b0cd30ebac4dc\",\"parent\":\"c42d375c72b4e709bc0eeda368591277fa73836dfd5597fe98e2524c8587536e\",\"created\":\"2016-01-04T21:25:06.327404242Z\",\"container_config\":{\"Cmd\":[\"/bin/sh
>  -c sed -i '/is_lxc \\u0026\\u0026 lxc_netdown/d' 
> /etc/init.d/rc.sysinit\"]},\"author\":\"Eric Windisch 
> \\u003ce...@windisch.us\\u003e\"}"
> [20:11:25]W:   [Step 10/10]       },
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "v1Compatibility": 
> "{\"id\":\"c42d375c72b4e709bc0eeda368591277fa73836dfd5597fe98e2524c8587536e\",\"parent\":\"34fa5867b8b0888ea3b718df9ad2925b8f7f50b6583b7cbdfabd826bfe5c6de8\",\"created\":\"2016-01-04T21:25:04.222498861Z\",\"container_config\":{\"Cmd\":[\"/bin/sh
>  -c rm /etc/rc3.d/S40-network\"]},\"author\":\"Eric Windisch 
> \\u003ce...@windisch.us\\u003e\"}"
> [20:11:25]W:   [Step 10/10]       },
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "v1Compatibility": 
> "{\"id\":\"34fa5867b8b0888ea3b718df9ad2925b8f7f50b6583b7cbdfabd826bfe5c6de8\",\"parent\":\"3690474eb5b4b26fdfbd89c6e159e8cc376ca76ef48032a30fa6aafd56337880\",\"created\":\"2016-01-04T21:25:01.412759058Z\",\"container_config\":{\"Cmd\":[\"/bin/sh
>  -c #(nop) ADD 
> file:65515284d0bebdd40442eb13bb6a9e6596ff52e7a6c847363d82844ed88a169e in 
> /\"]},\"author\":\"Eric Windisch \\u003ce...@windisch.us\\u003e\"}"
> [20:11:25]W:   [Step 10/10]       },
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "v1Compatibility": 
> "{\"id\":\"3690474eb5b4b26fdfbd89c6e159e8cc376ca76ef48032a30fa6aafd56337880\",\"created\":\"2016-01-04T21:25:00.01231519Z\",\"container_config\":{\"Cmd\":[\"/bin/sh
>  -c #(nop) MAINTAINER Eric Windisch 
> \\u003ce...@windisch.us\\u003e\"]},\"author\":\"Eric Windisch 
> \\u003ce...@windisch.us\\u003e\"}"
> [20:11:25]W:   [Step 10/10]       }
> [20:11:25]W:   [Step 10/10]    ],
> [20:11:25]W:   [Step 10/10]    "signatures": [
> [20:11:25]W:   [Step 10/10]       {
> [20:11:25]W:   [Step 10/10]          "header": {
> [20:11:25]W:   [Step 10/10]             "jwk": {
> [20:11:25]W:   [Step 10/10]                "crv": "P-256",
> [20:11:25]W:   [Step 10/10]                "kid": 
> "Z3VA:KNRP:DUR5:ZGOH:YBO6:UTHO:V56S:XKQF:ZHQ4:OCYL:STK4:QFUZ",
> [20:11:25]W:   [Step 10/10]                "kty": "EC",
> [20:11:25]W:   [Step 10/10]                "x": 
> "t9C-E0_BCULU0WzXFtKSDBnG1mNmoBurH4aFv7Y7QPw",
> [20:11:25]W:   [Step 10/10]                "y": 
> "tYhiPXODH2tgNPDrl_ScfZUDh6KL1Xl1wUAprIN8urM"
> [20:11:25]W:   [Step 10/10]             },
> [20:11:25]W:   [Step 10/10]             "alg": "ES256"
> [20:11:25]W:   [Step 10/10]          },
> [20:11:25]W:   [Step 10/10]          "signature": 
> "Vm2dYcwRmiJLmLIWHZF8yx9f32JykG9qWDLP4nVNT_8x_3QF3CLG8g0wBIOLc85gR-I6kqB_4Ryhca6O1XNuaQ",
> [20:11:25]W:   [Step 10/10]          "protected": 
> "eyJmb3JtYXRMZW5ndGgiOjM2MzEsImZvcm1hdFRhaWwiOiJDbjAiLCJ0aW1lIjoiMjAxNi0wOC0wNVQyMDoxMToyNVoifQ"
> [20:11:25]W:   [Step 10/10]       }
> [20:11:25]W:   [Step 10/10]    ]
> [20:11:25]W:   [Step 10/10] }'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.438086 24316 
> registry_puller.cpp:369] Fetching blob 
> 'sha256:a3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4' for 
> layer 'd8ca8144dee347ab43f0123099cc5c8d1b64b96c17da9637769519257006617e' of 
> image 'library/cirros'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.438100 24316 
> registry_puller.cpp:369] Fetching blob 
> 'sha256:b5a1edf1e076b8cd0a1befe7124b256c5757da5497a188c908d53643262047e1' for 
> layer '500e7eced838c4822a111abdb64fce8e7f3c0ecaf3d47157331b0cd30ebac4dc' of 
> image 'library/cirros'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.438109 24316 
> registry_puller.cpp:369] Fetching blob 
> 'sha256:e6cc72aea3e6702f07dc862041195b47deb7def56984860d1b4ff912fb458333' for 
> layer 'c42d375c72b4e709bc0eeda368591277fa73836dfd5597fe98e2524c8587536e' of 
> image 'library/cirros'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.438118 24316 
> registry_puller.cpp:369] Fetching blob 
> 'sha256:8c4568d4063684a72abcc5dbf16b74750d74ee600d4f520a5fad77308de9e195' for 
> layer '34fa5867b8b0888ea3b718df9ad2925b8f7f50b6583b7cbdfabd826bfe5c6de8' of 
> image 'library/cirros'
> [20:11:25]W:   [Step 10/10] I0805 20:11:25.438127 24316 
> registry_puller.cpp:369] Fetching blob 
> 'sha256:a3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4' for 
> layer '3690474eb5b4b26fdfbd89c6e159e8cc376ca76ef48032a30fa6aafd56337880' of 
> image 'library/cirros'
> [20:11:25]W:   [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/d8ca8144dee347ab43f0123099cc5c8d1b64b96c17da9637769519257006617e/rootfs'
> [20:11:25]W:   [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/500e7eced838c4822a111abdb64fce8e7f3c0ecaf3d47157331b0cd30ebac4dc/rootfs'
> [20:11:25]W:   [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/c42d375c72b4e709bc0eeda368591277fa73836dfd5597fe98e2524c8587536e/rootfs'
> [20:11:25]W:   [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/34fa5867b8b0888ea3b718df9ad2925b8f7f50b6583b7cbdfabd826bfe5c6de8/rootfs'
> [20:11:25]W:   [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/3690474eb5b4b26fdfbd89c6e159e8cc376ca76ef48032a30fa6aafd56337880/rootfs'
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.006029 24313 
> hierarchical.cpp:1734] Filtered offer with cpus(*):1; mem(*):896; 
> disk(*):1024; ports(*):[31000-32000] on agent 
> 21665992-d47e-402f-a00c-6f8fab613019-S0 for framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.006069 24313 
> hierarchical.cpp:1548] No allocations performed
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.006075 24313 
> hierarchical.cpp:1643] No inverse offers to send out!
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.006089 24313 
> hierarchical.cpp:1192] Performed allocation for 1 agents in 196593ns
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.044724 24314 
> metadata_manager.cpp:155] Successfully cached image 'cirros'
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.045126 24314 provisioner.cpp:312] 
> Provisioning image rootfs 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_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 using the 'aufs' backend
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.045382 24315 aufs.cpp:152] 
> Provisioning image rootfs with aufs: 
> 'dirs=/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/provisioner/containers/cb771051-d88d-428a-8c0b-cca24f477811/backends/aufs/scratch/6541ef43-5e41-4151-ad78-68d8b8542ed4/workdir:/tmp/mesos/store/docker/layers/d8ca8144dee347ab43f0123099cc5c8d1b64b96c17da9637769519257006617e/rootfs:/tmp/mesos/store/docker/layers/500e7eced838c4822a111abdb64fce8e7f3c0ecaf3d47157331b0cd30ebac4dc/rootfs:/tmp/mesos/store/docker/layers/c42d375c72b4e709bc0eeda368591277fa73836dfd5597fe98e2524c8587536e/rootfs:/tmp/mesos/store/docker/layers/34fa5867b8b0888ea3b718df9ad2925b8f7f50b6583b7cbdfabd826bfe5c6de8/rootfs:/tmp/mesos/store/docker/layers/3690474eb5b4b26fdfbd89c6e159e8cc376ca76ef48032a30fa6aafd56337880/rootfs'
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.052793 24316 
> containerizer.cpp:1299] Launching 'mesos-containerizer' with flags 
> '--command="{"arguments":["mesos-executor","--launcher_dir=\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src","--sandbox_directory=\/mnt\/mesos\/sandbox","--user=root","--rootfs=\/mnt\/teamcity\/temp\/buildTmp\/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf\/provisioner\/containers\/cb771051-d88d-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="false" --pipe_read="31" --pipe_write="109" 
> --pre_exec_commands="[{"arguments":["mesos-containerizer","mount","--help=false","--operation=make-rslave","--path=\/"],"shell":false,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-containerizer"},{"arguments":["mount","-n","--rbind","\/mnt\/teamcity\/temp\/buildTmp\/ProvisionerDockerPullerTest_ROOT_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","\/mnt\/teamcity\/temp\/buildTmp\/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_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="false" --user="root" 
> --working_directory="/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_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"'
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.052883 24316 
> linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWNS
> [20:11:26] :   [Step 10/10] Executing pre-exec command 
> '{"arguments":["mesos-containerizer","mount","--help=false","--operation=make-rslave","--path=\/"],"shell":false,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-containerizer"}'
> [20:11:26] :   [Step 10/10] Executing pre-exec command 
> '{"arguments":["mount","-n","--rbind","\/mnt\/teamcity\/temp\/buildTmp\/ProvisionerDockerPullerTest_ROOT_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","\/mnt\/teamcity\/temp\/buildTmp\/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf\/provisioner\/containers\/cb771051-d88d-428a-8c0b-cca24f477811\/backends\/aufs\/rootfses\/6541ef43-5e41-4151-ad78-68d8b8542ed4\/mnt\/mesos\/sandbox"],"shell":false,"value":"mount"}'
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.379375  9819 exec.cpp:162] 
> Version: 1.1.0
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.379905 24309 slave.cpp:2881] Got 
> registration for executor '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 from executor(1)@172.30.2.105:45519
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.380353  9824 exec.cpp:237] 
> Executor registered on agent 21665992-d47e-402f-a00c-6f8fab613019-S0
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.380439 24316 slave.cpp:2005] 
> Sending queued task '3b9069a1-abe8-4c37-ba1d-a84db1ee95c2' to 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] :   [Step 10/10] Received SUBSCRIBED event
> [20:11:26] :   [Step 10/10] Subscribed executor on 
> ip-172-30-2-105.mesosphere.io
> [20:11:26] :   [Step 10/10] Received LAUNCH event
> [20:11:26] :   [Step 10/10] Starting task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2
> [20:11:26] :   [Step 10/10] 
> /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer launch 
> --command="{"arguments":["test","!","-f","\/etc\/rc3.d\/S40-network"],"shell":false,"value":"\/usr\/bin\/test"}"
>  --help="false" 
> --rootfs="/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/provisioner/containers/cb771051-d88d-428a-8c0b-cca24f477811/backends/aufs/rootfses/6541ef43-5e41-4151-ad78-68d8b8542ed4"
>  --unshare_namespace_mnt="false" --user="root" 
> --working_directory="/mnt/mesos/sandbox"
> [20:11:26] :   [Step 10/10] Forked command at 9828
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.385869 24310 slave.cpp:3264] 
> Handling status update TASK_RUNNING (UUID: 
> 0f5f19fa-2bfa-45cd-9855-c34737304f52) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 from executor(1)@172.30.2.105:45519
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.386337 24315 
> status_update_manager.cpp:323] Received status update TASK_RUNNING (UUID: 
> 0f5f19fa-2bfa-45cd-9855-c34737304f52) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.386355 24315 
> status_update_manager.cpp:500] Creating StatusUpdate stream for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.386513 24315 
> status_update_manager.cpp:377] Forwarding update TASK_RUNNING (UUID: 
> 0f5f19fa-2bfa-45cd-9855-c34737304f52) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 to the agent
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.386613 24314 slave.cpp:3657] 
> Forwarding the update TASK_RUNNING (UUID: 
> 0f5f19fa-2bfa-45cd-9855-c34737304f52) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 to master@172.30.2.105:36006
> [20:11:26]W:   [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-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [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 framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 to executor(1)@172.30.2.105:45519
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.386802 24311 master.cpp:5141] 
> Status update TASK_RUNNING (UUID: 0f5f19fa-2bfa-45cd-9855-c34737304f52) for 
> 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:   [Step 10/10] I0805 20:11:26.386826 24311 master.cpp:5203] 
> Forwarding status update TASK_RUNNING (UUID: 
> 0f5f19fa-2bfa-45cd-9855-c34737304f52) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.386890 24311 master.cpp:6845] 
> Updating the state of task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 (latest state: TASK_RUNNING, status 
> update state: TASK_RUNNING)
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.386998 24315 sched.cpp:1025] 
> Scheduler::statusUpdate took 50116ns
> [20:11:26]W:   [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-6f8fab613019-0000 (default) at 
> scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2.105:36006 on agent 
> 21665992-d47e-402f-a00c-6f8fab613019-S0
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.388357 24313 
> status_update_manager.cpp:395] Received status update acknowledgement (UUID: 
> 0f5f19fa-2bfa-45cd-9855-c34737304f52) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.388425 24313 slave.cpp:2650] 
> Status update manager successfully handled status update acknowledgement 
> (UUID: 0f5f19fa-2bfa-45cd-9855-c34737304f52) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26] :   [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/6541ef43-5e41-4151-ad78-68d8b8542ed4
> [20:11:26] :   [Step 10/10] Command exited with status 1 (pid: 9828)
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.486747 24311 slave.cpp:3264] 
> Handling 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 executor(1)@172.30.2.105:45519
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.487098 24313 slave.cpp:6104] 
> Terminating task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.487478 24315 
> status_update_manager.cpp:323] Received 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
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.487525 24315 
> status_update_manager.cpp:377] Forwarding update TASK_FAILED (UUID: 
> 9a8b3240-f4f2-4457-a90f-16cbf09d134d) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 to the agent
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.487591 24314 slave.cpp:3657] 
> Forwarding the update TASK_FAILED (UUID: 
> 9a8b3240-f4f2-4457-a90f-16cbf09d134d) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 to master@172.30.2.105:36006
> [20:11:26]W:   [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-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26] :   [Step 10/10] 
> ../../src/tests/containerizer/provisioner_docker_tests.cpp:625: Failure
> [20:11:26]W:   [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 framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 to executor(1)@172.30.2.105:45519
> [20:11:26] :   [Step 10/10] Value of: statusFinished->state()
> [20:11:26] :   [Step 10/10]   Actual: TASK_FAILED
> [20:11:26]W:   [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 at slave(480)@172.30.2.105:36006 
> (ip-172-30-2-105.mesosphere.io)
> [20:11:26] :   [Step 10/10] Expected: TASK_FINISHED
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.487756 24309 master.cpp:5203] 
> Forwarding 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
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.487802 24309 master.cpp:6845] 
> Updating the state of task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 (latest state: TASK_FAILED, status 
> update state: TASK_FAILED)
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.487908 24310 sched.cpp:1025] 
> Scheduler::statusUpdate took 44522ns
> [20:11:26]W:   [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-a00c-6f8fab613019-S0 from framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [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-6f8fab613019-0000 (default) at 
> scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2.105:36006 on agent 
> 21665992-d47e-402f-a00c-6f8fab613019-S0
> [20:11:26]W:   [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 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:   [Step 10/10] I0805 20:11:26.488126 24295 sched.cpp:1987] Asked 
> to stop the driver
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.488155 24310 
> status_update_manager.cpp:395] Received status update acknowledgement (UUID: 
> 9a8b3240-f4f2-4457-a90f-16cbf09d134d) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.488179 24312 sched.cpp:1187] 
> Stopping framework 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.488198 24310 
> status_update_manager.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:   [Step 10/10] I0805 20:11:26.488283 24314 master.cpp:6304] 
> Processing TEARDOWN call for framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000 (default) at 
> scheduler-447125ed-5188-4af9-bc1d-1693d81f82e6@172.30.2.105:36006
> [20:11:26]W:   [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:   [Step 10/10] I0805 20:11:26.488351 24313 hierarchical.cpp:382] 
> Deactivated framework 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.488355 24309 slave.cpp:2650] 
> Status update manager successfully handled status update acknowledgement 
> (UUID: 9a8b3240-f4f2-4457-a90f-16cbf09d134d) for task 
> 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2 of framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.488371 24309 slave.cpp:6145] 
> Completing task 3b9069a1-abe8-4c37-ba1d-a84db1ee95c2
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.488409 24309 slave.cpp:2218] Asked 
> to shut down framework 21665992-d47e-402f-a00c-6f8fab613019-0000 by 
> master@172.30.2.105:36006
> [20:11:26]W:   [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:   [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:   [Step 10/10] I0805 20:11:26.488445 24314 hierarchical.cpp:333] 
> Removed framework 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.488981 24309 
> containerizer.cpp:1637] Destroying container 
> 'cb771051-d88d-428a-8c0b-cca24f477811'
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.489099  9822 exec.cpp:414] 
> Executor asked to shutdown
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.490057 24310 cgroups.cpp:2678] 
> Freezing cgroup 
> /sys/fs/cgroup/freezer/mesos/cb771051-d88d-428a-8c0b-cca24f477811
> [20:11:26]W:   [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:   [Step 10/10] I0805 20:11:26.492154 24311 cgroups.cpp:2696] 
> Thawing cgroup 
> /sys/fs/cgroup/freezer/mesos/cb771051-d88d-428a-8c0b-cca24f477811
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.493185 24314 cgroups.cpp:1441] 
> Successfully thawed cgroup 
> /sys/fs/cgroup/freezer/mesos/cb771051-d88d-428a-8c0b-cca24f477811 after 
> 1.014016ms
> [20:11:26]W:   [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:   [Step 10/10] I0805 20:11:26.545552 24313 
> containerizer.cpp:1878] Executor for container 
> 'cb771051-d88d-428a-8c0b-cca24f477811' has exited
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.545567 24313 
> containerizer.cpp:1633] Destroy has already been initiated for 
> 'cb771051-d88d-428a-8c0b-cca24f477811'
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.546809 24314 provisioner.cpp:455] 
> Destroying container rootfs at 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_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:   [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:   [Step 10/10] I0805 20:11:26.581300 24312 slave.cpp:4246] 
> Cleaning up 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:   [Step 10/10] I0805 20:11:26.581406 24309 gc.cpp:55] Scheduling 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_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'
>  for gc 6.99999327130667days in the future
> [20:11:26]W:   [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:   [Step 10/10] I0805 20:11:26.581456 24309 gc.cpp:55] Scheduling 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/slaves/21665992-d47e-402f-a00c-6f8fab613019-S0/frameworks/21665992-d47e-402f-a00c-6f8fab613019-0000/executors/3b9069a1-abe8-4c37-ba1d-a84db1ee95c2'
>  for gc 6.99999327068148days in the future
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.581508 24310 
> status_update_manager.cpp:285] Closing status update streams for framework 
> 21665992-d47e-402f-a00c-6f8fab613019-0000
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.581571 24316 gc.cpp:55] Scheduling 
> '/mnt/teamcity/temp/buildTmp/ProvisionerDockerPullerTest_ROOT_INTERNET_CURL_Whiteout_Aqlqpf/slaves/21665992-d47e-402f-a00c-6f8fab613019-S0/frameworks/21665992-d47e-402f-a00c-6f8fab613019-0000'
>  for gc 6.99999326983704days in the future
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.581689 24295 slave.cpp:767] Agent 
> terminating
> [20:11:26]W:   [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:36006 (ip-172-30-2-105.mesosphere.io) disconnected
> [20:11:26]W:   [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:   [Step 10/10] I0805 20:11:26.581810 24309 master.cpp:2804] 
> Deactivating 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:   [Step 10/10] I0805 20:11:26.581904 24309 hierarchical.cpp:571] 
> Agent 21665992-d47e-402f-a00c-6f8fab613019-S0 deactivated
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.583799 24295 master.cpp:1092] 
> Master terminating
> [20:11:26]W:   [Step 10/10] I0805 20:11:26.583896 24315 hierarchical.cpp:510] 
> Removed agent 21665992-d47e-402f-a00c-6f8fab613019-S0
> [20:11:26] :   [Step 10/10] [  FAILED  ] 
> ProvisionerDockerPullerTest.ROOT_INTERNET_CURL_Whiteout (1599 ms)
> {noformat}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Reply via email to