Gilbert Song created MESOS-9371:
-----------------------------------
Summary: `FetcherCacheTest.RemoveLRUCacheEntries` is flaky.
Key: MESOS-9371
URL: https://issues.apache.org/jira/browse/MESOS-9371
Project: Mesos
Issue Type: Bug
Reporter: Gilbert Song
{noformat}
[ RUN ] FetcherCacheTest.RemoveLRUCacheEntries
I1107 13:20:28.161957 39728 cluster.cpp:172] Creating default 'local' authorizer
I1107 13:20:28.165024 39777 master.cpp:457] Master
f7977f54-bb98-445f-9610-ede08bf34093 (core-dev) started on 10.0.49.2:41973
I1107 13:20:28.165122 39777 master.cpp:459] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --allocator="hierarchical"
--authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authentication_v0_timeout="15secs"
--authenticators="crammd5" --authorizers="local"
--credentials="/tmp/ds9Byj/credentials" --filter_gpu_resources="true"
--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"
--max_unreachable_tasks_per_framework="1000"
--min_allocatable_resources="cpus:0.01|mem:32" --port="5050" --quiet="false"
--recovery_agent_removal_limit="100%" --registry="in_memory"
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins"
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400"
--registry_store_timeout="100secs" --registry_strict="false"
--require_agent_domain="false" --role_sorter="drf" --root_submissions="true"
--version="false" --webui_dir="/usr/local/share/mesos/webui"
--work_dir="/tmp/ds9Byj/master" --zk_session_timeout="10secs"
I1107 13:20:28.169046 39777 master.cpp:508] Master only allowing authenticated
frameworks to register
I1107 13:20:28.169070 39777 master.cpp:514] Master only allowing authenticated
agents to register
I1107 13:20:28.169093 39777 master.cpp:520] Master only allowing authenticated
HTTP frameworks to register
I1107 13:20:28.169121 39777 credentials.hpp:37] Loading credentials for
authentication from '/tmp/ds9Byj/credentials'
I1107 13:20:28.169910 39777 master.cpp:564] Using default 'crammd5'
authenticator
I1107 13:20:28.170156 39777 authenticator.cpp:520] Initializing server SASL
I1107 13:20:28.171118 39777 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1107 13:20:28.171545 39777 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1107 13:20:28.171684 39777 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1107 13:20:28.171854 39777 master.cpp:643] Authorization enabled
I1107 13:20:28.185091 39744 master.cpp:2247] Elected as the leading master!
I1107 13:20:28.185139 39744 master.cpp:1727] Recovering from registrar
I1107 13:20:28.188170 39752 registrar.cpp:391] Successfully fetched the
registry (0B) in 2.571008ms
I1107 13:20:28.188540 39752 registrar.cpp:495] Applied 1 operations in
122344ns; attempting to update the registry
I1107 13:20:28.191902 39752 registrar.cpp:552] Successfully updated the
registry in 3.163904ms
I1107 13:20:28.192203 39752 registrar.cpp:424] Successfully recovered registrar
I1107 13:20:28.193151 39756 master.cpp:1840] Recovered 0 agents from the
registry (123B); allowing 10mins for agents to re-register
I1107 13:20:28.194456 39728 containerizer.cpp:304] Using isolation {
environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W1107 13:20:28.195065 39728 backend.cpp:76] Failed to create 'overlay' backend:
OverlayBackend requires root privileges
W1107 13:20:28.195108 39728 backend.cpp:76] Failed to create 'bind' backend:
BindBackend requires root privileges
I1107 13:20:28.195156 39728 provisioner.cpp:299] Using default backend 'copy'
W1107 13:20:28.198040 39728 process.cpp:2745] Attempted to spawn already
running process [email protected]:41973
I1107 13:20:28.198199 39728 cluster.cpp:460] Creating default 'local' authorizer
I1107 13:20:28.199762 39789 slave.cpp:261] Mesos agent started on
(1)@10.0.49.2:41973
I1107 13:20:28.199816 39789 slave.cpp:262] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi/store/appc"
--authenticate_http_readonly="true" --authenticate_http_readwrite="false"
--authenticatee="crammd5" --authentication_backoff_factor="1secs"
--authentication_timeout_max="1mins" --authentication_timeout_min="5secs"
--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="/tmp/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi/credential"
--default_role="*" --disallow_sharing_agent_pid_namespace="false"
--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/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_reregistration_timeout="2secs"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi/fetch"
--fetcher_cache_size="60B" --fetcher_stall_timeout="1mins" --frameworks_home=""
--gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
--hostname_lookup="true" --http_command_executor="false"
--http_credentials="/tmp/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem" --launcher="posix"
--launcher_dir="/home/gilbert/mesos/build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns"
--quiet="false" --reconfiguration_policy="equal" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:1000;mem:1000" --revocable_cpu_low_priority="true"
--runtime_dir="/tmp/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i"
--zk_session_timeout="10secs"
I1107 13:20:28.200455 39789 credentials.hpp:86] Loading credential for
authentication from
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi/credential'
I1107 13:20:28.200681 39789 slave.cpp:294] Agent using credential for:
test-principal
I1107 13:20:28.200724 39789 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi/http_credentials'
I1107 13:20:28.200971 39789 http.cpp:1045] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1107 13:20:28.202383 39789 slave.cpp:611] Agent resources:
[{"name":"cpus","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":46053.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I1107 13:20:28.202714 39789 slave.cpp:619] Agent attributes: [ ]
I1107 13:20:28.202750 39789 slave.cpp:628] Agent hostname: core-dev
I1107 13:20:28.203182 39743 task_status_update_manager.cpp:181] Pausing sending
task status updates
I1107 13:20:28.206714 39755 state.cpp:66] Recovering state from
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/meta'
I1107 13:20:28.207412 39750 task_status_update_manager.cpp:207] Recovering task
status update manager
I1107 13:20:28.207798 39757 containerizer.cpp:674] Recovering containerizer
I1107 13:20:28.211381 39766 provisioner.cpp:495] Provisioner recovery complete
I1107 13:20:28.212124 39771 slave.cpp:7330] Finished recovery
I1107 13:20:28.213066 39772 task_status_update_manager.cpp:181] Pausing sending
task status updates
I1107 13:20:28.213106 39771 slave.cpp:1262] New master detected at
[email protected]:41973
I1107 13:20:28.213232 39771 slave.cpp:1327] Detecting new master
I1107 13:20:28.218950 39778 slave.cpp:1354] Authenticating with master
[email protected]:41973
I1107 13:20:28.219066 39778 slave.cpp:1363] Using default CRAM-MD5 authenticatee
I1107 13:20:28.219641 39775 authenticatee.cpp:97] Initializing client SASL
I1107 13:20:28.219825 39775 authenticatee.cpp:121] Creating new client SASL
connection
I1107 13:20:28.220322 39780 master.cpp:9059] Authenticating
slave(1)@10.0.49.2:41973
I1107 13:20:28.221060 39782 authenticator.cpp:98] Creating new server SASL
connection
I1107 13:20:28.221434 39783 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1107 13:20:28.221490 39783 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1107 13:20:28.221662 39787 authenticator.cpp:204] Received SASL authentication
start
I1107 13:20:28.221809 39787 authenticator.cpp:326] Authentication requires more
steps
I1107 13:20:28.221963 39787 authenticatee.cpp:259] Received SASL authentication
step
I1107 13:20:28.222141 39747 authenticator.cpp:232] Received SASL authentication
step
I1107 13:20:28.222296 39747 authenticator.cpp:318] Authentication success
I1107 13:20:28.222481 39777 authenticatee.cpp:299] Authentication success
I1107 13:20:28.222745 39785 master.cpp:9091] Successfully authenticated
principal 'test-principal' at slave(1)@10.0.49.2:41973
I1107 13:20:28.222930 39784 slave.cpp:1454] Successfully authenticated with
master [email protected]:41973
I1107 13:20:28.223770 39746 master.cpp:6146] Received register agent message
from slave(1)@10.0.49.2:41973 (core-dev)
I1107 13:20:28.223964 39746 master.cpp:3911] Authorizing agent with principal
'test-principal'
I1107 13:20:28.225159 39753 master.cpp:6315] Registering agent at
slave(1)@10.0.49.2:41973 (core-dev) with id
f7977f54-bb98-445f-9610-ede08bf34093-S0
I1107 13:20:28.226071 39751 registrar.cpp:495] Applied 1 operations in
234510ns; attempting to update the registry
I1107 13:20:28.228108 39751 registrar.cpp:552] Successfully updated the
registry in 1.930752ms
I1107 13:20:28.229776 39761 master.cpp:6412] Registered agent
f7977f54-bb98-445f-9610-ede08bf34093-S0 at slave(1)@10.0.49.2:41973 (core-dev)
with cpus:1000; mem:1000; disk:46053; ports:[31000-32000]
I1107 13:20:28.230113 39762 slave.cpp:1486] Registered with master
[email protected]:41973; given agent ID f7977f54-bb98-445f-9610-ede08bf34093-S0
I1107 13:20:28.230247 39756 task_status_update_manager.cpp:188] Resuming
sending task status updates
I1107 13:20:28.230576 39760 hierarchical.cpp:576] Added agent
f7977f54-bb98-445f-9610-ede08bf34093-S0 (core-dev) with cpus:1000; mem:1000;
disk:46053; ports:[31000-32000] (allocated: {})
I1107 13:20:28.231068 39728 sched.cpp:232] Version: 1.5.2
I1107 13:20:28.231282 39762 slave.cpp:1553] Forwarding agent update
{"operations":{},"resource_version_uuid":{"value":"R\/u701ANQpKRXrXDq+uQog=="},"slave_id":{"value":"f7977f54-bb98-445f-9610-ede08bf34093-S0"},"update_oversubscribed_resources":true}
I1107 13:20:28.231889 39774 master.cpp:7339] Received update of agent
f7977f54-bb98-445f-9610-ede08bf34093-S0 at slave(1)@10.0.49.2:41973 (core-dev)
with total oversubscribed resources {}
I1107 13:20:28.232173 39776 sched.cpp:336] New master detected at
[email protected]:41973
I1107 13:20:28.232216 39774 master.cpp:7433] Ignoring update on agent
f7977f54-bb98-445f-9610-ede08bf34093-S0 at slave(1)@10.0.49.2:41973 (core-dev)
as it reports no changes
I1107 13:20:28.232291 39776 sched.cpp:401] Authenticating with master
[email protected]:41973
I1107 13:20:28.232326 39776 sched.cpp:408] Using default CRAM-MD5 authenticatee
I1107 13:20:28.232530 39771 authenticatee.cpp:121] Creating new client SASL
connection
I1107 13:20:28.232861 39778 master.cpp:9059] Authenticating
[email protected]:41973
I1107 13:20:28.233188 39780 authenticator.cpp:98] Creating new server SASL
connection
I1107 13:20:28.233477 39786 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1107 13:20:28.233522 39786 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1107 13:20:28.233618 39786 authenticator.cpp:204] Received SASL authentication
start
I1107 13:20:28.233675 39786 authenticator.cpp:326] Authentication requires more
steps
I1107 13:20:28.233758 39786 authenticatee.cpp:259] Received SASL authentication
step
I1107 13:20:28.233881 39788 authenticator.cpp:232] Received SASL authentication
step
I1107 13:20:28.233960 39788 authenticator.cpp:318] Authentication success
I1107 13:20:28.234045 39787 authenticatee.cpp:299] Authentication success
I1107 13:20:28.234163 39745 master.cpp:9091] Successfully authenticated
principal 'test-principal' at
[email protected]:41973
I1107 13:20:28.234391 39747 sched.cpp:514] Successfully authenticated with
master [email protected]:41973
I1107 13:20:28.234825 39784 master.cpp:3002] Received SUBSCRIBE call for
framework 'default' at
[email protected]:41973
W1107 13:20:28.234877 39784 master.cpp:3010] Setting 'principal' in
FrameworkInfo to 'test-principal' because the framework authenticated with that
principal but did not set it in FrameworkInfo
I1107 13:20:28.234912 39784 master.cpp:2319] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
I1107 13:20:28.235620 39749 master.cpp:3082] Subscribing framework default with
checkpointing enabled and capabilities [ ]
I1107 13:20:28.236039 39749 master.cpp:9289] Adding framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973 with roles { }
suppressed
I1107 13:20:28.236717 39749 sched.cpp:746] Framework registered with
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.237150 39753 hierarchical.cpp:299] Added framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.239576 39755 master.cpp:8893] Sending 1 offers to framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:28.242939 39756 master.cpp:10830] Removing offer
f7977f54-bb98-445f-9610-ede08bf34093-O0
I1107 13:20:28.243361 39756 master.cpp:4330] Processing ACCEPT call for offers:
[ f7977f54-bb98-445f-9610-ede08bf34093-O0 ] on agent
f7977f54-bb98-445f-9610-ede08bf34093-S0 at slave(1)@10.0.49.2:41973 (core-dev)
for framework f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:28.243461 39756 master.cpp:3638] Authorizing framework principal
'test-principal' to launch task 0
I1107 13:20:28.245926 39760 master.cpp:11588] Adding task 0 with resources
cpus(allocated: *):1; mem(allocated: *):1 on agent
f7977f54-bb98-445f-9610-ede08bf34093-S0 at slave(1)@10.0.49.2:41973 (core-dev)
I1107 13:20:28.246232 39760 master.cpp:5090] Launching task 0 of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":1.0},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":1.0},"type":"SCALAR"}]
on agent f7977f54-bb98-445f-9610-ede08bf34093-S0 at slave(1)@10.0.49.2:41973
(core-dev) on new executor
I1107 13:20:28.247491 39770 slave.cpp:2021] Got assigned task '0' for framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.250591 39770 slave.cpp:2395] Authorizing task '0' for framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.250668 39770 slave.cpp:8447] Authorizing framework principal
'test-principal' to launch task 0
I1107 13:20:28.252602 39776 slave.cpp:2869] Launching task '0' for framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.254923 39776 paths.cpp:756] Trying to chown
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/b0c1d94a-5bfe-443d-b284-be33a81924e7'
to user 'gilbert'
I1107 13:20:28.256227 39776 slave.cpp:8938] Launching executor '0' of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 with resources
[{"allocation_info":{"role":"*"},"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"allocation_info":{"role":"*"},"name":"mem","scalar":{"value":32.0},"type":"SCALAR"}]
in work directory
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/b0c1d94a-5bfe-443d-b284-be33a81924e7'
I1107 13:20:28.257133 39776 slave.cpp:3565] Launching container
b0c1d94a-5bfe-443d-b284-be33a81924e7 for executor '0' of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.258895 39776 slave.cpp:3085] Queued task '0' for executor '0' of
framework f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.259526 39775 containerizer.cpp:1209] Starting container
b0c1d94a-5bfe-443d-b284-be33a81924e7
I1107 13:20:28.262679 39775 containerizer.cpp:2993] Transitioning the state of
container b0c1d94a-5bfe-443d-b284-be33a81924e7 from PROVISIONING to PREPARING
I1107 13:20:28.272727 39743 launcher.cpp:151] Forked child with pid '39804' for
container 'b0c1d94a-5bfe-443d-b284-be33a81924e7'
I1107 13:20:28.273000 39743 containerizer.cpp:1965] Checkpointing container's
forked pid 39804 to
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/meta/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/b0c1d94a-5bfe-443d-b284-be33a81924e7/pids/forked.pid'
I1107 13:20:28.274046 39743 containerizer.cpp:2993] Transitioning the state of
container b0c1d94a-5bfe-443d-b284-be33a81924e7 from PREPARING to ISOLATING
I1107 13:20:28.275709 39743 containerizer.cpp:2993] Transitioning the state of
container b0c1d94a-5bfe-443d-b284-be33a81924e7 from ISOLATING to FETCHING
W1107 13:20:28.416662 39773 fetcher.cpp:912] Begin fetcher log (stderr in
sandbox) for container b0c1d94a-5bfe-443d-b284-be33a81924e7 from running
command: /home/gilbert/mesos/build/src/mesos-fetcher
I1107 13:20:28.373706 39811 fetcher.cpp:560] Fetcher Info:
{"cache_directory":"\/tmp\/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi\/fetch\/gilbert","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-cmd0","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i\/mesos-fetcher-test-assets\/cmd0"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i\/slaves\/f7977f54-bb98-445f-9610-ede08bf34093-S0\/frameworks\/f7977f54-bb98-445f-9610-ede08bf34093-0000\/executors\/0\/runs\/b0c1d94a-5bfe-443d-b284-be33a81924e7","stall_timeout":{"nanoseconds":60000000000},"user":"gilbert"}
I1107 13:20:28.384097 39811 fetcher.cpp:457] Fetching URI
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/mesos-fetcher-test-assets/cmd0'
I1107 13:20:28.384130 39811 fetcher.cpp:431] Downloading into cache
I1107 13:20:28.384142 39811 fetcher.cpp:227] Fetching URI
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/mesos-fetcher-test-assets/cmd0'
I1107 13:20:28.386828 39811 fetcher.cpp:351] Fetching from cache
I1107 13:20:28.389147 39811 fetcher.cpp:617] Fetched
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/mesos-fetcher-test-assets/cmd0'
to
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/b0c1d94a-5bfe-443d-b284-be33a81924e7/cmd0'
I1107 13:20:28.389169 39811 fetcher.cpp:622] Successfully fetched all URIs into
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/b0c1d94a-5bfe-443d-b284-be33a81924e7'
End fetcher log for container b0c1d94a-5bfe-443d-b284-be33a81924e7
E1107 13:20:28.416877 39773 fetcher.cpp:571] Failed to run mesos-fetcher: No
status available from mesos-fetcher
Failed to synchronize with agent (it's probably exited)
E1107 13:20:28.417824 39762 slave.cpp:6204] Container
'b0c1d94a-5bfe-443d-b284-be33a81924e7' for executor '0' of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 failed to start: No status available
from mesos-fetcher
I1107 13:20:28.418114 39769 containerizer.cpp:2375] Destroying container
b0c1d94a-5bfe-443d-b284-be33a81924e7 in FETCHING state
I1107 13:20:28.418174 39769 containerizer.cpp:2993] Transitioning the state of
container b0c1d94a-5bfe-443d-b284-be33a81924e7 from FETCHING to DESTROYING
I1107 13:20:28.419108 39769 launcher.cpp:167] Asked to destroy container
b0c1d94a-5bfe-443d-b284-be33a81924e7
I1107 13:20:28.517963 39779 containerizer.cpp:2832] Container
b0c1d94a-5bfe-443d-b284-be33a81924e7 has exited
I1107 13:20:28.522321 39758 slave.cpp:6333] Executor '0' of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 exited with status 1
I1107 13:20:28.524320 39758 slave.cpp:5311] Handling status update TASK_FAILED
(Status UUID: 7e2d6619-93b2-45de-8508-f945ad86de2a) for task 0 of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 from @0.0.0.0:0
W1107 13:20:28.525140 39755 containerizer.cpp:2177] Ignoring update for unknown
container b0c1d94a-5bfe-443d-b284-be33a81924e7
I1107 13:20:28.525960 39750 task_status_update_manager.cpp:328] Received task
status update TASK_FAILED (Status UUID: 7e2d6619-93b2-45de-8508-f945ad86de2a)
for task 0 of framework f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.526929 39750 task_status_update_manager.cpp:842] Checkpointing
UPDATE for task status update TASK_FAILED (Status UUID:
7e2d6619-93b2-45de-8508-f945ad86de2a) for task 0 of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.527523 39757 slave.cpp:5803] Forwarding the update TASK_FAILED
(Status UUID: 7e2d6619-93b2-45de-8508-f945ad86de2a) for task 0 of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 to [email protected]:41973
I1107 13:20:28.527943 39750 master.cpp:7985] Status update TASK_FAILED (Status
UUID: 7e2d6619-93b2-45de-8508-f945ad86de2a) for task 0 of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 from agent
f7977f54-bb98-445f-9610-ede08bf34093-S0 at slave(1)@10.0.49.2:41973 (core-dev)
I1107 13:20:28.528023 39750 master.cpp:8041] Forwarding status update
TASK_FAILED (Status UUID: 7e2d6619-93b2-45de-8508-f945ad86de2a) for task 0 of
framework f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.528257 39750 master.cpp:10313] Updating the state of task 0 of
framework f7977f54-bb98-445f-9610-ede08bf34093-0000 (latest state: TASK_FAILED,
status update state: TASK_FAILED)
I1107 13:20:28.529274 39750 master.cpp:5914] Processing ACKNOWLEDGE call
7e2d6619-93b2-45de-8508-f945ad86de2a for task 0 of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973 on agent
f7977f54-bb98-445f-9610-ede08bf34093-S0
I1107 13:20:28.529394 39750 master.cpp:10417] Removing task 0 with resources
cpus(allocated: *):1; mem(allocated: *):1 of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 on agent
f7977f54-bb98-445f-9610-ede08bf34093-S0 at slave(1)@10.0.49.2:41973 (core-dev)
I1107 13:20:28.530251 39763 task_status_update_manager.cpp:401] Received task
status update acknowledgement (UUID: 7e2d6619-93b2-45de-8508-f945ad86de2a) for
task 0 of framework f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.530354 39763 task_status_update_manager.cpp:842] Checkpointing
ACK for task status update TASK_FAILED (Status UUID:
7e2d6619-93b2-45de-8508-f945ad86de2a) for task 0 of framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.531067 39756 slave.cpp:6431] Cleaning up executor '0' of
framework f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.531690 39767 gc.cpp:95] Scheduling
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/b0c1d94a-5bfe-443d-b284-be33a81924e7'
for gc 6.99999384877333days in the future
I1107 13:20:28.531982 39767 gc.cpp:95] Scheduling
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0'
for gc 6.99999384428444days in the future
I1107 13:20:28.532151 39756 slave.cpp:6560] Cleaning up framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.532166 39767 gc.cpp:95] Scheduling
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/meta/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/b0c1d94a-5bfe-443d-b284-be33a81924e7'
for gc 6.99999384350815days in the future
I1107 13:20:28.532282 39767 gc.cpp:95] Scheduling
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/meta/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0'
for gc 6.99999384303407days in the future
I1107 13:20:28.532343 39760 task_status_update_manager.cpp:289] Closing task
status update streams for framework f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:28.532397 39767 gc.cpp:95] Scheduling
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000'
for gc 6.99999383965333days in the future
I1107 13:20:28.532516 39767 gc.cpp:95] Scheduling
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/meta/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000'
for gc 6.99999383915556days in the future
I1107 13:20:29.175374 39771 master.cpp:8893] Sending 1 offers to framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:29.176127 39781 master.cpp:5555] Processing DECLINE call for
offers: [ f7977f54-bb98-445f-9610-ede08bf34093-O1 ] for framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:29.176542 39781 master.cpp:10830] Removing offer
f7977f54-bb98-445f-9610-ede08bf34093-O1
I1107 13:20:34.184898 39754 master.cpp:8893] Sending 1 offers to framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:34.185727 39788 master.cpp:5555] Processing DECLINE call for
offers: [ f7977f54-bb98-445f-9610-ede08bf34093-O2 ] for framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:34.186174 39788 master.cpp:10830] Removing offer
f7977f54-bb98-445f-9610-ede08bf34093-O2
I1107 13:20:39.191220 39758 master.cpp:8893] Sending 1 offers to framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:39.191926 39758 master.cpp:5555] Processing DECLINE call for
offers: [ f7977f54-bb98-445f-9610-ede08bf34093-O3 ] for framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:39.192348 39758 master.cpp:10830] Removing offer
f7977f54-bb98-445f-9610-ede08bf34093-O3
../../src/tests/fetcher_cache_tests.cpp:1677: Failure
Failed to wait 15secs for awaitFinished(task.get())
Begin listing sandboxes
Begin listing sandbox
`/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/latest`:
Begin file contents of `stdout`:
End file
Begin file contents of `stderr`:
I1107 13:20:28.373706 39811 fetcher.cpp:560] Fetcher Info:
{"cache_directory":"\/tmp\/FetcherCacheTest_RemoveLRUCacheEntries_bzpwJi\/fetch\/gilbert","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-cmd0","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i\/mesos-fetcher-test-assets\/cmd0"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i\/slaves\/f7977f54-bb98-445f-9610-ede08bf34093-S0\/frameworks\/f7977f54-bb98-445f-9610-ede08bf34093-0000\/executors\/0\/runs\/b0c1d94a-5bfe-443d-b284-be33a81924e7","stall_timeout":{"nanoseconds":60000000000},"user":"gilbert"}
I1107 13:20:28.384097 39811 fetcher.cpp:457] Fetching URI
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/mesos-fetcher-test-assets/cmd0'
I1107 13:20:28.384130 39811 fetcher.cpp:431] Downloading into cache
I1107 13:20:28.384142 39811 fetcher.cpp:227] Fetching URI
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/mesos-fetcher-test-assets/cmd0'
I1107 13:20:28.386828 39811 fetcher.cpp:351] Fetching from cache
I1107 13:20:28.389147 39811 fetcher.cpp:617] Fetched
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/mesos-fetcher-test-assets/cmd0'
to
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/b0c1d94a-5bfe-443d-b284-be33a81924e7/cmd0'
I1107 13:20:28.389169 39811 fetcher.cpp:622] Successfully fetched all URIs into
'/tmp/FetcherCacheTest_RemoveLRUCacheEntries_aJU38i/slaves/f7977f54-bb98-445f-9610-ede08bf34093-S0/frameworks/f7977f54-bb98-445f-9610-ede08bf34093-0000/executors/0/runs/b0c1d94a-5bfe-443d-b284-be33a81924e7'
End file
Begin file contents of `cmd0`:
touch mesos-fetcher-test-cmd$1
End file
End sandbox
End sandboxes
I1107 13:20:43.242727 39728 sched.cpp:2004] Asked to stop the driver
I1107 13:20:43.242909 39766 sched.cpp:1186] Stopping framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:43.243196 39760 master.cpp:9578] Processing TEARDOWN call for
framework f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:43.243263 39760 master.cpp:9590] Removing framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:43.243294 39760 master.cpp:3372] Deactivating framework
f7977f54-bb98-445f-9610-ede08bf34093-0000 (default) at
[email protected]:41973
I1107 13:20:43.243441 39762 hierarchical.cpp:407] Deactivated framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:43.244105 39760 master.cpp:1185] Master terminating
I1107 13:20:43.244341 39778 hierarchical.cpp:346] Removed framework
f7977f54-bb98-445f-9610-ede08bf34093-0000
I1107 13:20:43.244846 39778 hierarchical.cpp:612] Removed agent
f7977f54-bb98-445f-9610-ede08bf34093-S0
I1107 13:20:43.244846 39760 slave.cpp:5935] Got exited event for
[email protected]:41973
W1107 13:20:43.244915 39760 slave.cpp:5940] Master disconnected! Waiting for a
new master to be elected
I1107 13:20:43.248229 39755 slave.cpp:921] Agent terminating
[ FAILED ] FetcherCacheTest.RemoveLRUCacheEntries (15107 ms)
[----------] 1 test from FetcherCacheTest (15109 ms total)
[----------] Global test environment tear-down
[==========] 1 test from 1 test case ran. (15138 ms total)
[ PASSED ] 0 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] FetcherCacheTest.RemoveLRUCacheEntries
1 FAILED TEST
I1107 13:20:43.287750 39790 process.cpp:874] Failed to accept socket: future
discarded
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
