[
https://issues.apache.org/jira/browse/MESOS-5351?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15277753#comment-15277753
]
Guangya Liu commented on MESOS-5351:
------------------------------------
Set up a environment on CentOS 7.1 and the test always failed, checked the
output of {{stderr}} and {{stdout}}, found that seems the task command always
failed due to the binary cannot be found..
{code}
[root@mesos-24 latest]# cat stderr
+ /root/src/mesos/build/src/mesos-containerizer mount --help=false
--operation=make-rslave --path=/
+ mount -n --rbind
/tmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_uf7nqr/slaves/4681e398-5b36-4849-832e-382fc7a373f5-S0/frameworks/4681e398-5b36-4849-832e-382fc7a373f5-0000/executors/4c69109a-5948-4bf2-a9d9-146ea6208acc/runs/e377e445-1479-4661-852f-9c8f9d7bf036
/tmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_uf7nqr/provisioner/containers/e377e445-1479-4661-852f-9c8f9d7bf036/backends/copy/rootfses/bbb9e1db-abdf-45d0-97fa-7d8bb445533a/mnt/mesos/sandbox
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0510 03:37:24.861348 698 process.cpp:1022] libprocess is initialized on
9.21.51.124:38163 with 8 worker threads
I0510 03:37:24.861948 698 logging.cpp:195] Logging to STDERR
I0510 03:37:24.863306 698 exec.cpp:150] Version: 0.29.0
I0510 03:37:24.868268 759 exec.cpp:200] Executor started at:
executor(1)@9.21.51.124:38163 with pid 698
I0510 03:37:24.872148 758 exec.cpp:225] Executor registered on agent
4681e398-5b36-4849-832e-382fc7a373f5-S0
I0510 03:37:24.873325 758 exec.cpp:237] Executor::registered took 283799ns
I0510 03:37:24.873634 758 exec.cpp:312] Executor asked to run task
'4c69109a-5948-4bf2-a9d9-146ea6208acc'
I0510 03:37:24.873761 758 exec.cpp:321] Executor::launchTask took 100260ns
I0510 03:37:24.877316 761 exec.cpp:535] Executor sending status update
TASK_RUNNING (UUID: 7e23419c-41d5-4f58-9343-2db169d5be4c) for task
4c69109a-5948-4bf2-a9d9-146ea6208acc of framework
4681e398-5b36-4849-832e-382fc7a373f5-0000
Failed to exec: No such file or directory
I0510 03:37:24.881904 757 exec.cpp:358] Executor received status update
acknowledgement 7e23419c-41d5-4f58-9343-2db169d5be4c for task
4c69109a-5948-4bf2-a9d9-146ea6208acc of framework
4681e398-5b36-4849-832e-382fc7a373f5-0000
I0510 03:37:24.978173 756 exec.cpp:535] Executor sending status update
TASK_FAILED (UUID: 41ed123f-a7ca-4e6e-9221-bbb3f9e74967) for task
4c69109a-5948-4bf2-a9d9-146ea6208acc of framework
4681e398-5b36-4849-832e-382fc7a373f5-0000
I0510 03:37:24.984695 762 exec.cpp:358] Executor received status update
acknowledgement 41ed123f-a7ca-4e6e-9221-bbb3f9e74967 for task
4c69109a-5948-4bf2-a9d9-146ea6208acc of framework
4681e398-5b36-4849-832e-382fc7a373f5-0000
[root@mesos-24 latest]# cat stdout
Registered executor on mesos-24.eng.platformlab.ibm.com
Starting task 4c69109a-5948-4bf2-a9d9-146ea6208acc
Forked command at 765
sh -c 'test -f tmp/foo1/file1 && test -f /tmp/M4PhRu/foo2/file2;'
Command terminated with signal Aborted (pid: 765)
{code}
> DockerVolumeIsolatorTest.ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes is
> flaky
> ---------------------------------------------------------------------------------
>
> Key: MESOS-5351
> URL: https://issues.apache.org/jira/browse/MESOS-5351
> Project: Mesos
> Issue Type: Bug
> Components: test
> Environment: GCC 4.9
> CentOS 7 and Fedora 23 (Both SSL or no-SSL)
> Reporter: Joseph Wu
> Labels: flaky, mesosphere
>
> Consistently fails on Mesosphere internal CI:
> {code}
> [14:38:12] : [Step 10/10] [ RUN ]
> DockerVolumeIsolatorTest.ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes
> [14:38:12]W: [Step 10/10] I0509 14:38:12.782032 2386 cluster.cpp:149]
> Creating default 'local' authorizer
> [14:38:12]W: [Step 10/10] I0509 14:38:12.786592 2386 leveldb.cpp:174]
> Opened db in 4.462265ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.787979 2386 leveldb.cpp:181]
> Compacted db in 1.368995ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.788007 2386 leveldb.cpp:196]
> Created db iterator in 4994ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.788014 2386 leveldb.cpp:202]
> Seeked to beginning of db in 724ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.788019 2386 leveldb.cpp:271]
> Iterated through 0 keys in the db in 388ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.788031 2386 replica.cpp:779]
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [14:38:12]W: [Step 10/10] I0509 14:38:12.788249 2402 recover.cpp:447]
> Starting replica recovery
> [14:38:12]W: [Step 10/10] I0509 14:38:12.788316 2402 recover.cpp:473]
> Replica is in EMPTY status
> [14:38:12]W: [Step 10/10] I0509 14:38:12.788684 2406 replica.cpp:673]
> Replica in EMPTY status received a broadcasted recover request from
> (18057)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.788744 2405 recover.cpp:193]
> Received a recover response from a replica in EMPTY status
> [14:38:12]W: [Step 10/10] I0509 14:38:12.788869 2400 recover.cpp:564]
> Updating replica status to STARTING
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789206 2406 master.cpp:383]
> Master 6c04237d-91d6-4a05-849a-8b46fdeafe76 (ip-172-30-2-145.mesosphere.io)
> started on 172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789216 2406 master.cpp:385] Flags
> at startup: --acls="" --allocation_interval="1secs"
> --allocator="HierarchicalDRF" --authenticate="true"
> --authenticate_http="true" --authenticate_http_frameworks="true"
> --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/vepf2X/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_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
> --max_slave_ping_timeouts="5" --quiet="false"
> --recovery_slave_removal_limit="100%" --registry="replicated_log"
> --registry_fetch_timeout="1mins" --registry_store_timeout="100secs"
> --registry_strict="true" --root_submissions="true"
> --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins"
> --user_sorter="drf" --version="false"
> --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/vepf2X/master"
> --zk_session_timeout="10secs"
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789342 2406 master.cpp:434]
> Master only allowing authenticated frameworks to register
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789348 2406 master.cpp:440]
> Master only allowing authenticated agents to register
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789351 2406 master.cpp:446]
> Master only allowing authenticated HTTP frameworks to register
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789355 2406 credentials.hpp:37]
> Loading credentials for authentication from '/tmp/vepf2X/credentials'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789466 2406 master.cpp:490] Using
> default 'crammd5' authenticator
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789504 2406 master.cpp:561] Using
> default 'basic' HTTP authenticator
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789540 2406 master.cpp:641] Using
> default 'basic' HTTP framework authenticator
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789599 2406 master.cpp:688]
> Authorization enabled
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789669 2402 hierarchical.cpp:142]
> Initialized hierarchical allocator process
> [14:38:12]W: [Step 10/10] I0509 14:38:12.789691 2407
> whitelist_watcher.cpp:77] No whitelist given
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790190 2403 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.259226ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790207 2403 replica.cpp:320]
> Persisted replica status to STARTING
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790297 2406 master.cpp:1939] The
> newly elected leader is master@172.30.2.145:48816 with id
> 6c04237d-91d6-4a05-849a-8b46fdeafe76
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790312 2406 master.cpp:1952]
> Elected as the leading master!
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790315 2406 master.cpp:1639]
> Recovering from registrar
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790364 2402 registrar.cpp:331]
> Recovering registrar
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790482 2400 recover.cpp:473]
> Replica is in STARTING status
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790793 2404 replica.cpp:673]
> Replica in STARTING status received a broadcasted recover request from
> (18060)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790879 2405 recover.cpp:193]
> Received a recover response from a replica in STARTING status
> [14:38:12]W: [Step 10/10] I0509 14:38:12.790978 2402 recover.cpp:564]
> Updating replica status to VOTING
> [14:38:12]W: [Step 10/10] I0509 14:38:12.792392 2400 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.343113ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.792407 2400 replica.cpp:320]
> Persisted replica status to VOTING
> [14:38:12]W: [Step 10/10] I0509 14:38:12.792438 2400 recover.cpp:578]
> Successfully joined the Paxos group
> [14:38:12]W: [Step 10/10] I0509 14:38:12.792470 2400 recover.cpp:462]
> Recover process terminated
> [14:38:12]W: [Step 10/10] I0509 14:38:12.792583 2407 log.cpp:524]
> Attempting to start the writer
> [14:38:12]W: [Step 10/10] I0509 14:38:12.792949 2402 replica.cpp:493]
> Replica received implicit promise request from (18061)@172.30.2.145:48816
> with proposal 1
> [14:38:12]W: [Step 10/10] I0509 14:38:12.794054 2402 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.082289ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.794070 2402 replica.cpp:342]
> Persisted promised to 1
> [14:38:12]W: [Step 10/10] I0509 14:38:12.794325 2401 coordinator.cpp:238]
> Coordinator attempting to fill missing positions
> [14:38:12]W: [Step 10/10] I0509 14:38:12.794801 2402 replica.cpp:388]
> Replica received explicit promise request from (18062)@172.30.2.145:48816 for
> position 0 with proposal 2
> [14:38:12]W: [Step 10/10] I0509 14:38:12.795915 2402 leveldb.cpp:341]
> Persisting action (8 bytes) to leveldb took 1.092972ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.795931 2402 replica.cpp:712]
> Persisted action at 0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.796303 2400 replica.cpp:537]
> Replica received write request for position 0 from (18063)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.796332 2400 leveldb.cpp:436]
> Reading position from leveldb took 12054ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.798745 2400 leveldb.cpp:341]
> Persisting action (14 bytes) to leveldb took 2.394659ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.798760 2400 replica.cpp:712]
> Persisted action at 0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.798959 2407 replica.cpp:691]
> Replica received learned notice for position 0 from @0.0.0.0:0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.800093 2407 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.119267ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.800108 2407 replica.cpp:712]
> Persisted action at 0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.800114 2407 replica.cpp:697]
> Replica learned NOP action at position 0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.800267 2404 log.cpp:540] Writer
> started with ending position 0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.800516 2407 leveldb.cpp:436]
> Reading position from leveldb took 8831ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.800720 2402 registrar.cpp:364]
> Successfully fetched the registry (0B) in 10.334976ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.800751 2402 registrar.cpp:463]
> Applied 1 operations in 2855ns; attempting to update the 'registry'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.800892 2405 log.cpp:548]
> Attempting to append 210 bytes to the log
> [14:38:12]W: [Step 10/10] I0509 14:38:12.800945 2404 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 1
> [14:38:12]W: [Step 10/10] I0509 14:38:12.801174 2405 replica.cpp:537]
> Replica received write request for position 1 from (18064)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.802278 2405 leveldb.cpp:341]
> Persisting action (229 bytes) to leveldb took 1.08634ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.802294 2405 replica.cpp:712]
> Persisted action at 1
> [14:38:12]W: [Step 10/10] I0509 14:38:12.802551 2400 replica.cpp:691]
> Replica received learned notice for position 1 from @0.0.0.0:0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.803722 2400 leveldb.cpp:341]
> Persisting action (231 bytes) to leveldb took 1.153142ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.803737 2400 replica.cpp:712]
> Persisted action at 1
> [14:38:12]W: [Step 10/10] I0509 14:38:12.803742 2400 replica.cpp:697]
> Replica learned APPEND action at position 1
> [14:38:12]W: [Step 10/10] I0509 14:38:12.803958 2401 registrar.cpp:508]
> Successfully updated the 'registry' in 3.170048ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.804006 2405 log.cpp:567]
> Attempting to truncate the log to 1
> [14:38:12]W: [Step 10/10] I0509 14:38:12.804024 2401 registrar.cpp:394]
> Successfully recovered registrar
> [14:38:12]W: [Step 10/10] I0509 14:38:12.804049 2405 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 2
> [14:38:12]W: [Step 10/10] I0509 14:38:12.804193 2407 master.cpp:1747]
> Recovered 0 agents from the Registry (171B) ; allowing 10mins for agents to
> re-register
> [14:38:12]W: [Step 10/10] I0509 14:38:12.804234 2405 hierarchical.cpp:169]
> Skipping recovery of hierarchical allocator: nothing to recover
> [14:38:12]W: [Step 10/10] I0509 14:38:12.804391 2403 replica.cpp:537]
> Replica received write request for position 2 from (18065)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.805544 2403 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.134511ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.805560 2403 replica.cpp:712]
> Persisted action at 2
> [14:38:12]W: [Step 10/10] I0509 14:38:12.805785 2404 replica.cpp:691]
> Replica received learned notice for position 2 from @0.0.0.0:0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.806874 2404 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.072776ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.806902 2404 leveldb.cpp:399]
> Deleting ~1 keys from leveldb took 14198ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.806910 2404 replica.cpp:712]
> Persisted action at 2
> [14:38:12]W: [Step 10/10] I0509 14:38:12.806915 2404 replica.cpp:697]
> Replica learned TRUNCATE action at position 2
> [14:38:12]W: [Step 10/10] I0509 14:38:12.815557 2386 isolator.cpp:116]
> Initialized the docker volume information root directory at
> '/run/mesos/isolators/docker/volume'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.820333 2386
> linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
> for the Linux launcher
> [14:38:12]W: [Step 10/10] E0509 14:38:12.823923 2386 shell.hpp:106]
> Command 'hadoop version 2>&1' failed; this is the output:
> [14:38:12]W: [Step 10/10] sh: hadoop: command not found
> [14:38:12]W: [Step 10/10] I0509 14:38:12.823945 2386 fetcher.cpp:59]
> Skipping URI fetcher plugin 'hadoop' as it could not be created: Failed to
> create HDFS client: Failed to execute 'hadoop version 2>&1'; the command was
> either not found or exited with a non-zero exit status: 127
> [14:38:12]W: [Step 10/10] I0509 14:38:12.823982 2386
> registry_puller.cpp:111] Creating registry puller with docker registry
> 'https://registry-1.docker.io'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.825127 2386 cluster.cpp:398]
> Creating default 'local' authorizer
> [14:38:12]W: [Step 10/10] I0509 14:38:12.825544 2407 slave.cpp:204] Agent
> started on 465)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.825561 2407 slave.cpp:205] Flags
> at startup: --acls="" --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
> --authenticatee="crammd5" --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/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/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"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/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/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/http_credentials"
> --image_providers="docker" --image_provisioner_backend="copy"
> --initialize_driver_logging="true"
> --isolation="docker/volume,docker/runtime,filesystem/linux"
> --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs"
> --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false"
> --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true" --systemd_enable_support="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc"
> [14:38:12]W: [Step 10/10] I0509 14:38:12.825808 2407 credentials.hpp:86]
> Loading credential for authentication from
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/credential'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.825950 2407 slave.cpp:342] Agent
> using credential for: test-principal
> [14:38:12]W: [Step 10/10] I0509 14:38:12.825963 2407 credentials.hpp:37]
> Loading credentials for authentication from
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/http_credentials'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826050 2407 slave.cpp:394] Using
> default 'basic' HTTP authenticator
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826171 2407 resources.cpp:572]
> Parsing resources as JSON failed:
> cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> [14:38:12]W: [Step 10/10] Trying semicolon-delimited string format instead
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826338 2386 sched.cpp:224]
> Version: 0.29.0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826341 2407 slave.cpp:593] Agent
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826370 2407 slave.cpp:601] Agent
> attributes: [ ]
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826377 2407 slave.cpp:606] Agent
> hostname: ip-172-30-2-145.mesosphere.io
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826546 2402 sched.cpp:328] New
> master detected at master@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826577 2402 sched.cpp:384]
> Authenticating with master master@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826583 2402 sched.cpp:391] Using
> default CRAM-MD5 authenticatee
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826675 2401
> authenticatee.cpp:121] Creating new client SASL connection
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826753 2400 state.cpp:57]
> Recovering state from
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/meta'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826874 2400
> status_update_manager.cpp:200] Recovering status update manager
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826926 2401 master.cpp:5827]
> Authenticating
> scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.826967 2400
> containerizer.cpp:444] Recovering containerizer
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827055 2402
> authenticator.cpp:413] Starting authentication session for
> crammd5_authenticatee(938)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827153 2405 authenticator.cpp:98]
> Creating new server SASL connection
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827311 2405
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827335 2405
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827374 2405
> authenticator.cpp:203] Received SASL authentication start
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827409 2405
> authenticator.cpp:325] Authentication requires more steps
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827440 2405
> authenticatee.cpp:258] Received SASL authentication step
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827478 2405
> authenticator.cpp:231] Received SASL authentication step
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827497 2405 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-145.mesosphere.io' server FQDN: 'ip-172-30-2-145.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827507 2405 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827519 2405 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827527 2405 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-145.mesosphere.io' server FQDN: 'ip-172-30-2-145.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827530 2405 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827533 2405 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827541 2405
> authenticator.cpp:317] Authentication success
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827594 2403
> authenticatee.cpp:298] Authentication success
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827608 2405 master.cpp:5857]
> Successfully authenticated principal 'test-principal' at
> scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827649 2401
> authenticator.cpp:431] Authentication session cleanup for
> crammd5_authenticatee(938)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827683 2405 sched.cpp:474]
> Successfully authenticated with master master@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827702 2405 sched.cpp:783]
> Sending SUBSCRIBE call to master@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827754 2405 sched.cpp:816] Will
> retry registration in 339.972184ms if necessary
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827795 2403 master.cpp:2489]
> Received SUBSCRIBE call for framework 'default' at
> scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827811 2403 master.cpp:1978]
> Authorizing framework principal 'test-principal' to receive offers for role
> '*'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.827904 2401 master.cpp:2565]
> Subscribing framework default with checkpointing disabled and capabilities [
> ]
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828029 2403 hierarchical.cpp:264]
> Added framework 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828047 2403
> hierarchical.cpp:1488] No resources available to allocate!
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828052 2403
> hierarchical.cpp:1583] No inverse offers to send out!
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828059 2403
> hierarchical.cpp:1139] Performed allocation for 0 agents in 19973ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828116 2406 sched.cpp:710]
> Framework registered with 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828176 2406 sched.cpp:724]
> Scheduler::registered took 40802ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828383 2400
> metadata_manager.cpp:235] Successfully loaded image 'alpine'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828405 2400
> metadata_manager.cpp:235] Successfully loaded image 'library/alpine'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828409 2400
> metadata_manager.cpp:238] Successfully loaded 2 Docker images
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828488 2403 provisioner.cpp:245]
> Provisioner recovery complete
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828595 2402 slave.cpp:4801]
> Finished recovery
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828809 2402 slave.cpp:4973]
> Querying resource estimator for oversubscribable resources
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828898 2401 slave.cpp:953] New
> master detected at master@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828909 2400
> status_update_manager.cpp:174] Pausing sending status updates
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828915 2401 slave.cpp:1016]
> Authenticating with master master@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828922 2401 slave.cpp:1021] Using
> default CRAM-MD5 authenticatee
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828951 2401 slave.cpp:989]
> Detecting new master
> [14:38:12]W: [Step 10/10] I0509 14:38:12.828990 2405
> authenticatee.cpp:121] Creating new client SASL connection
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829016 2401 slave.cpp:4987]
> Received oversubscribable resources from the resource estimator
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829147 2405 master.cpp:5827]
> Authenticating slave(465)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829196 2407
> authenticator.cpp:413] Starting authentication session for
> crammd5_authenticatee(939)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829283 2404 authenticator.cpp:98]
> Creating new server SASL connection
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829448 2404
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829460 2404
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829496 2404
> authenticator.cpp:203] Received SASL authentication start
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829527 2404
> authenticator.cpp:325] Authentication requires more steps
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829556 2404
> authenticatee.cpp:258] Received SASL authentication step
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829597 2404
> authenticator.cpp:231] Received SASL authentication step
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829612 2404 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-145.mesosphere.io' server FQDN: 'ip-172-30-2-145.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829617 2404 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829623 2404 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829629 2404 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-145.mesosphere.io' server FQDN: 'ip-172-30-2-145.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829633 2404 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829637 2404 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829643 2404
> authenticator.cpp:317] Authentication success
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829685 2404
> authenticatee.cpp:298] Authentication success
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829702 2407
> authenticator.cpp:431] Authentication session cleanup for
> crammd5_authenticatee(939)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829731 2403 master.cpp:5857]
> Successfully authenticated principal 'test-principal' at
> slave(465)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829799 2404 slave.cpp:1086]
> Successfully authenticated with master master@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829849 2404 slave.cpp:1482] Will
> retry registration in 16.170354ms if necessary
> [14:38:12]W: [Step 10/10] I0509 14:38:12.829901 2400 master.cpp:4538]
> Registering agent at slave(465)@172.30.2.145:48816
> (ip-172-30-2-145.mesosphere.io) with id
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.830001 2405 registrar.cpp:463]
> Applied 1 operations in 14902ns; attempting to update the 'registry'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.830173 2402 log.cpp:548]
> Attempting to append 396 bytes to the log
> [14:38:12]W: [Step 10/10] I0509 14:38:12.830215 2402 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 3
> [14:38:12]W: [Step 10/10] I0509 14:38:12.830474 2403 replica.cpp:537]
> Replica received write request for position 3 from (18087)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.831604 2403 leveldb.cpp:341]
> Persisting action (415 bytes) to leveldb took 1.112573ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.831619 2403 replica.cpp:712]
> Persisted action at 3
> [14:38:12]W: [Step 10/10] I0509 14:38:12.831883 2405 replica.cpp:691]
> Replica received learned notice for position 3 from @0.0.0.0:0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833027 2405 leveldb.cpp:341]
> Persisting action (417 bytes) to leveldb took 1.12543ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833044 2405 replica.cpp:712]
> Persisted action at 3
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833050 2405 replica.cpp:697]
> Replica learned APPEND action at position 3
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833289 2402 registrar.cpp:508]
> Successfully updated the 'registry' in 3264us
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833343 2403 log.cpp:567]
> Attempting to truncate the log to 3
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833405 2401 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 4
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833492 2400 master.cpp:4606]
> Registered agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at
> slave(465)@172.30.2.145:48816 (ip-172-30-2-145.mesosphere.io) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833528 2401 slave.cpp:3701]
> Received ping from slave-observer(423)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833542 2403 hierarchical.cpp:473]
> Added agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0
> (ip-172-30-2-145.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (allocated: )
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833600 2401 slave.cpp:1130]
> Registered with master master@172.30.2.145:48816; given agent ID
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833614 2401 fetcher.cpp:81]
> Clearing fetcher cache
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833672 2402 replica.cpp:537]
> Replica received write request for position 4 from (18088)@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833680 2404
> status_update_manager.cpp:181] Resuming sending status updates
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833712 2403
> hierarchical.cpp:1583] No inverse offers to send out!
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833741 2403
> hierarchical.cpp:1162] Performed allocation for agent
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 in 174023ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833792 2407 master.cpp:5656]
> Sending 1 offers to framework 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> (default) at scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833830 2401 slave.cpp:1153]
> Checkpointing SlaveInfo to
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/meta/slaves/6c04237d-91d6-4a05-849a-8b46fdeafe76-S0/slave.info'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833916 2407 sched.cpp:880]
> Scheduler::resourceOffers took 30657ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.833976 2401 slave.cpp:1190]
> Forwarding total oversubscribed resources
> [14:38:12]W: [Step 10/10] I0509 14:38:12.834058 2401 master.cpp:4950]
> Received update of agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at
> slave(465)@172.30.2.145:48816 (ip-172-30-2-145.mesosphere.io) with total
> oversubscribed resources
> [14:38:12]W: [Step 10/10] I0509 14:38:12.834161 2401 hierarchical.cpp:531]
> Agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 (ip-172-30-2-145.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])
> [14:38:12]W: [Step 10/10] I0509 14:38:12.834203 2401
> hierarchical.cpp:1488] No resources available to allocate!
> [14:38:12]W: [Step 10/10] I0509 14:38:12.834209 2401
> hierarchical.cpp:1583] No inverse offers to send out!
> [14:38:12]W: [Step 10/10] I0509 14:38:12.834218 2401
> hierarchical.cpp:1162] Performed allocation for agent
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 in 29746ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.834630 2407 master.cpp:3436]
> Processing ACCEPT call for offers: [ 6c04237d-91d6-4a05-849a-8b46fdeafe76-O0
> ] on agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at
> slave(465)@172.30.2.145:48816 (ip-172-30-2-145.mesosphere.io) for framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 (default) at
> scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.834645 2407 master.cpp:3039]
> Authorizing framework principal 'test-principal' to launch task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef as user 'root'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.834841 2402 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.149625ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.834856 2402 replica.cpp:712]
> Persisted action at 4
> [14:38:12]W: [Step 10/10] I0509 14:38:12.835150 2406 replica.cpp:691]
> Replica received learned notice for position 4 from @0.0.0.0:0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.835185 2403 master.hpp:177]
> Adding task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 (ip-172-30-2-145.mesosphere.io)
> [14:38:12]W: [Step 10/10] I0509 14:38:12.835234 2403 master.cpp:3921]
> Launching task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 (default) at
> scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816 with
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at
> slave(465)@172.30.2.145:48816 (ip-172-30-2-145.mesosphere.io)
> [14:38:12]W: [Step 10/10] I0509 14:38:12.835377 2404 slave.cpp:1522] Got
> assigned task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef for framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.835459 2404 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [14:38:12]W: [Step 10/10] Trying semicolon-delimited string format instead
> [14:38:12]W: [Step 10/10] I0509 14:38:12.835605 2404 slave.cpp:1641]
> Launching task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef for framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.835641 2404 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [14:38:12]W: [Step 10/10] Trying semicolon-delimited string format instead
> [14:38:12]W: [Step 10/10] I0509 14:38:12.835974 2404 paths.cpp:528] Trying
> to chown
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/slaves/6c04237d-91d6-4a05-849a-8b46fdeafe76-S0/frameworks/6c04237d-91d6-4a05-849a-8b46fdeafe76-0000/executors/779e4a5b-0b90-45de-b343-52c2f1d4c9ef/runs/df6a5947-24bf-4178-b127-622619ba840d'
> to user 'root'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.837096 2406 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.771006ms
> [14:38:12]W: [Step 10/10] I0509 14:38:12.837159 2406 leveldb.cpp:399]
> Deleting ~2 keys from leveldb took 27609ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.837172 2406 replica.cpp:712]
> Persisted action at 4
> [14:38:12]W: [Step 10/10] I0509 14:38:12.837184 2406 replica.cpp:697]
> Replica learned TRUNCATE action at position 4
> [14:38:12]W: [Step 10/10] I0509 14:38:12.839812 2404 slave.cpp:5621]
> Launching executor 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/slaves/6c04237d-91d6-4a05-849a-8b46fdeafe76-S0/frameworks/6c04237d-91d6-4a05-849a-8b46fdeafe76-0000/executors/779e4a5b-0b90-45de-b343-52c2f1d4c9ef/runs/df6a5947-24bf-4178-b127-622619ba840d'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.839999 2404 slave.cpp:1867]
> Queuing task '779e4a5b-0b90-45de-b343-52c2f1d4c9ef' for executor
> '779e4a5b-0b90-45de-b343-52c2f1d4c9ef' of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.840021 2405
> containerizer.cpp:703] Starting container
> 'df6a5947-24bf-4178-b127-622619ba840d' for executor
> '779e4a5b-0b90-45de-b343-52c2f1d4c9ef' of framework
> '6c04237d-91d6-4a05-849a-8b46fdeafe76-0000'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.840052 2404 slave.cpp:906]
> Successfully attached file
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/slaves/6c04237d-91d6-4a05-849a-8b46fdeafe76-S0/frameworks/6c04237d-91d6-4a05-849a-8b46fdeafe76-0000/executors/779e4a5b-0b90-45de-b343-52c2f1d4c9ef/runs/df6a5947-24bf-4178-b127-622619ba840d'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.840239 2403
> metadata_manager.cpp:159] Looking for image 'alpine'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.840555 2403 provisioner.cpp:285]
> Provisioning image rootfs
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/provisioner/containers/df6a5947-24bf-4178-b127-622619ba840d/backends/copy/rootfses/f23e43e8-c72a-4c0a-9672-ea31c9f99ca6'
> for container df6a5947-24bf-4178-b127-622619ba840d
> [14:38:12]W: [Step 10/10] I0509 14:38:12.840850 2406 copy.cpp:128] Copying
> layer path
> '/tmp/mesos/store/docker/layers/0a3b5ba3277d35fc1f2d7ecbd007f1f53ca289f7674854ac7a5405e5ee3e495d/rootfs'
> to rootfs
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/provisioner/containers/df6a5947-24bf-4178-b127-622619ba840d/backends/copy/rootfses/f23e43e8-c72a-4c0a-9672-ea31c9f99ca6'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.871347 2400 linux.cpp:349]
> Ignored a volume with source for container
> 'df6a5947-24bf-4178-b127-622619ba840d'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.871361 2400 linux.cpp:349]
> Ignored a volume with source for container
> 'df6a5947-24bf-4178-b127-622619ba840d'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.872126 2406 isolator.cpp:429]
> Successfully created checkpoint at
> '/run/mesos/isolators/docker/volume/df6a5947-24bf-4178-b127-622619ba840d/volumes'
> [14:38:12]W: [Step 10/10] I0509 14:38:12.872418 2403 isolator.cpp:484]
> Mounting docker volume mount point '/tmp/vepf2X/volume1' to
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/provisioner/containers/df6a5947-24bf-4178-b127-622619ba840d/backends/copy/rootfses/f23e43e8-c72a-4c0a-9672-ea31c9f99ca6/mnt/mesos/sandbox/tmp/foo1'
> for container df6a5947-24bf-4178-b127-622619ba840d
> [14:38:12]W: [Step 10/10] I0509 14:38:12.872431 2403 isolator.cpp:484]
> Mounting docker volume mount point '/tmp/vepf2X/volume2' to
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/provisioner/containers/df6a5947-24bf-4178-b127-622619ba840d/backends/copy/rootfses/f23e43e8-c72a-4c0a-9672-ea31c9f99ca6/tmp/vepf2X/foo2'
> for container df6a5947-24bf-4178-b127-622619ba840d
> [14:38:12]W: [Step 10/10] I0509 14:38:12.873044 2407
> linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWNS
> [14:38:12]W: [Step 10/10] I0509 14:38:12.975241 2407 slave.cpp:2862] Got
> registration for executor '779e4a5b-0b90-45de-b343-52c2f1d4c9ef' of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 from executor(1)@172.30.2.145:37151
> [14:38:12]W: [Step 10/10] I0509 14:38:12.975950 2401 slave.cpp:2032]
> Sending queued task '779e4a5b-0b90-45de-b343-52c2f1d4c9ef' to executor
> '779e4a5b-0b90-45de-b343-52c2f1d4c9ef' of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 at executor(1)@172.30.2.145:37151
> [14:38:12]W: [Step 10/10] I0509 14:38:12.978395 2402 slave.cpp:3221]
> Handling status update TASK_RUNNING (UUID:
> 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 from executor(1)@172.30.2.145:37151
> [14:38:12]W: [Step 10/10] I0509 14:38:12.978792 2401
> status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
> 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.978809 2401
> status_update_manager.cpp:497] Creating StatusUpdate stream for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.978981 2401
> status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
> 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 to the agent
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979136 2403 slave.cpp:3619]
> Forwarding the update TASK_RUNNING (UUID:
> 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 to master@172.30.2.145:48816
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979229 2403 slave.cpp:3513]
> Status update manager successfully handled status update TASK_RUNNING (UUID:
> 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979250 2403 slave.cpp:3529]
> Sending acknowledgement for status update TASK_RUNNING (UUID:
> 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 to executor(1)@172.30.2.145:37151
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979293 2401 master.cpp:5095]
> Status update TASK_RUNNING (UUID: 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for
> task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 from agent
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at slave(465)@172.30.2.145:48816
> (ip-172-30-2-145.mesosphere.io)
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979317 2401 master.cpp:5143]
> Forwarding status update TASK_RUNNING (UUID:
> 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979387 2401 master.cpp:6751]
> Updating the state of task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979490 2407 sched.cpp:988]
> Scheduler::statusUpdate took 51774ns
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979609 2407 master.cpp:4250]
> Processing ACKNOWLEDGE call 601e9c7c-124a-401a-a8a3-22e1e33ba9f3 for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 (default) at
> scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816 on agent
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979913 2405
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:12]W: [Step 10/10] I0509 14:38:12.979987 2405 slave.cpp:2631]
> Status update manager successfully handled status update acknowledgement
> (UUID: 601e9c7c-124a-401a-a8a3-22e1e33ba9f3) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:13]W: [Step 10/10] I0509 14:38:13.079680 2402 slave.cpp:3221]
> Handling status update TASK_FAILED (UUID:
> e5f6521c-327b-407c-9136-b9f9b89b08dc) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 from executor(1)@172.30.2.145:37151
> [14:38:13]W: [Step 10/10] I0509 14:38:13.079962 2403 slave.cpp:5941]
> Terminating task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080392 2404
> status_update_manager.cpp:320] Received status update TASK_FAILED (UUID:
> e5f6521c-327b-407c-9136-b9f9b89b08dc) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080430 2404
> status_update_manager.cpp:374] Forwarding update TASK_FAILED (UUID:
> e5f6521c-327b-407c-9136-b9f9b89b08dc) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 to the agent
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080507 2403 slave.cpp:3619]
> Forwarding the update TASK_FAILED (UUID:
> e5f6521c-327b-407c-9136-b9f9b89b08dc) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 to master@172.30.2.145:48816
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080566 2403 slave.cpp:3513]
> Status update manager successfully handled status update TASK_FAILED (UUID:
> e5f6521c-327b-407c-9136-b9f9b89b08dc) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080585 2403 slave.cpp:3529]
> Sending acknowledgement for status update TASK_FAILED (UUID:
> e5f6521c-327b-407c-9136-b9f9b89b08dc) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 to executor(1)@172.30.2.145:37151
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080610 2402 master.cpp:5095]
> Status update TASK_FAILED (UUID: e5f6521c-327b-407c-9136-b9f9b89b08dc) for
> task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 from agent
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at slave(465)@172.30.2.145:48816
> (ip-172-30-2-145.mesosphere.io)
> [14:38:13] : [Step 10/10]
> ../../src/tests/containerizer/docker_volume_isolator_tests.cpp:954: Failure
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080628 2402 master.cpp:5143]
> Forwarding status update TASK_FAILED (UUID:
> e5f6521c-327b-407c-9136-b9f9b89b08dc) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:13] : [Step 10/10] Value of: statusFinished->state()
> [14:38:13] : [Step 10/10] Actual: TASK_FAILED
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080687 2402 master.cpp:6751]
> Updating the state of task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 (latest state: TASK_FAILED, status
> update state: TASK_FAILED)
> [14:38:13] : [Step 10/10] Expected: TASK_FINISHED
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080750 2407 sched.cpp:988]
> Scheduler::statusUpdate took 28345ns
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080843 2402 master.cpp:4250]
> Processing ACKNOWLEDGE call e5f6521c-327b-407c-9136-b9f9b89b08dc for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 (default) at
> scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816 on agent
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080868 2402 master.cpp:6817]
> Removing task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 on agent
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at slave(465)@172.30.2.145:48816
> (ip-172-30-2-145.mesosphere.io)
> [14:38:13]W: [Step 10/10] I0509 14:38:13.080904 2406 hierarchical.cpp:891]
> Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000],
> allocated: ) on agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 from framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:13]W: [Step 10/10] I0509 14:38:13.081069 2406
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> e5f6521c-327b-407c-9136-b9f9b89b08dc) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:13]W: [Step 10/10] I0509 14:38:13.081104 2406
> status_update_manager.cpp:528] Cleaning up status update stream for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:13]W: [Step 10/10] I0509 14:38:13.081166 2406 slave.cpp:2631]
> Status update manager successfully handled status update acknowledgement
> (UUID: e5f6521c-327b-407c-9136-b9f9b89b08dc) for task
> 779e4a5b-0b90-45de-b343-52c2f1d4c9ef of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:13]W: [Step 10/10] I0509 14:38:13.081177 2406 slave.cpp:5982]
> Completing task 779e4a5b-0b90-45de-b343-52c2f1d4c9ef
> [14:38:13]W: [Step 10/10] I0509 14:38:13.790751 2407
> hierarchical.cpp:1583] No inverse offers to send out!
> [14:38:13]W: [Step 10/10] I0509 14:38:13.790789 2407
> hierarchical.cpp:1139] Performed allocation for 1 agents in 214050ns
> [14:38:13]W: [Step 10/10] I0509 14:38:13.790892 2405 master.cpp:5656]
> Sending 1 offers to framework 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> (default) at scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816
> [14:38:13]W: [Step 10/10] I0509 14:38:13.791057 2405 sched.cpp:880]
> Scheduler::resourceOffers took 10632ns
> [14:38:14]W: [Step 10/10] I0509 14:38:14.081109 2406 slave.cpp:3747]
> executor(1)@172.30.2.145:37151 exited
> [14:38:14]W: [Step 10/10] I0509 14:38:14.176753 2407
> containerizer.cpp:1731] Executor for container
> 'df6a5947-24bf-4178-b127-622619ba840d' has exited
> [14:38:14]W: [Step 10/10] I0509 14:38:14.176774 2407
> containerizer.cpp:1495] Destroying container
> 'df6a5947-24bf-4178-b127-622619ba840d'
> [14:38:14]W: [Step 10/10] I0509 14:38:14.178449 2402 cgroups.cpp:2676]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos/df6a5947-24bf-4178-b127-622619ba840d
> [14:38:14]W: [Step 10/10] I0509 14:38:14.179882 2403 cgroups.cpp:1409]
> Successfully froze cgroup
> /sys/fs/cgroup/freezer/mesos/df6a5947-24bf-4178-b127-622619ba840d after
> 1.405952ms
> [14:38:14]W: [Step 10/10] I0509 14:38:14.181386 2406 cgroups.cpp:2694]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos/df6a5947-24bf-4178-b127-622619ba840d
> [14:38:14]W: [Step 10/10] I0509 14:38:14.182862 2404 cgroups.cpp:1438]
> Successfully thawed cgroup
> /sys/fs/cgroup/freezer/mesos/df6a5947-24bf-4178-b127-622619ba840d after
> 1.45792ms
> [14:38:14]W: [Step 10/10] I0509 14:38:14.183701 2403 isolator.cpp:557]
> Unmounting the volume with driver 'driver2' and name 'name2' for container
> df6a5947-24bf-4178-b127-622619ba840d
> [14:38:14]W: [Step 10/10] I0509 14:38:14.183745 2403 isolator.cpp:557]
> Unmounting the volume with driver 'driver1' and name 'name1' for container
> df6a5947-24bf-4178-b127-622619ba840d
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184124 2386 sched.cpp:1911] Asked
> to stop the driver
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184159 2403 isolator.cpp:601]
> Removed the checkpoint directory at
> '/run/mesos/isolators/docker/volume/df6a5947-24bf-4178-b127-622619ba840d' for
> container df6a5947-24bf-4178-b127-622619ba840d
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184202 2402 sched.cpp:1150]
> Stopping framework '6c04237d-91d6-4a05-849a-8b46fdeafe76-0000'
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184391 2403 master.cpp:6224]
> Processing TEARDOWN call for framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 (default) at
> scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184406 2403 master.cpp:6236]
> Removing framework 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 (default) at
> scheduler-9cdbd508-f19c-436d-a4cb-805ab1f9b055@172.30.2.145:48816
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184528 2402 slave.cpp:2252] Asked
> to shut down framework 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 by
> master@172.30.2.145:48816
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184545 2402 slave.cpp:2277]
> Shutting down framework 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184552 2402 slave.cpp:4426]
> Shutting down executor '779e4a5b-0b90-45de-b343-52c2f1d4c9ef' of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 at executor(1)@172.30.2.145:37151
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184628 2405 hierarchical.cpp:375]
> Deactivated framework 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184746 2405 hierarchical.cpp:891]
> Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000],
> allocated: ) on agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 from framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184839 2408 poll_socket.cpp:131]
> Socket error while connecting
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184859 2408 process.cpp:1667]
> Failed to send 'mesos.internal.ShutdownExecutorMessage' to
> '172.30.2.145:37151', connect: Socket error while connecting
> [14:38:14]W: [Step 10/10] I0509 14:38:14.184866 2405 hierarchical.cpp:326]
> Removed framework 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:14]W: [Step 10/10] E0509 14:38:14.184883 2408 process.cpp:1975]
> Failed to shutdown socket with fd 95: Transport endpoint is not connected
> [14:38:14]W: [Step 10/10] I0509 14:38:14.185200 2406 provisioner.cpp:338]
> Destroying container rootfs at
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/provisioner/containers/df6a5947-24bf-4178-b127-622619ba840d/backends/copy/rootfses/f23e43e8-c72a-4c0a-9672-ea31c9f99ca6'
> for container df6a5947-24bf-4178-b127-622619ba840d
> [14:38:14]W: [Step 10/10] I0509 14:38:14.277624 2407 slave.cpp:4108]
> Executor '779e4a5b-0b90-45de-b343-52c2f1d4c9ef' of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 exited with status 0
> [14:38:14]W: [Step 10/10] I0509 14:38:14.277642 2407 slave.cpp:4212]
> Cleaning up executor '779e4a5b-0b90-45de-b343-52c2f1d4c9ef' of framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000 at executor(1)@172.30.2.145:37151
> [14:38:14]W: [Step 10/10] I0509 14:38:14.277740 2407 slave.cpp:4300]
> Cleaning up framework 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:14]W: [Step 10/10] I0509 14:38:14.277750 2405 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/slaves/6c04237d-91d6-4a05-849a-8b46fdeafe76-S0/frameworks/6c04237d-91d6-4a05-849a-8b46fdeafe76-0000/executors/779e4a5b-0b90-45de-b343-52c2f1d4c9ef/runs/df6a5947-24bf-4178-b127-622619ba840d'
> for gc 6.99999678598518days in the future
> [14:38:14]W: [Step 10/10] I0509 14:38:14.277809 2405 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/slaves/6c04237d-91d6-4a05-849a-8b46fdeafe76-S0/frameworks/6c04237d-91d6-4a05-849a-8b46fdeafe76-0000/executors/779e4a5b-0b90-45de-b343-52c2f1d4c9ef'
> for gc 6.99999678555556days in the future
> [14:38:14]W: [Step 10/10] I0509 14:38:14.277815 2401
> status_update_manager.cpp:282] Closing status update streams for framework
> 6c04237d-91d6-4a05-849a-8b46fdeafe76-0000
> [14:38:14]W: [Step 10/10] I0509 14:38:14.277851 2405 gc.cpp:55] Scheduling
> '/mnt/teamcity/temp/buildTmp/DockerVolumeIsolatorTest_ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes_MBxVbc/slaves/6c04237d-91d6-4a05-849a-8b46fdeafe76-S0/frameworks/6c04237d-91d6-4a05-849a-8b46fdeafe76-0000'
> for gc 6.99999678499852days in the future
> [14:38:14]W: [Step 10/10] I0509 14:38:14.278050 2403 slave.cpp:825] Agent
> terminating
> [14:38:14]W: [Step 10/10] I0509 14:38:14.278107 2403 master.cpp:1343]
> Agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at
> slave(465)@172.30.2.145:48816 (ip-172-30-2-145.mesosphere.io) disconnected
> [14:38:14]W: [Step 10/10] I0509 14:38:14.278120 2403 master.cpp:2849]
> Disconnecting agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at
> slave(465)@172.30.2.145:48816 (ip-172-30-2-145.mesosphere.io)
> [14:38:14]W: [Step 10/10] I0509 14:38:14.278143 2403 master.cpp:2868]
> Deactivating agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 at
> slave(465)@172.30.2.145:48816 (ip-172-30-2-145.mesosphere.io)
> [14:38:14]W: [Step 10/10] I0509 14:38:14.278221 2402 hierarchical.cpp:560]
> Agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0 deactivated
> [14:38:14]W: [Step 10/10] I0509 14:38:14.280328 2386 master.cpp:1190]
> Master terminating
> [14:38:14]W: [Step 10/10] I0509 14:38:14.280412 2401 hierarchical.cpp:505]
> Removed agent 6c04237d-91d6-4a05-849a-8b46fdeafe76-S0
> [14:38:14] : [Step 10/10] [ FAILED ]
> DockerVolumeIsolatorTest.ROOT_INTERNET_CURL_CommandTaskRootfsWithVolumes
> (1501 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
