[
https://issues.apache.org/jira/browse/MESOS-5805?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16898781#comment-16898781
]
Andrei Sekretenko commented on MESOS-5805:
------------------------------------------
Observed the same failure in internal CI:
{code}
[ RUN ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory
I0801 23:35:11.143187 27650 cluster.cpp:177] Creating default 'local' authorizer
I0801 23:35:11.144773 27657 master.cpp:440] Master
19a0e702-0f2f-43b7-a967-2dba846eec08 (ip-172-16-10-65.ec2.internal) started on
172.16.10.65:36302
I0801 23:35:11.144794 27657 master.cpp:443] 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/6UYK4V/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_operator_event_stream_subscribers="1000"
--max_unreachable_tasks_per_framework="1000" --memory_profiling="false"
--min_allocatable_resources="cpus:0.01|mem:32" --port="5050"
--publish_per_framework_metrics="true" --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/6UYK4V/master" --zk_session_timeout="10secs"
I0801 23:35:11.144940 27657 master.cpp:492] Master only allowing authenticated
frameworks to register
I0801 23:35:11.144948 27657 master.cpp:498] Master only allowing authenticated
agents to register
I0801 23:35:11.144953 27657 master.cpp:504] Master only allowing authenticated
HTTP frameworks to register
I0801 23:35:11.144958 27657 credentials.hpp:37] Loading credentials for
authentication from '/tmp/6UYK4V/credentials'
I0801 23:35:11.145025 27657 master.cpp:548] Using default 'crammd5'
authenticator
I0801 23:35:11.145069 27657 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0801 23:35:11.145115 27657 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0801 23:35:11.145139 27657 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0801 23:35:11.145164 27657 master.cpp:629] Authorization enabled
I0801 23:35:11.145248 27653 hierarchical.cpp:241] Initialized hierarchical
allocator process
I0801 23:35:11.145277 27653 whitelist_watcher.cpp:77] No whitelist given
I0801 23:35:11.145887 27652 master.cpp:2168] Elected as the leading master!
I0801 23:35:11.145900 27652 master.cpp:1664] Recovering from registrar
I0801 23:35:11.145939 27652 registrar.cpp:339] Recovering registrar
I0801 23:35:11.146075 27652 registrar.cpp:383] Successfully fetched the
registry (0B) in 123136ns
I0801 23:35:11.146106 27652 registrar.cpp:487] Applied 1 operations in 7573ns;
attempting to update the registry
I0801 23:35:11.146347 27652 registrar.cpp:544] Successfully updated the
registry in 229120ns
I0801 23:35:11.146379 27652 registrar.cpp:416] Successfully recovered registrar
I0801 23:35:11.146466 27651 master.cpp:1817] Recovered 0 agents from the
registry (180B); allowing 10mins for agents to reregister
I0801 23:35:11.146508 27651 hierarchical.cpp:280] Skipping recovery of
hierarchical allocator: nothing to recover
W0801 23:35:11.146796 27650 process.cpp:2877] Attempted to spawn already
running process version@172.16.10.65:36302
I0801 23:35:11.147542 27650 containerizer.cpp:318] Using isolation {
environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
I0801 23:35:11.149612 27650 linux_launcher.cpp:144] Using
/sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
I0801 23:35:11.150092 27650 provisioner.cpp:300] Using default backend 'aufs'
W0801 23:35:11.151890 27650 process.cpp:2877] Attempted to spawn already
running process files@172.16.10.65:36302
I0801 23:35:11.152179 27650 cluster.cpp:518] Creating default 'local' authorizer
I0801 23:35:11.152782 27656 slave.cpp:267] Mesos agent started on
(78)@172.16.10.65:36302
I0801 23:35:11.152798 27656 slave.cpp:268] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/6UYK4V/Tcs2lx/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --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_destroy_timeout="1mins" --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/6UYK4V/Tcs2lx/credential"
--default_role="*" --disallow_sharing_agent_ipc_namespace="false"
--disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins"
--docker="docker" --docker_ignore_runtime="false" --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/6UYK4V/Tcs2lx/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/6UYK4V/Tcs2lx/fetch" --fetcher_cache_size="2GB"
--fetcher_stall_timeout="1mins"
--frameworks_home="/tmp/6UYK4V/Tcs2lx/frameworks" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false"
--help="false" --hostname_lookup="true" --http_command_executor="false"
--http_credentials="/tmp/6UYK4V/Tcs2lx/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--jwt_secret_key="/tmp/6UYK4V/Tcs2lx/jwt_secret_key" --launcher="linux"
--launcher_dir="/home/ubuntu/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mesos-ec2-ubuntu-14.04/mesos/build/src"
--logbufsecs="0" --logging_level="INFO"
--max_completed_executors_per_framework="150" --memory_profiling="false"
--network_cni_metrics="true" --network_cni_root_dir_persist="false"
--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_CachedCustomOutputFileWithSubdirectory_kIMBVk"
--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_CachedCustomOutputFileWithSubdirectory_N1fbv8"
--zk_session_timeout="10secs"
I0801 23:35:11.153018 27656 credentials.hpp:86] Loading credential for
authentication from '/tmp/6UYK4V/Tcs2lx/credential'
I0801 23:35:11.153076 27656 slave.cpp:300] Agent using credential for:
test-principal
I0801 23:35:11.153085 27656 credentials.hpp:37] Loading credentials for
authentication from '/tmp/6UYK4V/Tcs2lx/http_credentials'
I0801 23:35:11.153164 27656 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I0801 23:35:11.153196 27656 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I0801 23:35:11.153234 27656 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0801 23:35:11.153252 27656 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I0801 23:35:11.153278 27656 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0801 23:35:11.153298 27656 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0801 23:35:11.153359 27656 disk_profile_adaptor.cpp:78] Creating default disk
profile adaptor module
I0801 23:35:11.153806 27656 slave.cpp:615] Agent resources:
[{"name":"cpus","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1000.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":35056.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0801 23:35:11.153877 27656 slave.cpp:623] Agent attributes: [ ]
I0801 23:35:11.153884 27656 slave.cpp:632] Agent hostname:
ip-172-16-10-65.ec2.internal
I0801 23:35:11.153985 27652 task_status_update_manager.cpp:181] Pausing sending
task status updates
I0801 23:35:11.154003 27652 status_update_manager_process.hpp:379] Pausing
operation status update manager
I0801 23:35:11.154182 27656 state.cpp:67] Recovering state from
'/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_N1fbv8/meta'
I0801 23:35:11.154232 27656 slave.cpp:7444] Finished recovering checkpointed
state from
'/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_N1fbv8/meta',
beginning agent recovery
I0801 23:35:11.154296 27656 task_status_update_manager.cpp:207] Recovering task
status update manager
I0801 23:35:11.154376 27656 containerizer.cpp:821] Recovering Mesos containers
I0801 23:35:11.154422 27656 linux_launcher.cpp:286] Recovering Linux launcher
I0801 23:35:11.154525 27656 containerizer.cpp:1147] Recovering isolators
I0801 23:35:11.154712 27651 containerizer.cpp:1186] Recovering provisioner
I0801 23:35:11.154834 27654 provisioner.cpp:500] Provisioner recovery complete
I0801 23:35:11.155041 27658 composing.cpp:339] Finished recovering all
containerizers
I0801 23:35:11.155100 27651 slave.cpp:7908] Recovering executors
I0801 23:35:11.155122 27651 slave.cpp:8061] Finished recovery
I0801 23:35:11.155514 27658 slave.cpp:1351] New master detected at
master@172.16.10.65:36302
I0801 23:35:11.155531 27657 task_status_update_manager.cpp:181] Pausing sending
task status updates
I0801 23:35:11.155546 27658 slave.cpp:1416] Detecting new master
I0801 23:35:11.155546 27657 status_update_manager_process.hpp:379] Pausing
operation status update manager
I0801 23:35:11.159817 27655 slave.cpp:1443] Authenticating with master
master@172.16.10.65:36302
I0801 23:35:11.159844 27655 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I0801 23:35:11.159915 27655 authenticatee.cpp:121] Creating new client SASL
connection
I0801 23:35:11.160410 27651 master.cpp:10578] Authenticating
slave(78)@172.16.10.65:36302
I0801 23:35:11.160465 27651 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(184)@172.16.10.65:36302
I0801 23:35:11.160517 27651 authenticator.cpp:98] Creating new server SASL
connection
I0801 23:35:11.161119 27651 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0801 23:35:11.161139 27651 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0801 23:35:11.161170 27651 authenticator.cpp:204] Received SASL authentication
start
I0801 23:35:11.161202 27651 authenticator.cpp:326] Authentication requires more
steps
I0801 23:35:11.161229 27651 authenticatee.cpp:259] Received SASL authentication
step
I0801 23:35:11.161264 27651 authenticator.cpp:232] Received SASL authentication
step
I0801 23:35:11.161280 27651 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-65.ec2.internal' server FQDN:
'ip-172-16-10-65.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0801 23:35:11.161288 27651 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0801 23:35:11.161298 27651 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0801 23:35:11.161306 27651 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-65.ec2.internal' server FQDN:
'ip-172-16-10-65.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0801 23:35:11.161312 27651 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0801 23:35:11.161317 27651 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0801 23:35:11.161329 27651 authenticator.cpp:318] Authentication success
I0801 23:35:11.161366 27651 authenticatee.cpp:299] Authentication success
I0801 23:35:11.161403 27651 master.cpp:10610] Successfully authenticated
principal 'test-principal' at slave(78)@172.16.10.65:36302
I0801 23:35:11.161423 27651 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(184)@172.16.10.65:36302
I0801 23:35:11.161479 27651 slave.cpp:1543] Successfully authenticated with
master master@172.16.10.65:36302
I0801 23:35:11.161574 27651 slave.cpp:1993] Will retry registration in
14.916579ms if necessary
I0801 23:35:11.161669 27651 master.cpp:7086] Received register agent message
from slave(78)@172.16.10.65:36302 (ip-172-16-10-65.ec2.internal)
I0801 23:35:11.161725 27651 master.cpp:4202] Authorizing agent providing
resources 'cpus:1000; mem:1000; disk:35056; ports:[31000-32000]' with principal
'test-principal'
I0801 23:35:11.161844 27651 master.cpp:7153] Authorized registration of agent
at slave(78)@172.16.10.65:36302 (ip-172-16-10-65.ec2.internal)
I0801 23:35:11.161873 27651 master.cpp:7265] Registering agent at
slave(78)@172.16.10.65:36302 (ip-172-16-10-65.ec2.internal) with id
19a0e702-0f2f-43b7-a967-2dba846eec08-S0
I0801 23:35:11.161984 27651 registrar.cpp:487] Applied 1 operations in 36623ns;
attempting to update the registry
I0801 23:35:11.162104 27651 registrar.cpp:544] Successfully updated the
registry in 104960ns
I0801 23:35:11.162150 27651 master.cpp:7313] Admitted agent
19a0e702-0f2f-43b7-a967-2dba846eec08-S0 at slave(78)@172.16.10.65:36302
(ip-172-16-10-65.ec2.internal)
I0801 23:35:11.162264 27651 master.cpp:7358] Registered agent
19a0e702-0f2f-43b7-a967-2dba846eec08-S0 at slave(78)@172.16.10.65:36302
(ip-172-16-10-65.ec2.internal) with cpus:1000; mem:1000; disk:35056;
ports:[31000-32000]
I0801 23:35:11.162312 27655 hierarchical.cpp:617] Added agent
19a0e702-0f2f-43b7-a967-2dba846eec08-S0 (ip-172-16-10-65.ec2.internal) with
cpus:1000; mem:1000; disk:35056; ports:[31000-32000] (allocated: {})
I0801 23:35:11.162359 27651 slave.cpp:1576] Registered with master
master@172.16.10.65:36302; given agent ID
19a0e702-0f2f-43b7-a967-2dba846eec08-S0
I0801 23:35:11.162403 27655 hierarchical.cpp:1508] Performed allocation for 1
agents in 18159ns
I0801 23:35:11.162447 27655 task_status_update_manager.cpp:188] Resuming
sending task status updates
I0801 23:35:11.162523 27651 slave.cpp:1611] Checkpointing SlaveInfo to
'/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_N1fbv8/meta/slaves/19a0e702-0f2f-43b7-a967-2dba846eec08-S0/slave.info'
I0801 23:35:11.162539 27655 status_update_manager_process.hpp:385] Resuming
operation status update manager
I0801 23:35:11.162786 27651 slave.cpp:1663] Forwarding agent update
{"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"MnMLYeKNRJ+tCmsVVkxuFQ=="},"slave_id":{"value":"19a0e702-0f2f-43b7-a967-2dba846eec08-S0"},"update_oversubscribed_resources":false}
I0801 23:35:11.162976 27651 master.cpp:8457] Ignoring update on agent
19a0e702-0f2f-43b7-a967-2dba846eec08-S0 at slave(78)@172.16.10.65:36302
(ip-172-16-10-65.ec2.internal) as it reports no changes
I0801 23:35:11.164294 27650 sched.cpp:239] Version: 1.9.0
I0801 23:35:11.164552 27654 sched.cpp:343] New master detected at
master@172.16.10.65:36302
I0801 23:35:11.164587 27654 sched.cpp:408] Authenticating with master
master@172.16.10.65:36302
I0801 23:35:11.164594 27654 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0801 23:35:11.164674 27654 authenticatee.cpp:121] Creating new client SASL
connection
I0801 23:35:11.165146 27654 master.cpp:10578] Authenticating
scheduler-8397da56-efe1-4dcb-a8de-3b5f615dbbe5@172.16.10.65:36302
I0801 23:35:11.165187 27654 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(185)@172.16.10.65:36302
I0801 23:35:11.165233 27654 authenticator.cpp:98] Creating new server SASL
connection
I0801 23:35:11.165809 27654 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0801 23:35:11.165829 27654 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0801 23:35:11.165858 27654 authenticator.cpp:204] Received SASL authentication
start
I0801 23:35:11.165884 27654 authenticator.cpp:326] Authentication requires more
steps
I0801 23:35:11.165910 27654 authenticatee.cpp:259] Received SASL authentication
step
I0801 23:35:11.165940 27654 authenticator.cpp:232] Received SASL authentication
step
I0801 23:35:11.165951 27654 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-65.ec2.internal' server FQDN:
'ip-172-16-10-65.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0801 23:35:11.165958 27654 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0801 23:35:11.165966 27654 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0801 23:35:11.165974 27654 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-65.ec2.internal' server FQDN:
'ip-172-16-10-65.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0801 23:35:11.165980 27654 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0801 23:35:11.165985 27654 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0801 23:35:11.165997 27654 authenticator.cpp:318] Authentication success
I0801 23:35:11.166030 27654 authenticatee.cpp:299] Authentication success
I0801 23:35:11.166061 27654 master.cpp:10610] Successfully authenticated
principal 'test-principal' at
scheduler-8397da56-efe1-4dcb-a8de-3b5f615dbbe5@172.16.10.65:36302
I0801 23:35:11.166081 27654 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(185)@172.16.10.65:36302
I0801 23:35:11.166129 27654 sched.cpp:520] Successfully authenticated with
master master@172.16.10.65:36302
I0801 23:35:11.166143 27654 sched.cpp:835] Sending SUBSCRIBE call to
master@172.16.10.65:36302
I0801 23:35:11.166177 27654 sched.cpp:870] Will retry registration in
1.470145692secs if necessary
I0801 23:35:11.166250 27654 master.cpp:2908] Received SUBSCRIBE call for
framework 'default' at
scheduler-8397da56-efe1-4dcb-a8de-3b5f615dbbe5@172.16.10.65:36302
W0801 23:35:11.166263 27654 master.cpp:2916] Setting 'principal' in
FrameworkInfo to 'test-principal' because the framework authenticated with that
principal but did not set it in FrameworkInfo
I0801 23:35:11.166273 27654 master.cpp:2240] Authorizing framework principal
'test-principal' to receive offers for roles '{ * }'
I0801 23:35:11.166347 27654 master.cpp:2995] Subscribing framework default with
checkpointing enabled and capabilities [ ]
I0801 23:35:11.166755 27654 master.cpp:10808] Adding framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000 (default) at
scheduler-8397da56-efe1-4dcb-a8de-3b5f615dbbe5@172.16.10.65:36302 with roles {
} suppressed
I0801 23:35:11.167191 27654 hierarchical.cpp:368] Added framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000
I0801 23:35:11.167289 27654 hierarchical.cpp:1508] Performed allocation for 1
agents in 72638ns
I0801 23:35:11.167322 27654 sched.cpp:751] Framework registered with
19a0e702-0f2f-43b7-a967-2dba846eec08-0000
I0801 23:35:11.167336 27654 sched.cpp:770] Scheduler::registered took 7336ns
I0801 23:35:11.167431 27654 master.cpp:10393] Sending offers [
19a0e702-0f2f-43b7-a967-2dba846eec08-O0 ] to framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000 (default) at
scheduler-8397da56-efe1-4dcb-a8de-3b5f615dbbe5@172.16.10.65:36302
I0801 23:35:11.167521 27654 sched.cpp:934] Scheduler::resourceOffers took 6315ns
I0801 23:35:12.145634 27656 hierarchical.cpp:1508] Performed allocation for 1
agents in 33917ns
I0801 23:35:13.146852 27658 hierarchical.cpp:1508] Performed allocation for 1
agents in 34657ns
I0801 23:35:14.148016 27654 hierarchical.cpp:1508] Performed allocation for 1
agents in 33903ns
I0801 23:35:15.149235 27651 hierarchical.cpp:1508] Performed allocation for 1
agents in 35451ns
I0801 23:35:16.150437 27652 hierarchical.cpp:1508] Performed allocation for 1
agents in 35023ns
I0801 23:35:17.150939 27656 hierarchical.cpp:1508] Performed allocation for 1
agents in 35719ns
I0801 23:35:18.152251 27651 hierarchical.cpp:1508] Performed allocation for 1
agents in 35574ns
I0801 23:35:19.152868 27658 hierarchical.cpp:1508] Performed allocation for 1
agents in 34394ns
I0801 23:35:20.154110 27655 hierarchical.cpp:1508] Performed allocation for 1
agents in 34543ns
I0801 23:35:21.154582 27657 hierarchical.cpp:1508] Performed allocation for 1
agents in 35957ns
I0801 23:35:22.155035 27652 hierarchical.cpp:1508] Performed allocation for 1
agents in 35519ns
I0801 23:35:23.155674 27651 hierarchical.cpp:1508] Performed allocation for 1
agents in 35380ns
I0801 23:35:24.156759 27652 hierarchical.cpp:1508] Performed allocation for 1
agents in 35615ns
I0801 23:35:25.157310 27651 hierarchical.cpp:1508] Performed allocation for 1
agents in 35600ns
I0801 23:35:26.157683 27654 hierarchical.cpp:1508] Performed allocation for 1
agents in 34557ns
../../src/tests/fetcher_cache_tests.cpp:801: Failure
task: Failed to wait for resource offers: discarded
Begin listing sandboxes
End sandboxes
I0801 23:35:26.168385 27650 sched.cpp:2166] Asked to stop the driver
I0801 23:35:26.168534 27654 sched.cpp:1204] Stopping framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000
I0801 23:35:26.168637 27651 master.cpp:11172] Processing TEARDOWN call for
framework 19a0e702-0f2f-43b7-a967-2dba846eec08-0000 (default) at
scheduler-8397da56-efe1-4dcb-a8de-3b5f615dbbe5@172.16.10.65:36302
I0801 23:35:26.168658 27651 master.cpp:11184] Removing framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000 (default) at
scheduler-8397da56-efe1-4dcb-a8de-3b5f615dbbe5@172.16.10.65:36302
I0801 23:35:26.168668 27651 master.cpp:3360] Deactivating framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000 (default) at
scheduler-8397da56-efe1-4dcb-a8de-3b5f615dbbe5@172.16.10.65:36302
I0801 23:35:26.168745 27653 hierarchical.cpp:475] Deactivated framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000
I0801 23:35:26.168759 27651 master.cpp:12685] Removing offer
19a0e702-0f2f-43b7-a967-2dba846eec08-O0
I0801 23:35:26.168856 27651 slave.cpp:4056] Asked to shut down framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000 by master@172.16.10.65:36302
I0801 23:35:26.168867 27651 slave.cpp:4071] Cannot shut down unknown framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000
I0801 23:35:26.168846 27653 hierarchical.cpp:1218] Recovered cpus(allocated:
*):1000; mem(allocated: *):1000; disk(allocated: *):35056; ports(allocated:
*):[31000-32000] (total: cpus:1000; mem:1000; disk:35056; ports:[31000-32000],
allocated: {}) on agent 19a0e702-0f2f-43b7-a967-2dba846eec08-S0 from framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000
I0801 23:35:26.169001 27650 master.cpp:1135] Master terminating
I0801 23:35:26.169194 27658 slave.cpp:6409] Got exited event for
master@172.16.10.65:36302
W0801 23:35:26.169207 27658 slave.cpp:6414] Master disconnected! Waiting for a
new master to be elected
I0801 23:35:26.169508 27653 hierarchical.cpp:1432] Allocation paused
I0801 23:35:26.169559 27653 hierarchical.cpp:417] Removed framework
19a0e702-0f2f-43b7-a967-2dba846eec08-0000
I0801 23:35:26.169571 27653 hierarchical.cpp:1442] Allocation resumed
I0801 23:35:26.169617 27653 hierarchical.cpp:775] Removed all filters for agent
19a0e702-0f2f-43b7-a967-2dba846eec08-S0
I0801 23:35:26.169625 27653 hierarchical.cpp:650] Removed agent
19a0e702-0f2f-43b7-a967-2dba846eec08-S0
I0801 23:35:26.170372 27650 slave.cpp:924] Agent terminating
[ FAILED ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory (15040 ms)
{code}
> FetcherCacheTest.CachedCustomOutputFileWithSubdirectory is flaky
> ----------------------------------------------------------------
>
> Key: MESOS-5805
> URL: https://issues.apache.org/jira/browse/MESOS-5805
> Project: Mesos
> Issue Type: Bug
> Reporter: Anand Mazumdar
> Priority: Major
> Labels: flaky, flaky-test, tests
>
> Showed up on ASF CI:
> https://builds.apache.org/job/Mesos/BUILDTOOL=autotools,COMPILER=clang,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(docker%7C%7CHadoop)&&(!ubuntu-us1)&&(!ubuntu-6)/2466/changes
> {code}
> [ RUN ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory
> I0707 19:32:26.474630 27874 cluster.cpp:155] Creating default 'local'
> authorizer
> I0707 19:32:26.569936 27874 leveldb.cpp:174] Opened db in 94.192009ms
> I0707 19:32:26.612267 27874 leveldb.cpp:181] Compacted db in 42.112514ms
> I0707 19:32:26.612556 27874 leveldb.cpp:196] Created db iterator in 53311ns
> I0707 19:32:26.612701 27874 leveldb.cpp:202] Seeked to beginning of db in
> 16446ns
> I0707 19:32:26.612807 27874 leveldb.cpp:271] Iterated through 0 keys in the
> db in 22978ns
> I0707 19:32:26.612962 27874 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0707 19:32:26.614738 27900 recover.cpp:451] Starting replica recovery
> I0707 19:32:26.615362 27900 recover.cpp:477] Replica is in EMPTY status
> I0707 19:32:26.617480 27893 replica.cpp:673] Replica in EMPTY status received
> a broadcasted recover request from (2046)@172.17.0.7:47769
> I0707 19:32:26.618697 27903 recover.cpp:197] Received a recover response from
> a replica in EMPTY status
> I0707 19:32:26.619361 27903 recover.cpp:568] Updating replica status to
> STARTING
> I0707 19:32:26.641041 27901 master.cpp:382] Master
> 27e097c5-33d2-457b-97f7-eafde246f1bb (89b080073abb) started on
> 172.17.0.7:47769
> I0707 19:32:26.641352 27901 master.cpp:384] 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="true" --authenticate_http_frameworks="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/6aq2CX/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="/mesos/mesos-1.0.0/_inst/share/mesos/webui"
> --work_dir="/tmp/6aq2CX/master" --zk_session_timeout="10secs"
> I0707 19:32:26.642398 27901 master.cpp:434] Master only allowing
> authenticated frameworks to register
> I0707 19:32:26.642501 27901 master.cpp:448] Master only allowing
> authenticated agents to register
> I0707 19:32:26.642599 27901 master.cpp:461] Master only allowing
> authenticated HTTP frameworks to register
> I0707 19:32:26.642691 27901 credentials.hpp:37] Loading credentials for
> authentication from '/tmp/6aq2CX/credentials'
> I0707 19:32:26.643245 27901 master.cpp:506] Using default 'crammd5'
> authenticator
> I0707 19:32:26.643949 27901 master.cpp:578] Using default 'basic' HTTP
> authenticator
> I0707 19:32:26.644579 27901 master.cpp:658] Using default 'basic' HTTP
> framework authenticator
> I0707 19:32:26.645917 27901 master.cpp:705] Authorization enabled
> I0707 19:32:26.646328 27897 hierarchical.cpp:151] Initialized hierarchical
> allocator process
> I0707 19:32:26.647629 27904 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 27.466685ms
> I0707 19:32:26.647743 27905 whitelist_watcher.cpp:77] No whitelist given
> I0707 19:32:26.647814 27904 replica.cpp:320] Persisted replica status to
> STARTING
> I0707 19:32:26.648566 27904 recover.cpp:477] Replica is in STARTING status
> I0707 19:32:26.651857 27899 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (2050)@172.17.0.7:47769
> I0707 19:32:26.652978 27907 recover.cpp:197] Received a recover response from
> a replica in STARTING status
> I0707 19:32:26.654054 27907 recover.cpp:568] Updating replica status to VOTING
> I0707 19:32:26.660482 27905 master.cpp:1973] The newly elected leader is
> master@172.17.0.7:47769 with id 27e097c5-33d2-457b-97f7-eafde246f1bb
> I0707 19:32:26.660712 27905 master.cpp:1986] Elected as the leading master!
> I0707 19:32:26.660835 27905 master.cpp:1673] Recovering from registrar
> I0707 19:32:26.661224 27895 registrar.cpp:332] Recovering registrar
> I0707 19:32:26.681769 27892 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 26.868425ms
> I0707 19:32:26.682031 27892 replica.cpp:320] Persisted replica status to
> VOTING
> I0707 19:32:26.682479 27899 recover.cpp:582] Successfully joined the Paxos
> group
> I0707 19:32:26.683171 27899 recover.cpp:466] Recover process terminated
> I0707 19:32:26.684547 27892 log.cpp:553] Attempting to start the writer
> I0707 19:32:26.686614 27897 replica.cpp:493] Replica received implicit
> promise request from (2051)@172.17.0.7:47769 with proposal 1
> I0707 19:32:26.709501 27897 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 22.766332ms
> I0707 19:32:26.709594 27897 replica.cpp:342] Persisted promised to 1
> I0707 19:32:26.711184 27897 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0707 19:32:26.713104 27897 replica.cpp:388] Replica received explicit
> promise request from (2052)@172.17.0.7:47769 for position 0 with proposal 2
> I0707 19:32:26.740506 27897 leveldb.cpp:341] Persisting action (8 bytes) to
> leveldb took 26.031904ms
> I0707 19:32:26.740598 27897 replica.cpp:712] Persisted action at 0
> I0707 19:32:26.742622 27902 replica.cpp:537] Replica received write request
> for position 0 from (2053)@172.17.0.7:47769
> I0707 19:32:26.742712 27902 leveldb.cpp:436] Reading position from leveldb
> took 57696ns
> I0707 19:32:26.768502 27902 leveldb.cpp:341] Persisting action (14 bytes) to
> leveldb took 25.768923ms
> I0707 19:32:26.768704 27902 replica.cpp:712] Persisted action at 0
> I0707 19:32:26.769994 27895 replica.cpp:691] Replica received learned notice
> for position 0 from @0.0.0.0:0
> I0707 19:32:26.793498 27895 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 23.061867ms
> I0707 19:32:26.793726 27895 replica.cpp:712] Persisted action at 0
> I0707 19:32:26.793859 27895 replica.cpp:697] Replica learned NOP action at
> position 0
> I0707 19:32:26.795469 27899 log.cpp:569] Writer started with ending position 0
> I0707 19:32:26.797344 27895 leveldb.cpp:436] Reading position from leveldb
> took 73951ns
> I0707 19:32:26.806041 27895 registrar.cpp:365] Successfully fetched the
> registry (0B) in 144.496128ms
> I0707 19:32:26.806359 27895 registrar.cpp:464] Applied 1 operations in
> 43069ns; attempting to update the 'registry'
> I0707 19:32:26.807682 27904 log.cpp:577] Attempting to append 168 bytes to
> the log
> I0707 19:32:26.807905 27904 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I0707 19:32:26.809219 27904 replica.cpp:537] Replica received write request
> for position 1 from (2054)@172.17.0.7:47769
> I0707 19:32:26.835285 27904 leveldb.cpp:341] Persisting action (187 bytes) to
> leveldb took 26.051963ms
> I0707 19:32:26.835520 27904 replica.cpp:712] Persisted action at 1
> I0707 19:32:26.837309 27904 replica.cpp:691] Replica received learned notice
> for position 1 from @0.0.0.0:0
> I0707 19:32:26.860438 27904 leveldb.cpp:341] Persisting action (189 bytes) to
> leveldb took 23.040844ms
> I0707 19:32:26.860656 27904 replica.cpp:712] Persisted action at 1
> I0707 19:32:26.860785 27904 replica.cpp:697] Replica learned APPEND action at
> position 1
> I0707 19:32:26.866220 27899 registrar.cpp:509] Successfully updated the
> 'registry' in 59.460096ms
> I0707 19:32:26.866374 27898 log.cpp:596] Attempting to truncate the log to 1
> I0707 19:32:26.867024 27898 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I0707 19:32:26.868391 27906 replica.cpp:537] Replica received write request
> for position 2 from (2055)@172.17.0.7:47769
> I0707 19:32:26.868849 27899 registrar.cpp:395] Successfully recovered
> registrar
> I0707 19:32:26.869691 27893 master.cpp:1781] Recovered 0 agents from the
> Registry (129B) ; allowing 10mins for agents to re-register
> I0707 19:32:26.869958 27893 hierarchical.cpp:178] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0707 19:32:26.893944 27906 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 25.434238ms
> I0707 19:32:26.894160 27906 replica.cpp:712] Persisted action at 2
> I0707 19:32:26.896083 27906 replica.cpp:691] Replica received learned notice
> for position 2 from @0.0.0.0:0
> I0707 19:32:26.919489 27906 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 23.328407ms
> I0707 19:32:26.919626 27906 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 73119ns
> I0707 19:32:26.919653 27906 replica.cpp:712] Persisted action at 2
> I0707 19:32:26.919689 27906 replica.cpp:697] Replica learned TRUNCATE action
> at position 2
> I0707 19:32:26.926030 27874 containerizer.cpp:196] Using isolation:
> posix/cpu,posix/mem,filesystem/posix,network/cni
> W0707 19:32:26.928402 27874 backend.cpp:75] Failed to create 'aufs' backend:
> AufsBackend requires root privileges, but is running as user mesos
> W0707 19:32:26.929761 27874 backend.cpp:75] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0707 19:32:26.940363 27874 cluster.cpp:432] Creating default 'local'
> authorizer
> I0707 19:32:26.946017 27901 slave.cpp:205] Agent started on
> 47)@172.17.0.7:47769
> I0707 19:32:26.946146 27901 slave.cpp:206] Flags at startup: --acls=""
> --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="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="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/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="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/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="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/http_credentials"
> --image_provisioner_backend="copy" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-1.0.0/_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:1000;mem:1000" --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="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97"
> I0707 19:32:26.947057 27901 credentials.hpp:86] Loading credential for
> authentication from
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/credential'
> I0707 19:32:26.947353 27901 slave.cpp:343] Agent using credential for:
> test-principal
> I0707 19:32:26.949486 27901 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/http_credentials'
> I0707 19:32:26.949837 27901 slave.cpp:395] Using default 'basic' HTTP
> authenticator
> I0707 19:32:26.951508 27901 resources.cpp:572] Parsing resources as JSON
> failed: cpus:1000;mem:1000
> Trying semicolon-delimited string format instead
> I0707 19:32:26.951822 27901 resources.cpp:572] Parsing resources as JSON
> failed: cpus:1000;mem:1000
> Trying semicolon-delimited string format instead
> I0707 19:32:26.952347 27901 slave.cpp:594] Agent resources: cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 19:32:26.955682 27901 slave.cpp:602] Agent attributes: [ ]
> I0707 19:32:26.955793 27901 slave.cpp:607] Agent hostname: 89b080073abb
> I0707 19:32:26.961683 27901 state.cpp:57] Recovering state from
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/meta'
> I0707 19:32:26.962864 27907 status_update_manager.cpp:200] Recovering status
> update manager
> I0707 19:32:26.963281 27905 containerizer.cpp:522] Recovering containerizer
> I0707 19:32:26.966325 27902 provisioner.cpp:253] Provisioner recovery complete
> I0707 19:32:26.968153 27902 slave.cpp:4856] Finished recovery
> I0707 19:32:26.969983 27902 slave.cpp:5028] Querying resource estimator for
> oversubscribable resources
> I0707 19:32:26.971781 27902 slave.cpp:969] New master detected at
> master@172.17.0.7:47769
> I0707 19:32:26.972028 27892 status_update_manager.cpp:174] Pausing sending
> status updates
> I0707 19:32:26.972312 27902 slave.cpp:1028] Authenticating with master
> master@172.17.0.7:47769
> I0707 19:32:26.972450 27902 slave.cpp:1039] Using default CRAM-MD5
> authenticatee
> I0707 19:32:26.972923 27896 authenticatee.cpp:121] Creating new client SASL
> connection
> I0707 19:32:26.974572 27904 master.cpp:6006] Authenticating
> slave(47)@172.17.0.7:47769
> I0707 19:32:26.974946 27895 authenticator.cpp:414] Starting authentication
> session for crammd5_authenticatee(139)@172.17.0.7:47769
> I0707 19:32:26.975589 27895 authenticator.cpp:98] Creating new server SASL
> connection
> I0707 19:32:26.976150 27895 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0707 19:32:26.976929 27895 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0707 19:32:26.977274 27895 authenticator.cpp:204] Received SASL
> authentication start
> I0707 19:32:26.978523 27895 authenticator.cpp:326] Authentication requires
> more steps
> I0707 19:32:26.978771 27904 authenticatee.cpp:259] Received SASL
> authentication step
> I0707 19:32:26.978956 27904 authenticator.cpp:232] Received SASL
> authentication step
> I0707 19:32:26.979115 27904 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '89b080073abb' server FQDN: '89b080073abb'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0707 19:32:26.979269 27904 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0707 19:32:26.979514 27904 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0707 19:32:26.979754 27904 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '89b080073abb' server FQDN: '89b080073abb'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0707 19:32:26.979840 27904 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0707 19:32:26.979966 27904 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0707 19:32:26.980000 27904 authenticator.cpp:318] Authentication success
> I0707 19:32:26.980474 27896 authenticatee.cpp:299] Authentication success
> I0707 19:32:26.980962 27904 master.cpp:6036] Successfully authenticated
> principal 'test-principal' at slave(47)@172.17.0.7:47769
> I0707 19:32:26.982486 27907 authenticator.cpp:432] Authentication session
> cleanup for crammd5_authenticatee(139)@172.17.0.7:47769
> I0707 19:32:26.983160 27902 slave.cpp:1001] Detecting new master
> I0707 19:32:26.984596 27902 slave.cpp:5042] Received oversubscribable
> resources from the resource estimator
> I0707 19:32:26.985185 27902 slave.cpp:1123] Successfully authenticated with
> master master@172.17.0.7:47769
> I0707 19:32:26.986740 27902 slave.cpp:1529] Will retry registration in
> 5.184254ms if necessary
> I0707 19:32:26.987226 27900 master.cpp:4676] Registering agent at
> slave(47)@172.17.0.7:47769 (89b080073abb) with id
> 27e097c5-33d2-457b-97f7-eafde246f1bb-S0
> I0707 19:32:26.989073 27900 registrar.cpp:464] Applied 1 operations in
> 101321ns; attempting to update the 'registry'
> I0707 19:32:26.993281 27900 log.cpp:577] Attempting to append 337 bytes to
> the log
> I0707 19:32:26.994741 27900 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 3
> I0707 19:32:26.998684 27898 replica.cpp:537] Replica received write request
> for position 3 from (2072)@172.17.0.7:47769
> I0707 19:32:27.006036 27901 slave.cpp:1529] Will retry registration in
> 32.31224ms if necessary
> I0707 19:32:27.006404 27901 master.cpp:4664] Ignoring register agent message
> from slave(47)@172.17.0.7:47769 (89b080073abb) as admission is already in
> progress
> I0707 19:32:27.022506 27898 leveldb.cpp:341] Persisting action (356 bytes) to
> leveldb took 23.781478ms
> I0707 19:32:27.022605 27898 replica.cpp:712] Persisted action at 3
> I0707 19:32:27.024341 27898 replica.cpp:691] Replica received learned notice
> for position 3 from @0.0.0.0:0
> I0707 19:32:27.040745 27900 slave.cpp:1529] Will retry registration in
> 64.501962ms if necessary
> I0707 19:32:27.041081 27900 master.cpp:4664] Ignoring register agent message
> from slave(47)@172.17.0.7:47769 (89b080073abb) as admission is already in
> progress
> I0707 19:32:27.054486 27898 leveldb.cpp:341] Persisting action (358 bytes) to
> leveldb took 30.127114ms
> I0707 19:32:27.054553 27898 replica.cpp:712] Persisted action at 3
> I0707 19:32:27.054594 27898 replica.cpp:697] Replica learned APPEND action at
> position 3
> I0707 19:32:27.058605 27900 registrar.cpp:509] Successfully updated the
> 'registry' in 68.084992ms
> I0707 19:32:27.058904 27895 log.cpp:596] Attempting to truncate the log to 3
> I0707 19:32:27.060483 27899 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 4
> I0707 19:32:27.062862 27892 replica.cpp:537] Replica received write request
> for position 4 from (2073)@172.17.0.7:47769
> I0707 19:32:27.064043 27907 master.cpp:4745] Registered agent
> 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 at slave(47)@172.17.0.7:47769
> (89b080073abb) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06;
> ports(*):[31000-32000]
> I0707 19:32:27.065629 27899 slave.cpp:1169] Registered with master
> master@172.17.0.7:47769; given agent ID
> 27e097c5-33d2-457b-97f7-eafde246f1bb-S0
> I0707 19:32:27.065661 27899 fetcher.cpp:86] Clearing fetcher cache
> I0707 19:32:27.066124 27899 slave.cpp:1192] Checkpointing SlaveInfo to
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/meta/slaves/27e097c5-33d2-457b-97f7-eafde246f1bb-S0/slave.info'
> I0707 19:32:27.066478 27904 status_update_manager.cpp:181] Resuming sending
> status updates
> I0707 19:32:27.067095 27899 slave.cpp:1229] Forwarding total oversubscribed
> resources
> I0707 19:32:27.067220 27899 slave.cpp:3760] Received ping from
> slave-observer(47)@172.17.0.7:47769
> I0707 19:32:27.068536 27907 hierarchical.cpp:478] Added agent
> 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 (89b080073abb) with cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0707 19:32:27.068730 27907 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:27.068801 27907 hierarchical.cpp:1195] Performed allocation for
> agent 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 in 218556ns
> I0707 19:32:27.068866 27899 master.cpp:5128] Received update of agent
> 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 at slave(47)@172.17.0.7:47769
> (89b080073abb) with total oversubscribed resources
> I0707 19:32:27.069129 27899 hierarchical.cpp:542] Agent
> 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 (89b080073abb) updated with
> oversubscribed resources (total: cpus(*):1000; mem(*):1000;
> disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0707 19:32:27.069268 27899 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:27.069330 27899 hierarchical.cpp:1195] Performed allocation for
> agent 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 in 157467ns
> I0707 19:32:27.071974 27874 sched.cpp:226] Version: 1.0.0
> I0707 19:32:27.073761 27906 sched.cpp:330] New master detected at
> master@172.17.0.7:47769
> I0707 19:32:27.073868 27906 sched.cpp:396] Authenticating with master
> master@172.17.0.7:47769
> I0707 19:32:27.073897 27906 sched.cpp:403] Using default CRAM-MD5
> authenticatee
> I0707 19:32:27.074276 27906 authenticatee.cpp:121] Creating new client SASL
> connection
> I0707 19:32:27.074748 27906 master.cpp:6006] Authenticating
> scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769
> I0707 19:32:27.074947 27906 authenticator.cpp:414] Starting authentication
> session for crammd5_authenticatee(140)@172.17.0.7:47769
> I0707 19:32:27.075307 27906 authenticator.cpp:98] Creating new server SASL
> connection
> I0707 19:32:27.076591 27906 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0707 19:32:27.076633 27906 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0707 19:32:27.076732 27906 authenticator.cpp:204] Received SASL
> authentication start
> I0707 19:32:27.076798 27906 authenticator.cpp:326] Authentication requires
> more steps
> I0707 19:32:27.076896 27906 authenticatee.cpp:259] Received SASL
> authentication step
> I0707 19:32:27.077006 27906 authenticator.cpp:232] Received SASL
> authentication step
> I0707 19:32:27.077044 27906 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '89b080073abb' server FQDN: '89b080073abb'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0707 19:32:27.077070 27906 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0707 19:32:27.077122 27906 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0707 19:32:27.077162 27906 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '89b080073abb' server FQDN: '89b080073abb'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0707 19:32:27.077186 27906 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0707 19:32:27.077201 27906 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0707 19:32:27.077224 27906 authenticator.cpp:318] Authentication success
> I0707 19:32:27.077405 27906 authenticatee.cpp:299] Authentication success
> I0707 19:32:27.077901 27906 sched.cpp:502] Successfully authenticated with
> master master@172.17.0.7:47769
> I0707 19:32:27.077930 27906 sched.cpp:820] Sending SUBSCRIBE call to
> master@172.17.0.7:47769
> I0707 19:32:27.078029 27906 sched.cpp:853] Will retry registration in
> 1.38078506secs if necessary
> I0707 19:32:27.077478 27894 master.cpp:6036] Successfully authenticated
> principal 'test-principal' at
> scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769
> I0707 19:32:27.078367 27894 master.cpp:2550] Received SUBSCRIBE call for
> framework 'default' at
> scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769
> I0707 19:32:27.077536 27893 authenticator.cpp:432] Authentication session
> cleanup for crammd5_authenticatee(140)@172.17.0.7:47769
> W0707 19:32:27.079169 27894 master.cpp:2558] Setting 'principal' in
> FrameworkInfo to 'test-principal' because the framework authenticated with
> that principal but did not set it in FrameworkInfo
> I0707 19:32:27.079267 27894 master.cpp:2012] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0707 19:32:27.079823 27894 master.cpp:2626] Subscribing framework default
> with checkpointing enabled and capabilities [ ]
> I0707 19:32:27.080744 27894 hierarchical.cpp:271] Added framework
> 27e097c5-33d2-457b-97f7-eafde246f1bb-0000
> I0707 19:32:27.081712 27894 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:27.081866 27894 hierarchical.cpp:1172] Performed allocation for 1
> agents in 1.013733ms
> I0707 19:32:27.082243 27894 sched.cpp:743] Framework registered with
> 27e097c5-33d2-457b-97f7-eafde246f1bb-0000
> I0707 19:32:27.082551 27894 sched.cpp:757] Scheduler::registered took 36098ns
> I0707 19:32:27.082960 27893 master.cpp:5835] Sending 1 offers to framework
> 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 (default) at
> scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769
> I0707 19:32:27.083443 27893 sched.cpp:917] Scheduler::resourceOffers took
> 56308ns
> I0707 19:32:27.098503 27892 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 35.618891ms
> I0707 19:32:27.098595 27892 replica.cpp:712] Persisted action at 4
> I0707 19:32:27.102179 27892 replica.cpp:691] Replica received learned notice
> for position 4 from @0.0.0.0:0
> I0707 19:32:27.131503 27892 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 29.315235ms
> I0707 19:32:27.131675 27892 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 96863ns
> I0707 19:32:27.131713 27892 replica.cpp:712] Persisted action at 4
> I0707 19:32:27.131757 27892 replica.cpp:697] Replica learned TRUNCATE action
> at position 4
> I0707 19:32:27.647403 27903 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:27.647547 27903 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:27.647682 27903 hierarchical.cpp:1172] Performed allocation for 1
> agents in 516669ns
> I0707 19:32:28.648784 27902 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:28.648861 27902 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:28.648948 27902 hierarchical.cpp:1172] Performed allocation for 1
> agents in 401012ns
> I0707 19:32:29.650446 27895 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:29.650642 27895 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:29.650847 27895 hierarchical.cpp:1172] Performed allocation for 1
> agents in 657345ns
> I0707 19:32:30.651702 27898 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:30.651906 27898 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:30.664597 27898 hierarchical.cpp:1172] Performed allocation for 1
> agents in 13.162927ms
> I0707 19:32:31.665630 27893 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:31.665824 27893 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:31.666036 27893 hierarchical.cpp:1172] Performed allocation for 1
> agents in 662365ns
> I0707 19:32:32.670071 27897 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:32.670270 27897 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:32.670495 27897 hierarchical.cpp:1172] Performed allocation for 1
> agents in 674425ns
> I0707 19:32:33.672061 27905 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:33.672142 27905 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:33.672230 27905 hierarchical.cpp:1172] Performed allocation for 1
> agents in 409318ns
> I0707 19:32:34.674059 27898 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:34.674139 27898 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:34.674226 27898 hierarchical.cpp:1172] Performed allocation for 1
> agents in 401379ns
> I0707 19:32:35.676055 27893 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:35.676136 27893 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:35.676223 27893 hierarchical.cpp:1172] Performed allocation for 1
> agents in 404615ns
> I0707 19:32:36.677132 27903 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:36.677203 27903 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:36.677285 27903 hierarchical.cpp:1172] Performed allocation for 1
> agents in 373906ns
> I0707 19:32:37.678169 27894 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:37.678241 27894 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:37.678328 27894 hierarchical.cpp:1172] Performed allocation for 1
> agents in 390602ns
> I0707 19:32:38.683040 27893 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:38.683117 27893 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:38.683199 27893 hierarchical.cpp:1172] Performed allocation for 1
> agents in 385950ns
> I0707 19:32:39.684876 27907 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:39.684948 27907 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:39.685032 27907 hierarchical.cpp:1172] Performed allocation for 1
> agents in 382509ns
> I0707 19:32:40.686470 27894 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:40.686542 27894 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:40.686628 27894 hierarchical.cpp:1172] Performed allocation for 1
> agents in 393049ns
> I0707 19:32:41.687438 27900 hierarchical.cpp:1537] No allocations performed
> I0707 19:32:41.687513 27900 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 19:32:41.687610 27900 hierarchical.cpp:1172] Performed allocation for 1
> agents in 443146ns
> I0707 19:32:41.986075 27898 slave.cpp:5028] Querying resource estimator for
> oversubscribable resources
> I0707 19:32:41.986361 27898 slave.cpp:5042] Received oversubscribable
> resources from the resource estimator
> I0707 19:32:42.064714 27897 slave.cpp:3760] Received ping from
> slave-observer(47)@172.17.0.7:47769
> ../../src/tests/fetcher_cache_tests.cpp:725: Failure
> task: Failed to wait for resource offers: discarded
> Begin listing sandboxes
> End sandboxes
> I0707 19:32:42.100826 27874 sched.cpp:1987] Asked to stop the driver
> I0707 19:32:42.101096 27892 sched.cpp:1187] Stopping framework
> '27e097c5-33d2-457b-97f7-eafde246f1bb-0000'
> I0707 19:32:42.101379 27900 master.cpp:6410] Processing TEARDOWN call for
> framework 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 (default) at
> scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769
> I0707 19:32:42.101488 27900 master.cpp:6422] Removing framework
> 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 (default) at
> scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769
> I0707 19:32:42.102313 27900 hierarchical.cpp:382] Deactivated framework
> 27e097c5-33d2-457b-97f7-eafde246f1bb-0000
> I0707 19:32:42.102485 27895 slave.cpp:2292] Asked to shut down framework
> 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 by master@172.17.0.7:47769
> W0707 19:32:42.102519 27895 slave.cpp:2307] Cannot shut down unknown
> framework 27e097c5-33d2-457b-97f7-eafde246f1bb-0000
> I0707 19:32:42.103277 27900 hierarchical.cpp:924] Recovered cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total:
> cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000],
> allocated: ) on agent 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 from framework
> 27e097c5-33d2-457b-97f7-eafde246f1bb-0000
> I0707 19:32:42.103543 27900 hierarchical.cpp:333] Removed framework
> 27e097c5-33d2-457b-97f7-eafde246f1bb-0000
> I0707 19:32:42.104722 27904 master.cpp:1218] Master terminating
> I0707 19:32:42.105665 27903 hierarchical.cpp:510] Removed agent
> 27e097c5-33d2-457b-97f7-eafde246f1bb-S0
> I0707 19:32:42.112759 27905 slave.cpp:3806] master@172.17.0.7:47769 exited
> W0707 19:32:42.112814 27905 slave.cpp:3811] Master disconnected! Waiting for
> a new master to be elected
> I0707 19:32:42.227802 27874 slave.cpp:841] Agent terminating
> [ FAILED ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory (15871
> ms)
> {code}
> Logs from a good run:
> {code}
> [ RUN ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory
> I0707 18:08:20.581107 29421 cluster.cpp:155] Creating default 'local'
> authorizer
> I0707 18:08:20.666667 29421 leveldb.cpp:174] Opened db in 85.116942ms
> I0707 18:08:20.692816 29421 leveldb.cpp:181] Compacted db in 26.071143ms
> I0707 18:08:20.692908 29421 leveldb.cpp:196] Created db iterator in 24163ns
> I0707 18:08:20.692925 29421 leveldb.cpp:202] Seeked to beginning of db in
> 2922ns
> I0707 18:08:20.692937 29421 leveldb.cpp:271] Iterated through 0 keys in the
> db in 335ns
> I0707 18:08:20.692993 29421 replica.cpp:779] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0707 18:08:20.694229 29454 recover.cpp:451] Starting replica recovery
> I0707 18:08:20.694669 29451 recover.cpp:477] Replica is in EMPTY status
> I0707 18:08:20.697399 29443 replica.cpp:673] Replica in EMPTY status received
> a broadcasted recover request from (2049)@172.17.0.7:43512
> I0707 18:08:20.698287 29443 recover.cpp:197] Received a recover response from
> a replica in EMPTY status
> I0707 18:08:20.699291 29443 recover.cpp:568] Updating replica status to
> STARTING
> I0707 18:08:20.714786 29444 master.cpp:382] Master
> 2d32adef-7b13-4aff-b8ed-363a2e14655f (753c2ae3a486) started on
> 172.17.0.7:43512
> I0707 18:08:20.715103 29444 master.cpp:384] 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="true" --authenticate_http_frameworks="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/g9jQAg/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="/mesos/mesos-1.0.0/_inst/share/mesos/webui"
> --work_dir="/tmp/g9jQAg/master" --zk_session_timeout="10secs"
> I0707 18:08:20.715935 29444 master.cpp:434] Master only allowing
> authenticated frameworks to register
> I0707 18:08:20.716097 29444 master.cpp:448] Master only allowing
> authenticated agents to register
> I0707 18:08:20.716236 29444 master.cpp:461] Master only allowing
> authenticated HTTP frameworks to register
> I0707 18:08:20.716428 29444 credentials.hpp:37] Loading credentials for
> authentication from '/tmp/g9jQAg/credentials'
> I0707 18:08:20.731957 29444 master.cpp:506] Using default 'crammd5'
> authenticator
> I0707 18:08:20.732342 29444 master.cpp:578] Using default 'basic' HTTP
> authenticator
> I0707 18:08:20.732915 29444 master.cpp:658] Using default 'basic' HTTP
> framework authenticator
> I0707 18:08:20.733528 29444 master.cpp:705] Authorization enabled
> I0707 18:08:20.734544 29441 hierarchical.cpp:151] Initialized hierarchical
> allocator process
> I0707 18:08:20.734659 29454 whitelist_watcher.cpp:77] No whitelist given
> I0707 18:08:20.739863 29446 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 39.990221ms
> I0707 18:08:20.740063 29446 replica.cpp:320] Persisted replica status to
> STARTING
> I0707 18:08:20.740602 29446 recover.cpp:477] Replica is in STARTING status
> I0707 18:08:20.742774 29446 replica.cpp:673] Replica in STARTING status
> received a broadcasted recover request from (2052)@172.17.0.7:43512
> I0707 18:08:20.743501 29446 recover.cpp:197] Received a recover response from
> a replica in STARTING status
> I0707 18:08:20.744494 29451 recover.cpp:568] Updating replica status to VOTING
> I0707 18:08:20.746140 29444 master.cpp:1973] The newly elected leader is
> master@172.17.0.7:43512 with id 2d32adef-7b13-4aff-b8ed-363a2e14655f
> I0707 18:08:20.746523 29444 master.cpp:1986] Elected as the leading master!
> I0707 18:08:20.746713 29444 master.cpp:1673] Recovering from registrar
> I0707 18:08:20.747117 29443 registrar.cpp:332] Recovering registrar
> I0707 18:08:20.780143 29445 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 34.654414ms
> I0707 18:08:20.780215 29445 replica.cpp:320] Persisted replica status to
> VOTING
> I0707 18:08:20.780552 29445 recover.cpp:582] Successfully joined the Paxos
> group
> I0707 18:08:20.781373 29444 log.cpp:553] Attempting to start the writer
> I0707 18:08:20.781486 29445 recover.cpp:466] Recover process terminated
> I0707 18:08:20.783949 29446 replica.cpp:493] Replica received implicit
> promise request from (2053)@172.17.0.7:43512 with proposal 1
> I0707 18:08:20.807478 29446 leveldb.cpp:304] Persisting metadata (8 bytes) to
> leveldb took 23.302934ms
> I0707 18:08:20.807561 29446 replica.cpp:342] Persisted promised to 1
> I0707 18:08:20.810058 29451 coordinator.cpp:238] Coordinator attempting to
> fill missing positions
> I0707 18:08:20.812877 29451 replica.cpp:388] Replica received explicit
> promise request from (2054)@172.17.0.7:43512 for position 0 with proposal 2
> I0707 18:08:20.838755 29451 leveldb.cpp:341] Persisting action (8 bytes) to
> leveldb took 25.80638ms
> I0707 18:08:20.838837 29451 replica.cpp:712] Persisted action at 0
> I0707 18:08:20.841653 29440 replica.cpp:537] Replica received write request
> for position 0 from (2055)@172.17.0.7:43512
> I0707 18:08:20.841735 29440 leveldb.cpp:436] Reading position from leveldb
> took 38136ns
> I0707 18:08:20.863855 29440 leveldb.cpp:341] Persisting action (14 bytes) to
> leveldb took 22.056724ms
> I0707 18:08:20.863939 29440 replica.cpp:712] Persisted action at 0
> I0707 18:08:20.864995 29440 replica.cpp:691] Replica received learned notice
> for position 0 from @0.0.0.0:0
> I0707 18:08:20.888983 29440 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 23.93767ms
> I0707 18:08:20.889062 29440 replica.cpp:712] Persisted action at 0
> I0707 18:08:20.889097 29440 replica.cpp:697] Replica learned NOP action at
> position 0
> I0707 18:08:20.890658 29454 log.cpp:569] Writer started with ending position 0
> I0707 18:08:20.892063 29441 leveldb.cpp:436] Reading position from leveldb
> took 51724ns
> I0707 18:08:20.893506 29441 registrar.cpp:365] Successfully fetched the
> registry (0B) in 146.110976ms
> I0707 18:08:20.893682 29441 registrar.cpp:464] Applied 1 operations in
> 27053ns; attempting to update the 'registry'
> I0707 18:08:20.894632 29453 log.cpp:577] Attempting to append 168 bytes to
> the log
> I0707 18:08:20.894870 29452 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 1
> I0707 18:08:20.895822 29450 replica.cpp:537] Replica received write request
> for position 1 from (2056)@172.17.0.7:43512
> I0707 18:08:20.922474 29450 leveldb.cpp:341] Persisting action (187 bytes) to
> leveldb took 26.593514ms
> I0707 18:08:20.922554 29450 replica.cpp:712] Persisted action at 1
> I0707 18:08:20.923375 29450 replica.cpp:691] Replica received learned notice
> for position 1 from @0.0.0.0:0
> I0707 18:08:20.947584 29450 leveldb.cpp:341] Persisting action (189 bytes) to
> leveldb took 24.082326ms
> I0707 18:08:20.947877 29450 replica.cpp:712] Persisted action at 1
> I0707 18:08:20.948094 29450 replica.cpp:697] Replica learned APPEND action at
> position 1
> I0707 18:08:20.950374 29455 registrar.cpp:509] Successfully updated the
> 'registry' in 56.603136ms
> I0707 18:08:20.950639 29445 log.cpp:596] Attempting to truncate the log to 1
> I0707 18:08:20.950664 29455 registrar.cpp:395] Successfully recovered
> registrar
> I0707 18:08:20.950953 29455 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 2
> I0707 18:08:20.951706 29445 master.cpp:1781] Recovered 0 agents from the
> Registry (129B) ; allowing 10mins for agents to re-register
> I0707 18:08:20.951740 29455 hierarchical.cpp:178] Skipping recovery of
> hierarchical allocator: nothing to recover
> I0707 18:08:20.952482 29455 replica.cpp:537] Replica received write request
> for position 2 from (2057)@172.17.0.7:43512
> I0707 18:08:20.972702 29455 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 20.161143ms
> I0707 18:08:20.972781 29455 replica.cpp:712] Persisted action at 2
> I0707 18:08:20.973821 29447 replica.cpp:691] Replica received learned notice
> for position 2 from @0.0.0.0:0
> I0707 18:08:20.997858 29447 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 23.980235ms
> I0707 18:08:20.998198 29447 leveldb.cpp:399] Deleting ~1 keys from leveldb
> took 260069ns
> I0707 18:08:20.998241 29447 replica.cpp:712] Persisted action at 2
> I0707 18:08:20.998284 29447 replica.cpp:697] Replica learned TRUNCATE action
> at position 2
> I0707 18:08:21.003728 29421 containerizer.cpp:196] Using isolation:
> posix/cpu,posix/mem,filesystem/posix,network/cni
> W0707 18:08:21.004771 29421 backend.cpp:75] Failed to create 'aufs' backend:
> AufsBackend requires root privileges, but is running as user mesos
> W0707 18:08:21.005142 29421 backend.cpp:75] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0707 18:08:21.009625 29421 cluster.cpp:432] Creating default 'local'
> authorizer
> I0707 18:08:21.019762 29454 slave.cpp:205] Agent started on
> 47)@172.17.0.7:43512
> I0707 18:08:21.019804 29454 slave.cpp:206] Flags at startup: --acls=""
> --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="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="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/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="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/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="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/http_credentials"
> --image_provisioner_backend="copy" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-1.0.0/_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:1000;mem:1000" --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="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d"
> I0707 18:08:21.020503 29454 credentials.hpp:86] Loading credential for
> authentication from
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/credential'
> I0707 18:08:21.020758 29454 slave.cpp:343] Agent using credential for:
> test-principal
> I0707 18:08:21.020795 29454 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/http_credentials'
> I0707 18:08:21.021077 29454 slave.cpp:395] Using default 'basic' HTTP
> authenticator
> I0707 18:08:21.021381 29454 resources.cpp:572] Parsing resources as JSON
> failed: cpus:1000;mem:1000
> Trying semicolon-delimited string format instead
> I0707 18:08:21.021611 29454 resources.cpp:572] Parsing resources as JSON
> failed: cpus:1000;mem:1000
> Trying semicolon-delimited string format instead
> I0707 18:08:21.022073 29454 slave.cpp:594] Agent resources: cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0707 18:08:21.022148 29454 slave.cpp:602] Agent attributes: [ ]
> I0707 18:08:21.022162 29454 slave.cpp:607] Agent hostname: 753c2ae3a486
> I0707 18:08:21.023818 29440 state.cpp:57] Recovering state from
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta'
> I0707 18:08:21.024276 29448 status_update_manager.cpp:200] Recovering status
> update manager
> I0707 18:08:21.024487 29448 containerizer.cpp:522] Recovering containerizer
> I0707 18:08:21.026320 29453 provisioner.cpp:253] Provisioner recovery complete
> I0707 18:08:21.026952 29452 slave.cpp:4856] Finished recovery
> I0707 18:08:21.027668 29452 slave.cpp:5028] Querying resource estimator for
> oversubscribable resources
> I0707 18:08:21.028062 29452 slave.cpp:5042] Received oversubscribable
> resources from the resource estimator
> I0707 18:08:21.028357 29452 slave.cpp:969] New master detected at
> master@172.17.0.7:43512
> I0707 18:08:21.028640 29452 slave.cpp:1028] Authenticating with master
> master@172.17.0.7:43512
> I0707 18:08:21.028800 29452 slave.cpp:1039] Using default CRAM-MD5
> authenticatee
> I0707 18:08:21.029043 29452 slave.cpp:1001] Detecting new master
> I0707 18:08:21.028524 29449 status_update_manager.cpp:174] Pausing sending
> status updates
> I0707 18:08:21.029203 29442 authenticatee.cpp:121] Creating new client SASL
> connection
> I0707 18:08:21.029804 29442 master.cpp:6006] Authenticating
> slave(47)@172.17.0.7:43512
> I0707 18:08:21.030040 29442 authenticator.cpp:414] Starting authentication
> session for crammd5_authenticatee(139)@172.17.0.7:43512
> I0707 18:08:21.030367 29449 authenticator.cpp:98] Creating new server SASL
> connection
> I0707 18:08:21.030680 29449 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0707 18:08:21.030711 29449 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0707 18:08:21.030793 29449 authenticator.cpp:204] Received SASL
> authentication start
> I0707 18:08:21.030849 29449 authenticator.cpp:326] Authentication requires
> more steps
> I0707 18:08:21.030926 29449 authenticatee.cpp:259] Received SASL
> authentication step
> I0707 18:08:21.031011 29449 authenticator.cpp:232] Received SASL
> authentication step
> I0707 18:08:21.031041 29449 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '753c2ae3a486' server FQDN: '753c2ae3a486'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0707 18:08:21.031056 29449 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0707 18:08:21.031095 29449 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0707 18:08:21.031117 29449 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '753c2ae3a486' server FQDN: '753c2ae3a486'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0707 18:08:21.031131 29449 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0707 18:08:21.031141 29449 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0707 18:08:21.031158 29449 authenticator.cpp:318] Authentication success
> I0707 18:08:21.031272 29449 authenticatee.cpp:299] Authentication success
> I0707 18:08:21.031570 29442 authenticator.cpp:432] Authentication session
> cleanup for crammd5_authenticatee(139)@172.17.0.7:43512
> I0707 18:08:21.031811 29449 slave.cpp:1123] Successfully authenticated with
> master master@172.17.0.7:43512
> I0707 18:08:21.031975 29449 slave.cpp:1529] Will retry registration in
> 5.31021ms if necessary
> I0707 18:08:21.032245 29451 master.cpp:6036] Successfully authenticated
> principal 'test-principal' at slave(47)@172.17.0.7:43512
> I0707 18:08:21.032536 29451 master.cpp:4676] Registering agent at
> slave(47)@172.17.0.7:43512 (753c2ae3a486) with id
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0
> I0707 18:08:21.033066 29451 registrar.cpp:464] Applied 1 operations in
> 69145ns; attempting to update the 'registry'
> I0707 18:08:21.033982 29440 log.cpp:577] Attempting to append 337 bytes to
> the log
> I0707 18:08:21.034283 29440 coordinator.cpp:348] Coordinator attempting to
> write APPEND action at position 3
> I0707 18:08:21.035542 29444 replica.cpp:537] Replica received write request
> for position 3 from (2074)@172.17.0.7:43512
> I0707 18:08:21.038626 29441 slave.cpp:1529] Will retry registration in
> 15.12588ms if necessary
> I0707 18:08:21.038935 29445 master.cpp:4664] Ignoring register agent message
> from slave(47)@172.17.0.7:43512 (753c2ae3a486) as admission is already in
> progress
> I0707 18:08:21.054829 29442 slave.cpp:1529] Will retry registration in
> 764229ns if necessary
> I0707 18:08:21.055054 29443 master.cpp:4664] Ignoring register agent message
> from slave(47)@172.17.0.7:43512 (753c2ae3a486) as admission is already in
> progress
> I0707 18:08:21.056470 29447 slave.cpp:1529] Will retry registration in
> 107.24051ms if necessary
> I0707 18:08:21.056874 29447 master.cpp:4664] Ignoring register agent message
> from slave(47)@172.17.0.7:43512 (753c2ae3a486) as admission is already in
> progress
> I0707 18:08:21.067499 29444 leveldb.cpp:341] Persisting action (356 bytes) to
> leveldb took 31.803841ms
> I0707 18:08:21.067585 29444 replica.cpp:712] Persisted action at 3
> I0707 18:08:21.068524 29448 replica.cpp:691] Replica received learned notice
> for position 3 from @0.0.0.0:0
> I0707 18:08:21.083830 29448 leveldb.cpp:341] Persisting action (358 bytes) to
> leveldb took 15.184375ms
> I0707 18:08:21.083922 29448 replica.cpp:712] Persisted action at 3
> I0707 18:08:21.083961 29448 replica.cpp:697] Replica learned APPEND action at
> position 3
> I0707 18:08:21.086673 29448 registrar.cpp:509] Successfully updated the
> 'registry' in 53.527808ms
> I0707 18:08:21.087697 29447 log.cpp:596] Attempting to truncate the log to 3
> I0707 18:08:21.087909 29447 coordinator.cpp:348] Coordinator attempting to
> write TRUNCATE action at position 4
> I0707 18:08:21.089154 29451 replica.cpp:537] Replica received write request
> for position 4 from (2075)@172.17.0.7:43512
> I0707 18:08:21.089615 29448 master.cpp:4745] Registered agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512
> (753c2ae3a486) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06;
> ports(*):[31000-32000]
> I0707 18:08:21.089970 29448 hierarchical.cpp:478] Added agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 (753c2ae3a486) with cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0707 18:08:21.090132 29448 hierarchical.cpp:1537] No allocations performed
> I0707 18:08:21.090188 29448 hierarchical.cpp:1195] Performed allocation for
> agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 in 177083ns
> I0707 18:08:21.090397 29448 slave.cpp:1169] Registered with master
> master@172.17.0.7:43512; given agent ID
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0
> I0707 18:08:21.090903 29448 fetcher.cpp:86] Clearing fetcher cache
> I0707 18:08:21.091346 29448 slave.cpp:1192] Checkpointing SlaveInfo to
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/slave.info'
> I0707 18:08:21.091488 29454 status_update_manager.cpp:181] Resuming sending
> status updates
> I0707 18:08:21.091950 29448 slave.cpp:1229] Forwarding total oversubscribed
> resources
> I0707 18:08:21.092053 29448 slave.cpp:3760] Received ping from
> slave-observer(45)@172.17.0.7:43512
> I0707 18:08:21.092229 29448 master.cpp:5128] Received update of agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512
> (753c2ae3a486) with total oversubscribed resources
> I0707 18:08:21.092576 29448 hierarchical.cpp:542] Agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 (753c2ae3a486) updated with
> oversubscribed resources (total: cpus(*):1000; mem(*):1000;
> disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0707 18:08:21.092691 29448 hierarchical.cpp:1537] No allocations performed
> I0707 18:08:21.092743 29448 hierarchical.cpp:1195] Performed allocation for
> agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 in 126981ns
> I0707 18:08:21.094138 29421 sched.cpp:226] Version: 1.0.0
> I0707 18:08:21.094784 29440 sched.cpp:330] New master detected at
> master@172.17.0.7:43512
> I0707 18:08:21.094863 29440 sched.cpp:396] Authenticating with master
> master@172.17.0.7:43512
> I0707 18:08:21.094884 29440 sched.cpp:403] Using default CRAM-MD5
> authenticatee
> I0707 18:08:21.095202 29440 authenticatee.cpp:121] Creating new client SASL
> connection
> I0707 18:08:21.095528 29441 master.cpp:6006] Authenticating
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512
> I0707 18:08:21.095715 29441 authenticator.cpp:414] Starting authentication
> session for crammd5_authenticatee(140)@172.17.0.7:43512
> I0707 18:08:21.096050 29441 authenticator.cpp:98] Creating new server SASL
> connection
> I0707 18:08:21.096276 29441 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0707 18:08:21.096307 29441 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0707 18:08:21.096530 29441 authenticator.cpp:204] Received SASL
> authentication start
> I0707 18:08:21.096591 29441 authenticator.cpp:326] Authentication requires
> more steps
> I0707 18:08:21.096679 29441 authenticatee.cpp:259] Received SASL
> authentication step
> I0707 18:08:21.096771 29441 authenticator.cpp:232] Received SASL
> authentication step
> I0707 18:08:21.096803 29441 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '753c2ae3a486' server FQDN: '753c2ae3a486'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0707 18:08:21.096818 29441 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0707 18:08:21.096859 29441 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0707 18:08:21.096885 29441 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '753c2ae3a486' server FQDN: '753c2ae3a486'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0707 18:08:21.096899 29441 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0707 18:08:21.096909 29441 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0707 18:08:21.096928 29441 authenticator.cpp:318] Authentication success
> I0707 18:08:21.097080 29441 authenticatee.cpp:299] Authentication success
> I0707 18:08:21.097163 29441 master.cpp:6036] Successfully authenticated
> principal 'test-principal' at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512
> I0707 18:08:21.097249 29441 authenticator.cpp:432] Authentication session
> cleanup for crammd5_authenticatee(140)@172.17.0.7:43512
> I0707 18:08:21.097561 29445 sched.cpp:502] Successfully authenticated with
> master master@172.17.0.7:43512
> I0707 18:08:21.097592 29445 sched.cpp:820] Sending SUBSCRIBE call to
> master@172.17.0.7:43512
> I0707 18:08:21.097674 29445 sched.cpp:853] Will retry registration in
> 1.44767632secs if necessary
> I0707 18:08:21.097885 29445 master.cpp:2550] Received SUBSCRIBE call for
> framework 'default' at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512
> W0707 18:08:21.097920 29445 master.cpp:2558] Setting 'principal' in
> FrameworkInfo to 'test-principal' because the framework authenticated with
> that principal but did not set it in FrameworkInfo
> I0707 18:08:21.097973 29445 master.cpp:2012] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0707 18:08:21.098445 29445 master.cpp:2626] Subscribing framework default
> with checkpointing enabled and capabilities [ ]
> I0707 18:08:21.099176 29445 hierarchical.cpp:271] Added framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:21.100005 29445 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 18:08:21.100078 29445 hierarchical.cpp:1172] Performed allocation for 1
> agents in 874090ns
> I0707 18:08:21.100342 29445 sched.cpp:743] Framework registered with
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:21.100389 29445 sched.cpp:757] Scheduler::registered took 22486ns
> I0707 18:08:21.100822 29445 master.cpp:5835] Sending 1 offers to framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512
> I0707 18:08:21.101421 29445 sched.cpp:917] Scheduler::resourceOffers took
> 258437ns
> I0707 18:08:21.101763 29445 master.cpp:4077] Processing DECLINE call for
> offers: [ 2d32adef-7b13-4aff-b8ed-363a2e14655f-O0 ] for framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512
> I0707 18:08:21.102890 29445 hierarchical.cpp:924] Recovered cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total:
> cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000],
> allocated: ) on agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 from framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:21.102955 29445 hierarchical.cpp:961] Framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 filtered agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for 5secs
> I0707 18:08:21.128569 29451 leveldb.cpp:341] Persisting action (16 bytes) to
> leveldb took 39.364122ms
> I0707 18:08:21.128710 29451 replica.cpp:712] Persisted action at 4
> I0707 18:08:21.130101 29451 replica.cpp:691] Replica received learned notice
> for position 4 from @0.0.0.0:0
> I0707 18:08:21.170497 29451 leveldb.cpp:341] Persisting action (18 bytes) to
> leveldb took 40.264167ms
> I0707 18:08:21.170656 29451 leveldb.cpp:399] Deleting ~2 keys from leveldb
> took 81667ns
> I0707 18:08:21.170687 29451 replica.cpp:712] Persisted action at 4
> I0707 18:08:21.170724 29451 replica.cpp:697] Replica learned TRUNCATE action
> at position 4
> I0707 18:08:21.735710 29442 hierarchical.cpp:1723] Filtered offer with
> cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on
> agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:21.735790 29442 hierarchical.cpp:1537] No allocations performed
> I0707 18:08:21.735828 29442 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 18:08:21.735908 29442 hierarchical.cpp:1172] Performed allocation for 1
> agents in 647442ns
> I0707 18:08:22.737726 29444 hierarchical.cpp:1723] Filtered offer with
> cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on
> agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:22.737809 29444 hierarchical.cpp:1537] No allocations performed
> I0707 18:08:22.737846 29444 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 18:08:22.737920 29444 hierarchical.cpp:1172] Performed allocation for 1
> agents in 720313ns
> I0707 18:08:23.739508 29448 hierarchical.cpp:1723] Filtered offer with
> cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on
> agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:23.739596 29448 hierarchical.cpp:1537] No allocations performed
> I0707 18:08:23.739634 29448 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 18:08:23.739708 29448 hierarchical.cpp:1172] Performed allocation for 1
> agents in 733422ns
> I0707 18:08:24.741200 29449 hierarchical.cpp:1723] Filtered offer with
> cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on
> agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:24.741292 29449 hierarchical.cpp:1537] No allocations performed
> I0707 18:08:24.741333 29449 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 18:08:24.741431 29449 hierarchical.cpp:1172] Performed allocation for 1
> agents in 767509ns
> I0707 18:08:25.743439 29448 hierarchical.cpp:1723] Filtered offer with
> cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on
> agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:25.743540 29448 hierarchical.cpp:1537] No allocations performed
> I0707 18:08:25.743582 29448 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 18:08:25.743664 29448 hierarchical.cpp:1172] Performed allocation for 1
> agents in 812917ns
> I0707 18:08:26.745857 29448 hierarchical.cpp:1632] No inverse offers to send
> out!
> I0707 18:08:26.746567 29445 master.cpp:5835] Sending 1 offers to framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512
> I0707 18:08:26.747846 29445 sched.cpp:917] Scheduler::resourceOffers took
> 119209ns
> I0707 18:08:26.748867 29448 hierarchical.cpp:1172] Performed allocation for 1
> agents in 3.93405ms
> I0707 18:08:26.748996 29421 resources.cpp:572] Parsing resources as JSON
> failed: cpus:1;mem:1
> Trying semicolon-delimited string format instead
> I0707 18:08:26.752707 29454 master.cpp:3468] Processing ACCEPT call for
> offers: [ 2d32adef-7b13-4aff-b8ed-363a2e14655f-O1 ] on agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512
> (753c2ae3a486) for framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> (default) at scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512
> I0707 18:08:26.752810 29454 master.cpp:3106] Authorizing framework principal
> 'test-principal' to launch task 0
> I0707 18:08:26.754878 29445 master.cpp:7565] Adding task 0 with resources
> cpus(*):1; mem(*):1 on agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0
> (753c2ae3a486)
> I0707 18:08:26.754997 29445 master.cpp:3957] Launching task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 with
> resources cpus(*):1; mem(*):1 on agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512
> (753c2ae3a486)
> I0707 18:08:26.756191 29443 hierarchical.cpp:924] Recovered cpus(*):999;
> mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated:
> cpus(*):1; mem(*):1) on agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 from
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:26.756541 29443 hierarchical.cpp:961] Framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 filtered agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for 5secs
> I0707 18:08:26.756454 29451 slave.cpp:1569] Got assigned task 0 for framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:26.757066 29451 slave.cpp:5668] Checkpointing FrameworkInfo to
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/framework.info'
> I0707 18:08:26.757915 29451 slave.cpp:5679] Checkpointing framework pid
> 'scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512' to
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/framework.pid'
> I0707 18:08:26.758503 29451 resources.cpp:572] Parsing resources as JSON
> failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:08:26.759313 29451 slave.cpp:1688] Launching task 0 for framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:26.759589 29451 resources.cpp:572] Parsing resources as JSON
> failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0707 18:08:26.760591 29451 paths.cpp:528] Trying to chown
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18'
> to user 'mesos'
> I0707 18:08:26.766592 29451 slave.cpp:6150] Checkpointing ExecutorInfo to
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/executor.info'
> I0707 18:08:26.767770 29451 slave.cpp:5748] Launching executor 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18'
> I0707 18:08:26.768576 29444 containerizer.cpp:781] Starting container
> '3cb609be-9171-4cc1-bd76-393eb055af18' for executor '0' of framework
> '2d32adef-7b13-4aff-b8ed-363a2e14655f-0000'
> I0707 18:08:26.768690 29451 slave.cpp:6173] Checkpointing TaskInfo to
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18/tasks/0/task.info'
> I0707 18:08:26.769353 29451 slave.cpp:1914] Queuing task '0' for executor '0'
> of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:26.769631 29451 slave.cpp:922] Successfully attached file
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18'
> I0707 18:08:26.774013 29453 containerizer.cpp:1284] Launching
> 'mesos-containerizer' with flags
> '--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.0.0\/_build\/src"],"shell":false,"uris":[{"cache":true,"executable":true,"extract":true,"output_file":"subdir\/my-command","value":"\/tmp\/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d\/mesos-fetcher-test-assets\/mesos-fetcher-test-cmd"}],"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}"
> --help="false" --pipe_read="9" --pipe_write="12" --pre_exec_commands="[]"
> --unshare_namespace_mnt="false" --user="mesos"
> --working_directory="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18"'
> I0707 18:08:26.775884 29453 launcher.cpp:126] Forked child with pid '342' for
> container '3cb609be-9171-4cc1-bd76-393eb055af18'
> I0707 18:08:26.776357 29453 containerizer.cpp:1319] Checkpointing executor's
> forked pid 342 to
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18/pids/forked.pid'
> I0707 18:08:26.779757 29441 fetcher.cpp:348] Starting to fetch URIs for
> container: 3cb609be-9171-4cc1-bd76-393eb055af18, directory:
> /tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18
> I0707 18:08:26.784481 29441 fetcher.cpp:949] Created cache entry
> 'mesos@/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
> with file: c1-mesos-fetc_r-test-cmd
> I0707 18:08:26.785914 29442 fetcher.cpp:290] Fetching size for URI:
> /tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/mesos-fetcher-test-assets/mesos-fetcher-test-cmd
> I0707 18:08:26.789315 29441 fetcher.cpp:719] Claiming fetcher cache space
> for:
> mesos@/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/mesos-fetcher-test-assets/mesos-fetcher-test-cmd
> I0707 18:08:26.789444 29441 fetcher.cpp:1170] Claimed cache space: 30B, now
> using: 30B
> I0707 18:08:26.799283 29441 fetcher.cpp:821] Fetching URIs using command
> '/mesos/mesos-1.0.0/_build/src/mesos-fetcher'
> I0707 18:08:27.003576 29440 fetcher.cpp:1182] Released cache space: 0B, now
> using: 30B
> I0707 18:08:27.140242 342 exec.cpp:161] Version: 1.0.0
> I0707 18:08:27.144256 29440 slave.cpp:2902] Got registration for executor '0'
> of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from
> executor(1)@172.17.0.7:54683
> I0707 18:08:27.145002 29440 slave.cpp:2988] Checkpointing executor pid
> 'executor(1)@172.17.0.7:54683' to
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18/pids/libprocess.pid'
> I0707 18:08:27.147004 401 exec.cpp:236] Executor registered on agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0
> I0707 18:08:27.147676 29451 slave.cpp:2079] Sending queued task '0' to
> executor '0' of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 at
> executor(1)@172.17.0.7:54683
> Received SUBSCRIBED event
> Subscribed executor on 753c2ae3a486
> Received LAUNCH event
> Starting task 0
> /mesos/mesos-1.0.0/_build/src/mesos-containerizer launch
> --command="{"shell":true,"uris":[{"cache":true,"executable":true,"extract":true,"output_file":"subdir\/my-command","value":"\/tmp\/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d\/mesos-fetcher-test-assets\/mesos-fetcher-test-cmd"}],"value":".\/subdir\/my-command
> 0"}" --help="false" --unshare_namespace_mnt="false"
> Forked command at 411
> I0707 18:08:27.176249 29450 slave.cpp:3285] Handling status update
> TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from
> executor(1)@172.17.0.7:54683
> I0707 18:08:27.179903 29450 status_update_manager.cpp:320] Received status
> update TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0
> of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.179950 29450 status_update_manager.cpp:497] Creating
> StatusUpdate stream for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.180871 29450 status_update_manager.cpp:825] Checkpointing
> UPDATE for status update TASK_RUNNING (UUID:
> ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.283306 29450 status_update_manager.cpp:374] Forwarding update
> TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to the agent
> I0707 18:08:27.284230 29450 slave.cpp:3678] Forwarding the update
> TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to master@172.17.0.7:43512
> I0707 18:08:27.284757 29450 slave.cpp:3572] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.285354 29450 slave.cpp:3588] Sending acknowledgement for
> status update TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for
> task 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to
> executor(1)@172.17.0.7:54683
> I0707 18:08:27.285240 29444 master.cpp:5273] Status update TASK_RUNNING
> (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512
> (753c2ae3a486)
> I0707 18:08:27.288682 29444 master.cpp:5321] Forwarding status update
> TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.290532 29443 sched.cpp:1025] Scheduler::statusUpdate took
> 1.319302ms
> I0707 18:08:27.290921 29444 master.cpp:6959] Updating the state of task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (latest state:
> TASK_RUNNING, status update state: TASK_RUNNING)
> I0707 18:08:27.291749 29444 master.cpp:4388] Processing ACKNOWLEDGE call
> ac92d492-3e51-4f07-8753-b0f8bc99afcc for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 on agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0
> I0707 18:08:27.293953 29450 status_update_manager.cpp:392] Received status
> update acknowledgement (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task
> 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.296530 29450 status_update_manager.cpp:825] Checkpointing ACK
> for status update TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc)
> for task 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.361351 29447 slave.cpp:2671] Status update manager
> successfully handled status update acknowledgement (UUID:
> ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> Command exited with status 0 (pid: 411)
> I0707 18:08:27.375931 29450 slave.cpp:3285] Handling status update
> TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from
> executor(1)@172.17.0.7:54683
> I0707 18:08:27.378550 29447 slave.cpp:6088] Terminating task 0
> I0707 18:08:27.380687 29447 status_update_manager.cpp:320] Received status
> update TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0
> of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.380910 29447 status_update_manager.cpp:825] Checkpointing
> UPDATE for status update TASK_FINISHED (UUID:
> a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.428735 29447 status_update_manager.cpp:374] Forwarding update
> TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to the agent
> I0707 18:08:27.429576 29448 slave.cpp:3678] Forwarding the update
> TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to master@172.17.0.7:43512
> I0707 18:08:27.430321 29448 master.cpp:5273] Status update TASK_FINISHED
> (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512
> (753c2ae3a486)
> I0707 18:08:27.430564 29448 master.cpp:5321] Forwarding status update
> TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.431305 29449 sched.cpp:1025] Scheduler::statusUpdate took
> 212137ns
> I0707 18:08:27.433158 29448 master.cpp:6959] Updating the state of task 0 of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (latest state:
> TASK_FINISHED, status update state: TASK_FINISHED)
> I0707 18:08:27.433796 29448 master.cpp:4388] Processing ACKNOWLEDGE call
> a778fb07-07e1-47e5-a5a4-01987fe6f8c8 for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 on agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0
> I0707 18:08:27.434646 29448 master.cpp:7025] Removing task 0 with resources
> cpus(*):1; mem(*):1 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 on
> agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512
> (753c2ae3a486)
> I0707 18:08:27.434487 29441 hierarchical.cpp:924] Recovered cpus(*):1;
> mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06;
> ports(*):[31000-32000], allocated: ) on agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 from framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.434103 29421 sched.cpp:1987] Asked to stop the driver
> I0707 18:08:27.435642 29446 sched.cpp:1187] Stopping framework
> '2d32adef-7b13-4aff-b8ed-363a2e14655f-0000'
> I0707 18:08:27.436372 29442 master.cpp:6410] Processing TEARDOWN call for
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512
> I0707 18:08:27.436658 29442 master.cpp:6422] Removing framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at
> scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512
> I0707 18:08:27.437214 29442 master.cpp:1218] Master terminating
> I0707 18:08:27.437697 29449 hierarchical.cpp:382] Deactivated framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.437919 29451 slave.cpp:2292] Asked to shut down framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 by master@172.17.0.7:43512
> I0707 18:08:27.439893 29451 slave.cpp:2317] Shutting down framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.440057 29451 slave.cpp:4481] Shutting down executor '0' of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 at
> executor(1)@172.17.0.7:54683
> I0707 18:08:27.440824 29449 hierarchical.cpp:333] Removed framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.441685 29449 hierarchical.cpp:510] Removed agent
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0
> I0707 18:08:27.442066 29442 slave.cpp:3806] master@172.17.0.7:43512 exited
> W0707 18:08:27.442292 29442 slave.cpp:3811] Master disconnected! Waiting for
> a new master to be elected
> I0707 18:08:27.444540 394 exec.cpp:413] Executor asked to shutdown
> I0707 18:08:27.445024 29447 status_update_manager.cpp:392] Received status
> update acknowledgement (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task
> 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.445197 29454 slave.cpp:3572] Status update manager
> successfully handled status update TASK_FINISHED (UUID:
> a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.446210 29454 slave.cpp:3588] Sending acknowledgement for
> status update TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for
> task 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to
> executor(1)@172.17.0.7:54683
> I0707 18:08:27.446987 29447 status_update_manager.cpp:825] Checkpointing ACK
> for status update TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8)
> for task 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.454666 29455 containerizer.cpp:1622] Destroying container
> '3cb609be-9171-4cc1-bd76-393eb055af18'
> I0707 18:08:27.469662 29454 slave.cpp:3806] executor(1)@172.17.0.7:54683
> exited
> I0707 18:08:27.510895 29442 containerizer.cpp:1863] Executor for container
> '3cb609be-9171-4cc1-bd76-393eb055af18' has exited
> I0707 18:08:27.511548 29447 status_update_manager.cpp:528] Cleaning up status
> update stream for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.512651 29442 containerizer.cpp:1618] Destroy has already been
> initiated for '3cb609be-9171-4cc1-bd76-393eb055af18'
> I0707 18:08:27.513653 29453 provisioner.cpp:411] Ignoring destroy request for
> unknown container 3cb609be-9171-4cc1-bd76-393eb055af18
> I0707 18:08:27.513283 29452 slave.cpp:2671] Status update manager
> successfully handled status update acknowledgement (UUID:
> a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.513978 29452 slave.cpp:6129] Completing task 0
> I0707 18:08:27.514606 29452 slave.cpp:4163] Executor '0' of framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 terminated with signal Killed
> I0707 18:08:27.514744 29452 slave.cpp:4267] Cleaning up executor '0' of
> framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 at
> executor(1)@172.17.0.7:54683
> I0707 18:08:27.515455 29453 gc.cpp:55] Scheduling
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18'
> for gc 6.99999403632days in the future
> I0707 18:08:27.515810 29442 gc.cpp:55] Scheduling
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0'
> for gc 6.9999940309363days in the future
> I0707 18:08:27.516185 29452 slave.cpp:4355] Cleaning up framework
> 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.516422 29440 status_update_manager.cpp:282] Closing status
> update streams for framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000
> I0707 18:08:27.516657 29442 gc.cpp:55] Scheduling
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18'
> for gc 6.99999402774222days in the future
> I0707 18:08:27.517086 29442 gc.cpp:55] Scheduling
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0'
> for gc 6.99999402624889days in the future
> I0707 18:08:27.517400 29442 gc.cpp:55] Scheduling
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000'
> for gc 6.99999402189926days in the future
> I0707 18:08:27.517514 29421 slave.cpp:841] Agent terminating
> I0707 18:08:27.517562 29442 gc.cpp:55] Scheduling
> '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000'
> for gc 6.99999402084444days in the future
> [ OK ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory (6966 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.14#76016)
