[MESOS-5805] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory is flaky - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Accepted
Priority: Major
Resolution: Unresolved
Affects Version/s: None
Fix Version/s: None
Component/s: None
Labels:

Epic Link:
flaky

Description

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

[ 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)

Logs from a good run:

[ 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)

Attachments

Issue Links

is related to

MESOS-8254 Some fetcher cache tests are flaky.

Accepted

MESOS-4692 FetcherCacheHttpTest.HttpCachedSerialized flaky again.

Accepted

Activity

People

Assignee:: Unassigned

Reporter:: Anand Mazumdar

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 07/Jul/16 20:19

Updated:: 19/Aug/19 12:38