[ 
https://issues.apache.org/jira/browse/MESOS-5805?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16898840#comment-16898840
 ] 

Andrei Sekretenko commented on MESOS-5805:
------------------------------------------

Identical failures has been reported in MESOS-8254.

> 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: containerization, 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)

Reply via email to