Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
None
-
Ubuntu 14, Ubuntu 12
Or any os with aufs module
Description
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.
[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 \\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\":\"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 \\u003ceric@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 \\u003ceric@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 \\u003ceric@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 \\u003ceric@windisch.us\\u003e\"]},\"author\":\"Eric Windisch \\u003ceric@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)