You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Alexander Rojas (JIRA)" <ji...@apache.org> on 2015/12/07 16:56:11 UTC
[jira] [Comment Edited] (MESOS-3755)
FetcherCacheTest.FallbackFromEviction is flaky
[ https://issues.apache.org/jira/browse/MESOS-3755?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15045093#comment-15045093 ]
Alexander Rojas edited comment on MESOS-3755 at 12/7/15 3:55 PM:
-----------------------------------------------------------------
I ran into this today:
{noformat}
[ RUN ] FetcherCacheTest.FallbackFromEviction
I1207 16:29:44.399755 2093539328 exec.cpp:134] Version: 0.27.0
I1207 16:29:44.401639 2674688 exec.cpp:208] Executor registered on slave 73f8791e-f7dc-4cca-be2b-2e635d276977-S0
Registered executor on localhost
Starting task 0
sh -c './cmd0 0'
Forked command at 71255
Command exited with status 0 (pid: 71255)
I1207 16:29:45.315861 2093539328 exec.cpp:134] Version: 0.27.0
../../src/tests/fetcher_cache_tests.cpp:1402: Failure
Failed to wait 15secs for awaitFinished(task1.get())
Begin listing sandboxes
Begin listing sandbox `/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/0/runs/latest`:
Begin file contents of `cmd0`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `mesos-fetcher-test-cmd0`:
End file
Begin file contents of `stderr`:
I1207 16:29:44.265651 2093539328 fetcher.cpp:421] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/fetch\/slaves\/73f8791e-f7dc-4cca-be2b-2e635d276977-S0\/alexander","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-cmd0","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/mesos-fetcher-test-assets\/cmd0"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/slaves\/73f8791e-f7dc-4cca-be2b-2e635d276977-S0\/frameworks\/73f8791e-f7dc-4cca-be2b-2e635d276977-0000\/executors\/0\/runs\/1ee6e8cc-ce77-4be1-ad07-cbed852bd05b","user":"alexander"}
I1207 16:29:44.268673 2093539328 fetcher.cpp:376] Fetching URI '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd0'
I1207 16:29:44.268690 2093539328 fetcher.cpp:346] Downloading into cache
I1207 16:29:44.268966 2093539328 fetcher.cpp:184] Fetching URI '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd0'
I1207 16:29:44.269004 2093539328 fetcher.cpp:164] Copying resource with command:cp '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd0' '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/fetch/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/alexander/c1-cmd0'
I1207 16:29:44.273054 2093539328 fetcher.cpp:286] Fetching from cache
I1207 16:29:44.273082 2093539328 fetcher.cpp:164] Copying resource with command:cp '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/fetch/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/alexander/c1-cmd0' '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/0/runs/1ee6e8cc-ce77-4be1-ad07-cbed852bd05b/cmd0'
I1207 16:29:44.277532 2093539328 fetcher.cpp:453] Fetched '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd0' to '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/0/runs/1ee6e8cc-ce77-4be1-ad07-cbed852bd05b/cmd0'
End file
Begin file contents of `stdout`:
End file
End sandbox
Begin listing sandbox `/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/1/runs/latest`:
Begin file contents of `cmd1`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `stderr`:
I1207 16:29:45.229575 2093539328 fetcher.cpp:421] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/fetch\/slaves\/73f8791e-f7dc-4cca-be2b-2e635d276977-S0\/alexander","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c2-cmd1","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/mesos-fetcher-test-assets\/cmd1"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/slaves\/73f8791e-f7dc-4cca-be2b-2e635d276977-S0\/frameworks\/73f8791e-f7dc-4cca-be2b-2e635d276977-0000\/executors\/1\/runs\/b3a4bb68-1bf8-4071-b5af-39425de2a7c3","user":"alexander"}
I1207 16:29:45.232558 2093539328 fetcher.cpp:376] Fetching URI '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd1'
I1207 16:29:45.232574 2093539328 fetcher.cpp:346] Downloading into cache
I1207 16:29:45.232620 2093539328 fetcher.cpp:184] Fetching URI '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd1'
I1207 16:29:45.232656 2093539328 fetcher.cpp:164] Copying resource with command:cp '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd1' '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/fetch/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/alexander/c2-cmd1'
I1207 16:29:45.236754 2093539328 fetcher.cpp:286] Fetching from cache
I1207 16:29:45.236783 2093539328 fetcher.cpp:164] Copying resource with command:cp '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/fetch/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/alexander/c2-cmd1' '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/1/runs/b3a4bb68-1bf8-4071-b5af-39425de2a7c3/cmd1'
I1207 16:29:45.240356 2093539328 fetcher.cpp:453] Fetched '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd1' to '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/1/runs/b3a4bb68-1bf8-4071-b5af-39425de2a7c3/cmd1'
End file
Begin file contents of `stdout`:
End file
End sandbox
End sandboxes
../../src/tests/fetcher_cache_tests.cpp:1319: Failure
Actual function call count doesn't match EXPECT_CALL(*fetcherProcess, run(_, _, _, _, _))...
Expected: to be called 3 times
Actual: called twice - unsatisfied and active
[ FAILED ] FetcherCacheTest.FallbackFromEviction (16125 ms)
{noformat}
I haven't been able to reproduce anymore, though.
was (Author: arojas):
I ran into this today:
{noformat}
[ RUN ] FetcherCacheTest.FallbackFromEviction
I1207 16:29:44.399755 2093539328 exec.cpp:134] Version: 0.27.0
I1207 16:29:44.401639 2674688 exec.cpp:208] Executor registered on slave 73f8791e-f7dc-4cca-be2b-2e635d276977-S0
Registered executor on localhost
Starting task 0
sh -c './cmd0 0'
Forked command at 71255
Command exited with status 0 (pid: 71255)
I1207 16:29:45.315861 2093539328 exec.cpp:134] Version: 0.27.0
../../src/tests/fetcher_cache_tests.cpp:1402: Failure
Failed to wait 15secs for awaitFinished(task1.get())
Begin listing sandboxes
Begin listing sandbox `/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/0/runs/latest`:
Begin file contents of `cmd0`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `mesos-fetcher-test-cmd0`:
End file
Begin file contents of `stderr`:
I1207 16:29:44.265651 2093539328 fetcher.cpp:421] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/fetch\/slaves\/73f8791e-f7dc-4cca-be2b-2e635d276977-S0\/alexander","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-cmd0","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/mesos-fetcher-test-assets\/cmd0"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/slaves\/73f8791e-f7dc-4cca-be2b-2e635d276977-S0\/frameworks\/73f8791e-f7dc-4cca-be2b-2e635d276977-0000\/executors\/0\/runs\/1ee6e8cc-ce77-4be1-ad07-cbed852bd05b","user":"alexander"}
I1207 16:29:44.268673 2093539328 fetcher.cpp:376] Fetching URI '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd0'
I1207 16:29:44.268690 2093539328 fetcher.cpp:346] Downloading into cache
I1207 16:29:44.268966 2093539328 fetcher.cpp:184] Fetching URI '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd0'
I1207 16:29:44.269004 2093539328 fetcher.cpp:164] Copying resource with command:cp '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd0' '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/fetch/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/alexander/c1-cmd0'
I1207 16:29:44.273054 2093539328 fetcher.cpp:286] Fetching from cache
I1207 16:29:44.273082 2093539328 fetcher.cpp:164] Copying resource with command:cp '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/fetch/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/alexander/c1-cmd0' '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/0/runs/1ee6e8cc-ce77-4be1-ad07-cbed852bd05b/cmd0'
I1207 16:29:44.277532 2093539328 fetcher.cpp:453] Fetched '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd0' to '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/0/runs/1ee6e8cc-ce77-4be1-ad07-cbed852bd05b/cmd0'
End file
Begin file contents of `stdout`:
End file
End sandbox
Begin listing sandbox `/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/1/runs/latest`:
Begin file contents of `cmd1`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `stderr`:
I1207 16:29:45.229575 2093539328 fetcher.cpp:421] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/fetch\/slaves\/73f8791e-f7dc-4cca-be2b-2e635d276977-S0\/alexander","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c2-cmd1","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/mesos-fetcher-test-assets\/cmd1"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_FallbackFromEviction_12yKsN\/slaves\/73f8791e-f7dc-4cca-be2b-2e635d276977-S0\/frameworks\/73f8791e-f7dc-4cca-be2b-2e635d276977-0000\/executors\/1\/runs\/b3a4bb68-1bf8-4071-b5af-39425de2a7c3","user":"alexander"}
I1207 16:29:45.232558 2093539328 fetcher.cpp:376] Fetching URI '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd1'
I1207 16:29:45.232574 2093539328 fetcher.cpp:346] Downloading into cache
I1207 16:29:45.232620 2093539328 fetcher.cpp:184] Fetching URI '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd1'
I1207 16:29:45.232656 2093539328 fetcher.cpp:164] Copying resource with command:cp '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd1' '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/fetch/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/alexander/c2-cmd1'
I1207 16:29:45.236754 2093539328 fetcher.cpp:286] Fetching from cache
I1207 16:29:45.236783 2093539328 fetcher.cpp:164] Copying resource with command:cp '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/fetch/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/alexander/c2-cmd1' '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/1/runs/b3a4bb68-1bf8-4071-b5af-39425de2a7c3/cmd1'
I1207 16:29:45.240356 2093539328 fetcher.cpp:453] Fetched '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/mesos-fetcher-test-assets/cmd1' to '/tmp/FetcherCacheTest_FallbackFromEviction_12yKsN/slaves/73f8791e-f7dc-4cca-be2b-2e635d276977-S0/frameworks/73f8791e-f7dc-4cca-be2b-2e635d276977-0000/executors/1/runs/b3a4bb68-1bf8-4071-b5af-39425de2a7c3/cmd1'
End file
Begin file contents of `stdout`:
End file
End sandbox
End sandboxes
../../src/tests/fetcher_cache_tests.cpp:1319: Failure
Actual function call count doesn't match EXPECT_CALL(*fetcherProcess, run(_, _, _, _, _))...
Expected: to be called 3 times
Actual: called twice - unsatisfied and active
[ FAILED ] FetcherCacheTest.FallbackFromEviction (16125 ms)
{noformat}
> FetcherCacheTest.FallbackFromEviction is flaky
> ----------------------------------------------
>
> Key: MESOS-3755
> URL: https://issues.apache.org/jira/browse/MESOS-3755
> Project: Mesos
> Issue Type: Bug
> Components: fetcher, test
> Reporter: Anand Mazumdar
> Assignee: Jan Schlicht
> Labels: flaky-test, mesosphere
>
> Showed up on ASF CI:
> https://builds.apache.org/job/Mesos/952/COMPILER=gcc,CONFIGURATION=--verbose,OS=ubuntu:14.04,label_exp=docker%7C%7CHadoop/console
> {code}
> [ RUN ] FetcherCacheTest.FallbackFromEviction
> Using temporary directory '/tmp/FetcherCacheTest_FallbackFromEviction_KyfZRU'
> I1019 04:57:09.311411 29446 leveldb.cpp:176] Opened db in 10.086569ms
> I1019 04:57:09.314345 29446 leveldb.cpp:183] Compacted db in 2.842135ms
> I1019 04:57:09.314440 29446 leveldb.cpp:198] Created db iterator in 29521ns
> I1019 04:57:09.314460 29446 leveldb.cpp:204] Seeked to beginning of db in 3304ns
> I1019 04:57:09.314472 29446 leveldb.cpp:273] Iterated through 0 keys in the db in 288ns
> I1019 04:57:09.314538 29446 replica.cpp:746] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I1019 04:57:09.315892 29479 recover.cpp:449] Starting replica recovery
> I1019 04:57:09.316381 29479 recover.cpp:475] Replica is in EMPTY status
> I1019 04:57:09.317890 29469 replica.cpp:642] Replica in EMPTY status received a broadcasted recover request from (1557)@172.17.2.49:42763
> I1019 04:57:09.320924 29470 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I1019 04:57:09.321693 29470 recover.cpp:566] Updating replica status to STARTING
> I1019 04:57:09.322746 29470 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 763643ns
> I1019 04:57:09.322830 29470 replica.cpp:323] Persisted replica status to STARTING
> I1019 04:57:09.323094 29473 recover.cpp:475] Replica is in STARTING status
> I1019 04:57:09.324791 29471 master.cpp:376] Master 2f8cca9b-a727-4199-bec3-1529d3456817 (26f92b9cc910) started on 172.17.2.49:42763
> I1019 04:57:09.325127 29466 replica.cpp:642] Replica in STARTING status received a broadcasted recover request from (1558)@172.17.2.49:42763
> I1019 04:57:09.324827 29471 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/FetcherCacheTest_FallbackFromEviction_KyfZRU/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" --work_dir="/tmp/FetcherCacheTest_FallbackFromEviction_KyfZRU/master" --zk_session_timeout="10secs"
> I1019 04:57:09.325294 29471 master.cpp:423] Master only allowing authenticated frameworks to register
> I1019 04:57:09.325311 29471 master.cpp:428] Master only allowing authenticated slaves to register
> I1019 04:57:09.325322 29471 credentials.hpp:37] Loading credentials for authentication from '/tmp/FetcherCacheTest_FallbackFromEviction_KyfZRU/credentials'
> I1019 04:57:09.325686 29471 master.cpp:467] Using default 'crammd5' authenticator
> I1019 04:57:09.325749 29467 recover.cpp:195] Received a recover response from a replica in STARTING status
> I1019 04:57:09.325855 29471 master.cpp:504] Authorization enabled
> I1019 04:57:09.326429 29480 whitelist_watcher.cpp:79] No whitelist given
> I1019 04:57:09.326493 29480 recover.cpp:566] Updating replica status to VOTING
> I1019 04:57:09.327389 29479 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 632809ns
> I1019 04:57:09.327424 29479 replica.cpp:323] Persisted replica status to VOTING
> I1019 04:57:09.327638 29479 recover.cpp:580] Successfully joined the Paxos group
> I1019 04:57:09.327834 29479 recover.cpp:464] Recover process terminated
> I1019 04:57:09.329691 29468 hierarchical.cpp:140] Initialized hierarchical allocator process
> I1019 04:57:09.331760 29471 master.cpp:1609] The newly elected leader is master@172.17.2.49:42763 with id 2f8cca9b-a727-4199-bec3-1529d3456817
> I1019 04:57:09.331830 29471 master.cpp:1622] Elected as the leading master!
> I1019 04:57:09.331851 29471 master.cpp:1382] Recovering from registrar
> I1019 04:57:09.332181 29471 registrar.cpp:309] Recovering registrar
> I1019 04:57:09.334329 29474 log.cpp:661] Attempting to start the writer
> I1019 04:57:09.336091 29469 replica.cpp:478] Replica received implicit promise request from (1559)@172.17.2.49:42763 with proposal 1
> I1019 04:57:09.337303 29469 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 1.158388ms
> I1019 04:57:09.337357 29469 replica.cpp:345] Persisted promised to 1
> I1019 04:57:09.338634 29469 coordinator.cpp:231] Coordinator attemping to fill missing position
> I1019 04:57:09.340657 29480 replica.cpp:378] Replica received explicit promise request from (1560)@172.17.2.49:42763 for position 0 with proposal 2
> I1019 04:57:09.341295 29480 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 576216ns
> I1019 04:57:09.341327 29480 replica.cpp:681] Persisted action at 0
> I1019 04:57:09.342880 29480 replica.cpp:512] Replica received write request for position 0 from (1561)@172.17.2.49:42763
> I1019 04:57:09.342962 29480 leveldb.cpp:438] Reading position from leveldb took 37214ns
> I1019 04:57:09.344303 29480 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 1.282259ms
> I1019 04:57:09.344357 29480 replica.cpp:681] Persisted action at 0
> I1019 04:57:09.345175 29480 replica.cpp:660] Replica received learned notice for position 0 from @0.0.0.0:0
> I1019 04:57:09.346297 29480 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 1.08427ms
> I1019 04:57:09.346336 29480 replica.cpp:681] Persisted action at 0
> I1019 04:57:09.346364 29480 replica.cpp:666] Replica learned NOP action at position 0
> I1019 04:57:09.347473 29477 log.cpp:677] Writer started with ending position 0
> I1019 04:57:09.349506 29479 leveldb.cpp:438] Reading position from leveldb took 95775ns
> I1019 04:57:09.351241 29479 registrar.cpp:342] Successfully fetched the registry (0B) in 19.009792ms
> I1019 04:57:09.351526 29479 registrar.cpp:441] Applied 1 operations in 45877ns; attempting to update the 'registry'
> I1019 04:57:09.352840 29479 log.cpp:685] Attempting to append 174 bytes to the log
> I1019 04:57:09.353103 29479 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
> I1019 04:57:09.354475 29467 replica.cpp:512] Replica received write request for position 1 from (1562)@172.17.2.49:42763
> I1019 04:57:09.355309 29467 leveldb.cpp:343] Persisting action (193 bytes) to leveldb took 766051ns
> I1019 04:57:09.355348 29467 replica.cpp:681] Persisted action at 1
> I1019 04:57:09.356562 29474 replica.cpp:660] Replica received learned notice for position 1 from @0.0.0.0:0
> I1019 04:57:09.357292 29474 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 689221ns
> I1019 04:57:09.357322 29474 replica.cpp:681] Persisted action at 1
> I1019 04:57:09.357347 29474 replica.cpp:666] Replica learned APPEND action at position 1
> I1019 04:57:09.359163 29474 registrar.cpp:486] Successfully updated the 'registry' in 7.56736ms
> I1019 04:57:09.359316 29467 log.cpp:704] Attempting to truncate the log to 1
> I1019 04:57:09.359447 29474 registrar.cpp:372] Successfully recovered registrar
> I1019 04:57:09.359616 29467 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
> I1019 04:57:09.360002 29474 master.cpp:1419] Recovered 0 slaves from the Registry (135B) ; allowing 10mins for slaves to re-register
> I1019 04:57:09.361136 29465 replica.cpp:512] Replica received write request for position 2 from (1563)@172.17.2.49:42763
> I1019 04:57:09.362299 29465 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 1.093337ms
> I1019 04:57:09.362339 29465 replica.cpp:681] Persisted action at 2
> I1019 04:57:09.363440 29465 replica.cpp:660] Replica received learned notice for position 2 from @0.0.0.0:0
> I1019 04:57:09.364114 29465 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 544883ns
> I1019 04:57:09.364177 29465 leveldb.cpp:401] Deleting ~1 keys from leveldb took 33863ns
> I1019 04:57:09.364198 29465 replica.cpp:681] Persisted action at 2
> I1019 04:57:09.364223 29465 replica.cpp:666] Replica learned TRUNCATE action at position 2
> I1019 04:57:09.373134 29446 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W1019 04:57:09.373626 29446 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
> I1019 04:57:09.386418 29477 slave.cpp:191] Slave started on 50)@172.17.2.49:42763
> I1019 04:57:09.386672 29477 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --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_FallbackFromEviction_Xd4U3v/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/fetch" --fetcher_cache_size="40B" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.26.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_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v"
> I1019 04:57:09.387290 29477 credentials.hpp:85] Loading credential for authentication from '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/credential'
> I1019 04:57:09.387626 29477 slave.cpp:322] Slave using credential for: test-principal
> I1019 04:57:09.388428 29477 slave.cpp:392] Slave resources: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I1019 04:57:09.388517 29477 slave.cpp:400] Slave attributes: [ ]
> I1019 04:57:09.388535 29477 slave.cpp:405] Slave hostname: 26f92b9cc910
> I1019 04:57:09.388546 29477 slave.cpp:410] Slave checkpoint: true
> I1019 04:57:09.390626 29476 state.cpp:54] Recovering state from '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta'
> I1019 04:57:09.391163 29476 status_update_manager.cpp:202] Recovering status update manager
> I1019 04:57:09.391413 29476 containerizer.cpp:385] Recovering containerizer
> I1019 04:57:09.392730 29476 slave.cpp:4222] Finished recovery
> I1019 04:57:09.393497 29476 slave.cpp:4379] Querying resource estimator for oversubscribable resources
> I1019 04:57:09.394035 29476 slave.cpp:4393] Received oversubscribable resources from the resource estimator
> I1019 04:57:09.394387 29476 slave.cpp:726] New master detected at master@172.17.2.49:42763
> I1019 04:57:09.394520 29473 status_update_manager.cpp:176] Pausing sending status updates
> I1019 04:57:09.394666 29476 slave.cpp:789] Authenticating with master master@172.17.2.49:42763
> I1019 04:57:09.394700 29476 slave.cpp:794] Using default CRAM-MD5 authenticatee
> I1019 04:57:09.394929 29476 slave.cpp:762] Detecting new master
> I1019 04:57:09.395155 29473 authenticatee.cpp:115] Creating new client SASL connection
> I1019 04:57:09.395594 29473 master.cpp:5144] Authenticating slave(50)@172.17.2.49:42763
> I1019 04:57:09.395834 29473 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(145)@172.17.2.49:42763
> I1019 04:57:09.396229 29473 authenticator.cpp:92] Creating new server SASL connection
> I1019 04:57:09.396591 29473 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
> I1019 04:57:09.396627 29473 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1019 04:57:09.396723 29473 authenticator.cpp:197] Received SASL authentication start
> I1019 04:57:09.396809 29473 authenticator.cpp:319] Authentication requires more steps
> I1019 04:57:09.396924 29473 authenticatee.cpp:252] Received SASL authentication step
> I1019 04:57:09.397058 29473 authenticator.cpp:225] Received SASL authentication step
> I1019 04:57:09.397096 29473 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '26f92b9cc910' server FQDN: '26f92b9cc910' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1019 04:57:09.397117 29473 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
> I1019 04:57:09.397220 29473 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1019 04:57:09.397290 29473 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '26f92b9cc910' server FQDN: '26f92b9cc910' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1019 04:57:09.397335 29473 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1019 04:57:09.397347 29473 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1019 04:57:09.397367 29473 authenticator.cpp:311] Authentication success
> I1019 04:57:09.397689 29473 authenticatee.cpp:292] Authentication success
> I1019 04:57:09.397804 29480 master.cpp:5174] Successfully authenticated principal 'test-principal' at slave(50)@172.17.2.49:42763
> I1019 04:57:09.397928 29480 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(145)@172.17.2.49:42763
> I1019 04:57:09.398519 29476 slave.cpp:857] Successfully authenticated with master master@172.17.2.49:42763
> I1019 04:57:09.398952 29476 slave.cpp:1251] Will retry registration in 2.004052ms if necessary
> I1019 04:57:09.399350 29480 master.cpp:3868] Registering slave at slave(50)@172.17.2.49:42763 (26f92b9cc910) with id 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:09.400003 29480 registrar.cpp:441] Applied 1 operations in 77579ns; attempting to update the 'registry'
> I1019 04:57:09.401924 29480 log.cpp:685] Attempting to append 343 bytes to the log
> I1019 04:57:09.402417 29472 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
> I1019 04:57:09.403699 29472 slave.cpp:1251] Will retry registration in 10.397067ms if necessary
> I1019 04:57:09.404350 29470 replica.cpp:512] Replica received write request for position 3 from (1576)@172.17.2.49:42763
> I1019 04:57:09.404731 29470 leveldb.cpp:343] Persisting action (362 bytes) to leveldb took 326609ns
> I1019 04:57:09.404762 29470 replica.cpp:681] Persisted action at 3
> I1019 04:57:09.406062 29465 replica.cpp:660] Replica received learned notice for position 3 from @0.0.0.0:0
> I1019 04:57:09.406631 29465 leveldb.cpp:343] Persisting action (364 bytes) to leveldb took 530351ns
> I1019 04:57:09.406663 29465 replica.cpp:681] Persisted action at 3
> I1019 04:57:09.406693 29465 replica.cpp:666] Replica learned APPEND action at position 3
> I1019 04:57:09.409371 29468 registrar.cpp:486] Successfully updated the 'registry' in 8.966912ms
> I1019 04:57:09.410024 29472 master.cpp:3856] Ignoring register slave message from slave(50)@172.17.2.49:42763 (26f92b9cc910) as admission is already in progress
> I1019 04:57:09.410783 29475 slave.cpp:3212] Received ping from slave-observer(47)@172.17.2.49:42763
> I1019 04:57:09.411249 29480 log.cpp:704] Attempting to truncate the log to 3
> I1019 04:57:09.411998 29480 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
> I1019 04:57:09.413143 29468 replica.cpp:512] Replica received write request for position 4 from (1577)@172.17.2.49:42763
> I1019 04:57:09.411582 29469 hierarchical.cpp:335] Added slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 (26f92b9cc910) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I1019 04:57:09.413777 29469 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:09.413838 29469 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:09.413874 29469 hierarchical.cpp:867] Performed allocation for slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 in 328338ns
> I1019 04:57:09.411664 29474 slave.cpp:901] Registered with master master@172.17.2.49:42763; given slave ID 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:09.413960 29474 fetcher.cpp:79] Clearing fetcher cache
> I1019 04:57:09.414439 29474 slave.cpp:924] Checkpointing SlaveInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/slave.info'
> I1019 04:57:09.414886 29473 status_update_manager.cpp:183] Resuming sending status updates
> I1019 04:57:09.415091 29474 slave.cpp:960] Forwarding total oversubscribed resources
> I1019 04:57:09.415591 29468 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 2.394464ms
> I1019 04:57:09.415638 29468 replica.cpp:681] Persisted action at 4
> I1019 04:57:09.411360 29472 master.cpp:3936] Registered slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I1019 04:57:09.416435 29472 master.cpp:4278] Received update of slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910) with total oversubscribed resources
> I1019 04:57:09.417014 29480 hierarchical.cpp:391] Slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 (26f92b9cc910) updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I1019 04:57:09.417172 29473 replica.cpp:660] Replica received learned notice for position 4 from @0.0.0.0:0
> I1019 04:57:09.417340 29480 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:09.417500 29480 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:09.417570 29480 hierarchical.cpp:867] Performed allocation for slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 in 509142ns
> I1019 04:57:09.418155 29473 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 952413ns
> I1019 04:57:09.418234 29473 leveldb.cpp:401] Deleting ~2 keys from leveldb took 50752ns
> I1019 04:57:09.418273 29473 replica.cpp:681] Persisted action at 4
> I1019 04:57:09.418315 29473 replica.cpp:666] Replica learned TRUNCATE action at position 4
> I1019 04:57:10.331061 29474 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:10.331156 29474 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:10.331195 29474 hierarchical.cpp:851] Performed allocation for 1 slaves in 427275ns
> I1019 04:57:11.332774 29477 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:11.332867 29477 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:11.332907 29477 hierarchical.cpp:851] Performed allocation for 1 slaves in 461427ns
> I1019 04:57:12.334422 29466 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:12.334512 29466 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:12.334544 29466 hierarchical.cpp:851] Performed allocation for 1 slaves in 418739ns
> I1019 04:57:13.335605 29473 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:13.335702 29473 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:13.335741 29473 hierarchical.cpp:851] Performed allocation for 1 slaves in 442967ns
> I1019 04:57:14.336596 29472 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:14.336673 29472 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:14.336704 29472 hierarchical.cpp:851] Performed allocation for 1 slaves in 375625ns
> I1019 04:57:15.337990 29473 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:15.338081 29473 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:15.338120 29473 hierarchical.cpp:851] Performed allocation for 1 slaves in 425138ns
> I1019 04:57:16.339422 29472 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:16.339510 29472 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:16.339550 29472 hierarchical.cpp:851] Performed allocation for 1 slaves in 434932ns
> I1019 04:57:17.341084 29478 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:17.341163 29478 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:17.341191 29478 hierarchical.cpp:851] Performed allocation for 1 slaves in 457545ns
> I1019 04:57:18.342689 29476 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:18.342784 29476 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:18.342825 29476 hierarchical.cpp:851] Performed allocation for 1 slaves in 439250ns
> I1019 04:57:19.344156 29475 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:19.344249 29475 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:19.344300 29475 hierarchical.cpp:851] Performed allocation for 1 slaves in 426393ns
> I1019 04:57:20.345165 29467 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:20.345268 29467 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:20.345307 29467 hierarchical.cpp:851] Performed allocation for 1 slaves in 445666ns
> I1019 04:57:21.345991 29474 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:21.346074 29474 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:21.346109 29474 hierarchical.cpp:851] Performed allocation for 1 slaves in 399659ns
> I1019 04:57:22.347188 29465 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:22.347282 29465 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:22.347321 29465 hierarchical.cpp:851] Performed allocation for 1 slaves in 387060ns
> I1019 04:57:23.348729 29480 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:23.348805 29480 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:23.348831 29480 hierarchical.cpp:851] Performed allocation for 1 slaves in 352043ns
> I1019 04:57:24.350011 29478 hierarchical.cpp:952] No resources available to allocate!
> I1019 04:57:24.350105 29478 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:24.350142 29478 hierarchical.cpp:851] Performed allocation for 1 slaves in 432494ns
> I1019 04:57:24.395115 29478 slave.cpp:4379] Querying resource estimator for oversubscribable resources
> I1019 04:57:24.395454 29478 slave.cpp:4393] Received oversubscribable resources from the resource estimator
> I1019 04:57:24.411938 29475 slave.cpp:3212] Received ping from slave-observer(47)@172.17.2.49:42763
> ../../src/tests/fetcher_cache_tests.cpp:289: Failure
> Failed to wait 15secs for slaveRegisteredMessage
> I1019 04:57:24.421470 29446 sched.cpp:166] Version: 0.26.0
> I1019 04:57:24.422117 29466 sched.cpp:264] New master detected at master@172.17.2.49:42763
> I1019 04:57:24.422235 29466 sched.cpp:320] Authenticating with master master@172.17.2.49:42763
> I1019 04:57:24.422267 29466 sched.cpp:327] Using default CRAM-MD5 authenticatee
> I1019 04:57:24.422559 29479 authenticatee.cpp:115] Creating new client SASL connection
> I1019 04:57:24.422829 29477 master.cpp:5144] Authenticating scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:24.422953 29466 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(146)@172.17.2.49:42763
> I1019 04:57:24.423233 29477 authenticator.cpp:92] Creating new server SASL connection
> I1019 04:57:24.423462 29466 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
> I1019 04:57:24.423494 29466 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1019 04:57:24.423600 29466 authenticator.cpp:197] Received SASL authentication start
> I1019 04:57:24.423660 29466 authenticator.cpp:319] Authentication requires more steps
> I1019 04:57:24.423749 29466 authenticatee.cpp:252] Received SASL authentication step
> I1019 04:57:24.423854 29466 authenticator.cpp:225] Received SASL authentication step
> I1019 04:57:24.423885 29466 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '26f92b9cc910' server FQDN: '26f92b9cc910' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1019 04:57:24.423902 29466 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
> I1019 04:57:24.423960 29466 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1019 04:57:24.424003 29466 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '26f92b9cc910' server FQDN: '26f92b9cc910' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1019 04:57:24.424021 29466 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1019 04:57:24.424031 29466 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1019 04:57:24.424049 29466 authenticator.cpp:311] Authentication success
> I1019 04:57:24.424221 29466 authenticatee.cpp:292] Authentication success
> I1019 04:57:24.424334 29466 master.cpp:5174] Successfully authenticated principal 'test-principal' at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:24.424456 29469 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(146)@172.17.2.49:42763
> I1019 04:57:24.424891 29474 sched.cpp:409] Successfully authenticated with master master@172.17.2.49:42763
> I1019 04:57:24.424918 29474 sched.cpp:716] Sending SUBSCRIBE call to master@172.17.2.49:42763
> I1019 04:57:24.425039 29474 sched.cpp:749] Will retry registration in 154.578589ms if necessary
> I1019 04:57:24.425163 29477 master.cpp:2185] Received SUBSCRIBE call for framework 'default' at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> W1019 04:57:24.425197 29477 master.cpp:2192] Framework at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> I1019 04:57:24.425268 29477 master.cpp:1648] Authorizing framework principal '' to receive offers for role '*'
> I1019 04:57:24.425617 29472 master.cpp:2256] Subscribing framework default with checkpointing enabled and capabilities [ ]
> I1019 04:57:24.426018 29478 hierarchical.cpp:185] Added framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.426162 29470 sched.cpp:643] Framework registered with 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.426214 29470 sched.cpp:657] Scheduler::registered took 23224ns
> I1019 04:57:24.426890 29478 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:24.426944 29478 hierarchical.cpp:851] Performed allocation for 1 slaves in 900692ns
> I1019 04:57:24.427212 29472 master.cpp:4973] Sending 1 offers to framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:24.427757 29479 sched.cpp:813] Scheduler::resourceOffers took 128601ns
> I1019 04:57:24.429461 29476 master.cpp:2924] Processing ACCEPT call for offers: [ 2f8cca9b-a727-4199-bec3-1529d3456817-O0 ] on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910) for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:24.429515 29476 master.cpp:2720] Authorizing framework principal '' to launch task 0 as user 'mesos'
> I1019 04:57:24.430940 29476 master.hpp:176] Adding task 0 with resources cpus(*):1; mem(*):1 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 (26f92b9cc910)
> I1019 04:57:24.431069 29476 master.cpp:3254] Launching task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 with resources cpus(*):1; mem(*):1 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:24.431426 29468 slave.cpp:1291] Got assigned task 0 for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.431607 29468 slave.cpp:4915] Checkpointing FrameworkInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/framework.info'
> I1019 04:57:24.431823 29476 hierarchical.cpp:739] 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 slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 from framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.431897 29476 hierarchical.cpp:776] Framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 filtered slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 for 5secs
> I1019 04:57:24.432140 29468 slave.cpp:4926] Checkpointing framework pid 'scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763' to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/framework.pid'
> I1019 04:57:24.433055 29468 slave.cpp:1407] Launching task 0 for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.438769 29468 slave.cpp:5351] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/executor.info'
> I1019 04:57:24.439752 29468 slave.cpp:4994] Launching executor 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/a10b1250-049e-4daf-b106-84ae83afdcd4'
> I1019 04:57:24.440444 29474 containerizer.cpp:639] Starting container 'a10b1250-049e-4daf-b106-84ae83afdcd4' for executor '0' of framework '2f8cca9b-a727-4199-bec3-1529d3456817-0000'
> I1019 04:57:24.440497 29468 slave.cpp:5374] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/a10b1250-049e-4daf-b106-84ae83afdcd4/tasks/0/task.info'
> I1019 04:57:24.441014 29468 slave.cpp:1625] Queuing task '0' for executor 0 of framework '2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.441145 29468 slave.cpp:679] Successfully attached file '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/a10b1250-049e-4daf-b106-84ae83afdcd4'
> I1019 04:57:24.444752 29471 launcher.cpp:132] Forked child with pid '486' for container 'a10b1250-049e-4daf-b106-84ae83afdcd4'
> I1019 04:57:24.445034 29471 containerizer.cpp:872] Checkpointing executor's forked pid 486 to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/a10b1250-049e-4daf-b106-84ae83afdcd4/pids/forked.pid'
> I1019 04:57:24.448362 29465 fetcher.cpp:301] Starting to fetch URIs for container: a10b1250-049e-4daf-b106-84ae83afdcd4, directory: /tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/a10b1250-049e-4daf-b106-84ae83afdcd4
> I1019 04:57:24.453506 29465 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd0' with file: c1-cmd0
> I1019 04:57:24.454756 29480 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd0
> I1019 04:57:24.457115 29465 fetcher.cpp:665] Claiming fetcher cache space for: mesos@/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd0
> I1019 04:57:24.457149 29465 fetcher.cpp:1110] Claimed cache space: 30B, now using: 30B
> I1019 04:57:24.463912 29477 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
> I1019 04:57:24.600153 29477 fetcher.cpp:1122] Released cache space: 0B, now using: 30B
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1019 04:57:24.683722 525 process.cpp:968] libprocess is initialized on 172.17.2.49:58172 for 16 cpus
> I1019 04:57:24.684742 525 logging.cpp:177] Logging to STDERR
> I1019 04:57:24.687618 525 exec.cpp:136] Version: 0.26.0
> I1019 04:57:24.695040 551 exec.cpp:186] Executor started at: executor(1)@172.17.2.49:58172 with pid 525
> I1019 04:57:24.697676 29466 slave.cpp:2415] Got registration for executor '0' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from executor(1)@172.17.2.49:58172
> I1019 04:57:24.697815 29466 slave.cpp:2501] Checkpointing executor pid 'executor(1)@172.17.2.49:58172' to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/a10b1250-049e-4daf-b106-84ae83afdcd4/pids/libprocess.pid'
> I1019 04:57:24.700615 29465 slave.cpp:1796] Sending queued task '0' to executor '0' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.700831 547 exec.cpp:210] Executor registered on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:24.702958 547 exec.cpp:222] Executor::registered took 290745ns
> Registered executor on 26f92b9cc910
> I1019 04:57:24.703323 547 exec.cpp:297] Executor asked to run task '0'
> I1019 04:57:24.703418 547 exec.cpp:306] Executor::launchTask took 70892ns
> Starting task 0
> Forked command at 556
> sh -c './cmd0 0'
> I1019 04:57:24.707320 544 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.708860 29480 slave.cpp:2778] Handling status update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from executor(1)@172.17.2.49:58172
> I1019 04:57:24.709362 29465 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.709411 29465 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.710072 29465 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.711269 29465 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to the slave
> I1019 04:57:24.711637 29465 slave.cpp:3090] Forwarding the update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to master@172.17.2.49:42763
> I1019 04:57:24.711779 29465 slave.cpp:3014] Status update manager successfully handled status update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.711809 29465 slave.cpp:3020] Sending acknowledgement for status update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to executor(1)@172.17.2.49:58172
> I1019 04:57:24.712242 29480 master.cpp:4421] Status update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:24.712523 29480 master.cpp:4460] Forwarding status update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.712935 29480 master.cpp:6086] Updating the latest state of task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to TASK_RUNNING
> I1019 04:57:24.713146 29465 sched.cpp:920] Scheduler::statusUpdate took 138673ns
> I1019 04:57:24.713323 547 exec.cpp:343] Executor received status update acknowledgement 9d00f0aa-c366-4514-95e6-dab43448125e for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.713556 29480 master.cpp:3612] Processing ACKNOWLEDGE call 9d00f0aa-c366-4514-95e6-dab43448125e for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:24.714046 29475 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.714458 29475 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.715454 29475 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: 9d00f0aa-c366-4514-95e6-dab43448125e) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> Command exited with status 0 (pid: 556)
> I1019 04:57:24.808979 546 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.810267 29479 slave.cpp:2778] Handling status update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from executor(1)@172.17.2.49:58172
> I1019 04:57:24.810483 29479 slave.cpp:5289] Terminating task 0
> I1019 04:57:24.811733 29468 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.811815 29468 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.812860 29468 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to the slave
> I1019 04:57:24.813191 29476 slave.cpp:3090] Forwarding the update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to master@172.17.2.49:42763
> I1019 04:57:24.813397 29476 slave.cpp:3014] Status update manager successfully handled status update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.813427 29476 slave.cpp:3020] Sending acknowledgement for status update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to executor(1)@172.17.2.49:58172
> I1019 04:57:24.813634 29478 master.cpp:4421] Status update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:24.813685 29478 master.cpp:4460] Forwarding status update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.813892 29478 master.cpp:6086] Updating the latest state of task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to TASK_FINISHED
> I1019 04:57:24.814155 29476 sched.cpp:920] Scheduler::statusUpdate took 127673ns
> I1019 04:57:24.814463 29478 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 from framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.814555 29476 master.cpp:6154] Removing task 0 with resources cpus(*):1; mem(*):1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:24.814724 29476 master.cpp:3612] Processing ACKNOWLEDGE call 1637b611-9277-4596-b95a-f8bad14c7465 for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:24.815021 29476 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.815160 547 exec.cpp:343] Executor received status update acknowledgement 1637b611-9277-4596-b95a-f8bad14c7465 for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.815171 29476 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FINISHED (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> ../../src/tests/fetcher_cache_tests.cpp:347: Failure
> access: No such file or directory
> ../../src/tests/fetcher_cache_tests.cpp:1355: Failure
> Value of: isExecutable( path::join(task0.get().runDirectory.value, commandFilename0))
> Actual: false
> Expected: true
> ../../src/tests/fetcher_cache_tests.cpp:1357: Failure
> Value of: os::exists( path::join(task0.get().runDirectory.value, COMMAND_NAME + taskName(0)))
> Actual: false
> Expected: true
> I1019 04:57:24.816639 29476 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.817061 29470 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: 1637b611-9277-4596-b95a-f8bad14c7465) for task 0 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:24.817129 29470 slave.cpp:5330] Completing task 0
> I1019 04:57:25.351634 29478 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:25.351707 29478 hierarchical.cpp:851] Performed allocation for 1 slaves in 821455ns
> I1019 04:57:25.352063 29480 master.cpp:4973] Sending 1 offers to framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:25.352634 29480 sched.cpp:813] Scheduler::resourceOffers took 113773ns
> I1019 04:57:25.354380 29480 master.cpp:2924] Processing ACCEPT call for offers: [ 2f8cca9b-a727-4199-bec3-1529d3456817-O1 ] on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910) for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:25.354430 29480 master.cpp:2720] Authorizing framework principal '' to launch task 1 as user 'mesos'
> I1019 04:57:25.355931 29479 master.hpp:176] Adding task 1 with resources cpus(*):1; mem(*):1 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 (26f92b9cc910)
> I1019 04:57:25.356034 29479 master.cpp:3254] Launching task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 with resources cpus(*):1; mem(*):1 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:25.356412 29472 slave.cpp:1291] Got assigned task 1 for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.356850 29478 hierarchical.cpp:739] 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 slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 from framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.356935 29478 hierarchical.cpp:776] Framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 filtered slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 for 5secs
> I1019 04:57:25.357030 29472 slave.cpp:1407] Launching task 1 for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.361490 29472 slave.cpp:5351] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/executor.info'
> I1019 04:57:25.362288 29472 slave.cpp:4994] Launching executor 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/3983ba52-b308-4411-899d-8640ae410369'
> I1019 04:57:25.362972 29470 containerizer.cpp:639] Starting container '3983ba52-b308-4411-899d-8640ae410369' for executor '1' of framework '2f8cca9b-a727-4199-bec3-1529d3456817-0000'
> I1019 04:57:25.363062 29472 slave.cpp:5374] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/3983ba52-b308-4411-899d-8640ae410369/tasks/1/task.info'
> I1019 04:57:25.363564 29472 slave.cpp:1625] Queuing task '1' for executor 1 of framework '2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.363674 29472 slave.cpp:679] Successfully attached file '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/3983ba52-b308-4411-899d-8640ae410369'
> I1019 04:57:25.367036 29468 launcher.cpp:132] Forked child with pid '561' for container '3983ba52-b308-4411-899d-8640ae410369'
> I1019 04:57:25.367264 29468 containerizer.cpp:872] Checkpointing executor's forked pid 561 to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/3983ba52-b308-4411-899d-8640ae410369/pids/forked.pid'
> I1019 04:57:25.370226 29476 fetcher.cpp:301] Starting to fetch URIs for container: 3983ba52-b308-4411-899d-8640ae410369, directory: /tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/3983ba52-b308-4411-899d-8640ae410369
> I1019 04:57:25.376375 29476 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd1' with file: c2-cmd1
> I1019 04:57:25.377418 29468 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd1
> I1019 04:57:25.379102 29476 fetcher.cpp:1031] Freeing up fetcher cache space for: 30B
> I1019 04:57:25.379163 29476 fetcher.cpp:967] Removing cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd0' with filename: c1-cmd0
> I1019 04:57:25.379442 29476 fetcher.cpp:1122] Released cache space: 30B, now using: 0B
> I1019 04:57:25.379478 29476 fetcher.cpp:665] Claiming fetcher cache space for: mesos@/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd1
> I1019 04:57:25.379497 29476 fetcher.cpp:1110] Claimed cache space: 40B, now using: 40B
> I1019 04:57:25.384996 29468 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
> I1019 04:57:25.508708 29473 fetcher.cpp:1122] Released cache space: 0B, now using: 40B
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1019 04:57:25.587517 600 process.cpp:968] libprocess is initialized on 172.17.2.49:38308 for 16 cpus
> I1019 04:57:25.591351 600 logging.cpp:177] Logging to STDERR
> I1019 04:57:25.595842 600 exec.cpp:136] Version: 0.26.0
> I1019 04:57:25.600965 628 exec.cpp:186] Executor started at: executor(1)@172.17.2.49:38308 with pid 600
> I1019 04:57:25.604195 29473 slave.cpp:2415] Got registration for executor '1' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from executor(1)@172.17.2.49:38308
> I1019 04:57:25.604346 29473 slave.cpp:2501] Checkpointing executor pid 'executor(1)@172.17.2.49:38308' to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/3983ba52-b308-4411-899d-8640ae410369/pids/libprocess.pid'
> I1019 04:57:25.606540 29479 slave.cpp:1796] Sending queued task '1' to executor '1' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.607420 618 exec.cpp:210] Executor registered on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:25.609412 618 exec.cpp:222] Executor::registered took 325674ns
> Registered executor on 26f92b9cc910
> I1019 04:57:25.609809 618 exec.cpp:297] Executor asked to run task '1'
> Starting task 1
> I1019 04:57:25.609942 618 exec.cpp:306] Executor::launchTask took 107095ns
> Forked command at 631
> sh -c './cmd1 1'
> I1019 04:57:25.613590 617 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.614697 29466 slave.cpp:2778] Handling status update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from executor(1)@172.17.2.49:38308
> I1019 04:57:25.615073 29479 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.615121 29479 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.615700 29479 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.616911 29479 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to the slave
> I1019 04:57:25.617133 29469 slave.cpp:3090] Forwarding the update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to master@172.17.2.49:42763
> I1019 04:57:25.617388 29469 slave.cpp:3014] Status update manager successfully handled status update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.617424 29469 slave.cpp:3020] Sending acknowledgement for status update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to executor(1)@172.17.2.49:38308
> I1019 04:57:25.617544 29467 master.cpp:4421] Status update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:25.617588 29467 master.cpp:4460] Forwarding status update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.617769 29467 master.cpp:6086] Updating the latest state of task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to TASK_RUNNING
> I1019 04:57:25.618140 29476 sched.cpp:920] Scheduler::statusUpdate took 174934ns
> I1019 04:57:25.618484 29465 master.cpp:3612] Processing ACKNOWLEDGE call 35be859d-dfa9-4efb-9ba8-9667e0cdd233 for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:25.618654 621 exec.cpp:343] Executor received status update acknowledgement 35be859d-dfa9-4efb-9ba8-9667e0cdd233 for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.618737 29476 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.618888 29476 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.619743 29465 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: 35be859d-dfa9-4efb-9ba8-9667e0cdd233) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> Command exited with status 0 (pid: 631)
> I1019 04:57:25.714745 616 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.715857 29473 slave.cpp:2778] Handling status update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from executor(1)@172.17.2.49:38308
> I1019 04:57:25.716056 29473 slave.cpp:5289] Terminating task 1
> I1019 04:57:25.717303 29476 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.717381 29476 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.718417 29476 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to the slave
> I1019 04:57:25.718724 29474 slave.cpp:3090] Forwarding the update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to master@172.17.2.49:42763
> I1019 04:57:25.718955 29474 slave.cpp:3014] Status update manager successfully handled status update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.718998 29474 slave.cpp:3020] Sending acknowledgement for status update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to executor(1)@172.17.2.49:38308
> I1019 04:57:25.719074 29476 master.cpp:4421] Status update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:25.719126 29476 master.cpp:4460] Forwarding status update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.719321 29476 master.cpp:6086] Updating the latest state of task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to TASK_FINISHED
> I1019 04:57:25.719682 29476 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 from framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.719810 29474 sched.cpp:920] Scheduler::statusUpdate took 180299ns
> ../../src/tests/fetcher_cache_tests.cpp:347: Failure
> access: No such file or directory
> ../../src/tests/fetcher_cache_tests.cpp:1404: Failure
> Value of: isExecutable( path::join(task1.get().runDirectory.value, commandFilename1))
> Actual: false
> Expected: true
> ../../src/tests/fetcher_cache_tests.cpp:1406: Failure
> Value of: os::exists( path::join(task1.get().runDirectory.value, COMMAND_NAME + taskName(1)))
> Actual: false
> Expected: true
> I1019 04:57:25.720315 29465 master.cpp:6154] Removing task 1 with resources cpus(*):1; mem(*):1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:25.720490 29465 master.cpp:3612] Processing ACKNOWLEDGE call d374813c-4c5c-42a6-a7a6-01542dee9060 for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:25.720793 29468 status_update_manager.cpp:394] Received status update acknowledgement (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.720909 29468 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FINISHED (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.721073 628 exec.cpp:343] Executor received status update acknowledgement d374813c-4c5c-42a6-a7a6-01542dee9060 for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.721751 29468 status_update_manager.cpp:530] Cleaning up status update stream for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.722187 29472 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: d374813c-4c5c-42a6-a7a6-01542dee9060) for task 1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.722239 29472 slave.cpp:5330] Completing task 1
> I1019 04:57:25.912261 29472 containerizer.cpp:1278] Executor for container 'a10b1250-049e-4daf-b106-84ae83afdcd4' has exited
> I1019 04:57:25.912317 29472 containerizer.cpp:1095] Destroying container 'a10b1250-049e-4daf-b106-84ae83afdcd4'
> I1019 04:57:25.916136 29479 slave.cpp:3542] Executor '0' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 exited with status 0
> I1019 04:57:25.916224 29479 slave.cpp:3646] Cleaning up executor '0' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:25.916610 29469 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/a10b1250-049e-4daf-b106-84ae83afdcd4' for gc 6.99998939204741days in the future
> I1019 04:57:25.916764 29469 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0' for gc 6.99998939018667days in the future
> I1019 04:57:25.916880 29469 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/a10b1250-049e-4daf-b106-84ae83afdcd4' for gc 6.99998938907259days in the future
> I1019 04:57:25.916960 29469 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0' for gc 6.9999893879763days in the future
> I1019 04:57:26.353588 29474 hierarchical.cpp:1045] No inverse offers to send out!
> I1019 04:57:26.353662 29474 hierarchical.cpp:851] Performed allocation for 1 slaves in 961121ns
> I1019 04:57:26.354140 29474 master.cpp:4973] Sending 1 offers to framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:26.354676 29474 sched.cpp:813] Scheduler::resourceOffers took 130483ns
> I1019 04:57:26.356875 29474 master.cpp:2924] Processing ACCEPT call for offers: [ 2f8cca9b-a727-4199-bec3-1529d3456817-O2 ] on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910) for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:26.356932 29474 master.cpp:2720] Authorizing framework principal '' to launch task 2 as user 'mesos'
> I1019 04:57:26.358589 29474 master.hpp:176] Adding task 2 with resources cpus(*):1; mem(*):1 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 (26f92b9cc910)
> I1019 04:57:26.358700 29474 master.cpp:3254] Launching task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 with resources cpus(*):1; mem(*):1 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:26.359005 29467 slave.cpp:1291] Got assigned task 2 for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.359287 29474 hierarchical.cpp:739] 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 slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 from framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.359346 29474 hierarchical.cpp:776] Framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 filtered slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 for 5secs
> I1019 04:57:26.359705 29467 slave.cpp:1407] Launching task 2 for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.364697 29467 slave.cpp:5351] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/executor.info'
> I1019 04:57:26.365528 29467 slave.cpp:4994] Launching executor 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/2805d07d-71a7-48bb-be21-7e29d6db6e84'
> I1019 04:57:26.366124 29465 containerizer.cpp:639] Starting container '2805d07d-71a7-48bb-be21-7e29d6db6e84' for executor '2' of framework '2f8cca9b-a727-4199-bec3-1529d3456817-0000'
> I1019 04:57:26.366168 29467 slave.cpp:5374] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/2805d07d-71a7-48bb-be21-7e29d6db6e84/tasks/2/task.info'
> I1019 04:57:26.366616 29467 slave.cpp:1625] Queuing task '2' for executor 2 of framework '2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.366755 29467 slave.cpp:679] Successfully attached file '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/2805d07d-71a7-48bb-be21-7e29d6db6e84'
> I1019 04:57:26.369740 29472 launcher.cpp:132] Forked child with pid '636' for container '2805d07d-71a7-48bb-be21-7e29d6db6e84'
> I1019 04:57:26.369951 29472 containerizer.cpp:872] Checkpointing executor's forked pid 636 to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/2805d07d-71a7-48bb-be21-7e29d6db6e84/pids/forked.pid'
> I1019 04:57:26.372288 29466 fetcher.cpp:301] Starting to fetch URIs for container: 2805d07d-71a7-48bb-be21-7e29d6db6e84, directory: /tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/2805d07d-71a7-48bb-be21-7e29d6db6e84
> I1019 04:57:26.375838 29466 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd2' with file: c3-cmd2
> I1019 04:57:26.376973 29471 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd2
> I1019 04:57:26.379469 29466 fetcher.cpp:1031] Freeing up fetcher cache space for: 50B
> I1019 04:57:26.379555 29466 fetcher.cpp:967] Removing cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd2' with filename: c3-cmd2
> W1019 04:57:26.380565 29466 fetcher.cpp:438] Reverting to fetching directly into the sandbox for '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/mesos-fetcher-test-assets/cmd2', due to failure to fetch through the cache, with error: Failed to reserve space in the cache: Could not free up enough fetcher cache space
> I1019 04:57:26.384846 29466 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1019 04:57:26.587430 673 process.cpp:968] libprocess is initialized on 172.17.2.49:59130 for 16 cpus
> I1019 04:57:26.588117 673 logging.cpp:177] Logging to STDERR
> I1019 04:57:26.590126 673 exec.cpp:136] Version: 0.26.0
> I1019 04:57:26.596298 700 exec.cpp:186] Executor started at: executor(1)@172.17.2.49:59130 with pid 673
> I1019 04:57:26.598784 29474 slave.cpp:2415] Got registration for executor '2' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from executor(1)@172.17.2.49:59130
> I1019 04:57:26.598914 29474 slave.cpp:2501] Checkpointing executor pid 'executor(1)@172.17.2.49:59130' to '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/2805d07d-71a7-48bb-be21-7e29d6db6e84/pids/libprocess.pid'
> I1019 04:57:26.601294 29466 slave.cpp:1796] Sending queued task '2' to executor '2' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.601531 699 exec.cpp:210] Executor registered on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:26.603502 699 exec.cpp:222] Executor::registered took 276632ns
> Registered executor on 26f92b9cc910
> I1019 04:57:26.603796 699 exec.cpp:297] Executor asked to run task '2'
> I1019 04:57:26.603917 699 exec.cpp:306] Executor::launchTask took 84549ns
> Starting task 2
> Forked command at 704
> sh -c './cmd2 2'
> I1019 04:57:26.606669 699 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.607658 29478 slave.cpp:2778] Handling status update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from executor(1)@172.17.2.49:59130
> I1019 04:57:26.608012 29473 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.608054 29473 status_update_manager.cpp:499] Creating StatusUpdate stream for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.608526 29473 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.609452 29473 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to the slave
> I1019 04:57:26.609715 29467 slave.cpp:3090] Forwarding the update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to master@172.17.2.49:42763
> I1019 04:57:26.609940 29467 slave.cpp:3014] Status update manager successfully handled status update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.609974 29467 slave.cpp:3020] Sending acknowledgement for status update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to executor(1)@172.17.2.49:59130
> I1019 04:57:26.610065 29472 master.cpp:4421] Status update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:26.610107 29472 master.cpp:4460] Forwarding status update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.610270 29472 master.cpp:6086] Updating the latest state of task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to TASK_RUNNING
> I1019 04:57:26.610637 29470 sched.cpp:920] Scheduler::statusUpdate took 169744ns
> II1019 04:57:26.611011 29470 master.cpp:3612] Processing ACKNOWLEDGE call e6b5d99c-a2c6-42f1-8d80-e63c1f60805c for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> 1019 04:57:26.611064 690 exec.cpp:343] Executor received status update acknowledgement e6b5d99c-a2c6-42f1-8d80-e63c1f60805c for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.611379 29474 status_update_manager.cpp:394] Received status update acknowledgement (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.611518 29474 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.612284 29472 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: e6b5d99c-a2c6-42f1-8d80-e63c1f60805c) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> Command exited with status 0 (pid: 704)
> I1019 04:57:26.709445 698 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.710645 29469 slave.cpp:2778] Handling status update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from executor(1)@172.17.2.49:59130
> I1019 04:57:26.710849 29469 slave.cpp:5289] Terminating task 2
> I1019 04:57:26.712038 29478 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.712110 29478 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.712962 29478 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to the slave
> I1019 04:57:26.713237 29479 slave.cpp:3090] Forwarding the update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to master@172.17.2.49:42763
> I1019 04:57:26.713429 29479 slave.cpp:3014] Status update manager successfully handled status update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.713464 29479 slave.cpp:3020] Sending acknowledgement for status update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to executor(1)@172.17.2.49:59130
> I1019 04:57:26.713615 29472 master.cpp:4421] Status update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 from slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:26.713673 29472 master.cpp:4460] Forwarding status update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.714195 29476 sched.cpp:920] Scheduler::statusUpdate took 173314ns
> I1019 04:57:26.714344 29472 master.cpp:6086] Updating the latest state of task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 to TASK_FINISHED
> ../../src/tests/fetcher_cache_tests.cpp:347: Failure
> access: No such file or directory
> ../../src/tests/fetcher_cache_tests.cpp:1452: Failure
> Value of: isExecutable( path::join(task2.get().runDirectory.value, commandFilename2))
> Actual: false
> Expected: true
> ../../src/tests/fetcher_cache_tests.cpp:1454: Failure
> Value of: os::exists( path::join(task2.get().runDirectory.value, COMMAND_NAME + taskName(2)))
> Actual: false
> Expected: true
> I1019 04:57:26.714762 29469 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 from framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.714831 29472 master.cpp:6154] Removing task 2 with resources cpus(*):1; mem(*):1 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0 at slave(50)@172.17.2.49:42763 (26f92b9cc910)
> I1019 04:57:26.715010 29472 master.cpp:3612] Processing ACKNOWLEDGE call 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6 for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 on slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:26.715333 691 exec.cpp:343] Executor received status update acknowledgement 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6 for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.715401 29470 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.715546 29470 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FINISHED (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> Begin listing sandboxes
> Could not list sandbox `/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/latest`: Failed to opendir '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/0/runs/latest': No such file or directory
> Could not list sandbox `/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/latest`: Failed to opendir '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/latest': No such file or directory
> Could not list sandbox `/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/latest`: Failed to opendir '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/latest': No such file or directory
> End sandboxes
> I1019 04:57:26.715937 29446 sched.cpp:1781] Asked to stop the driver
> I1019 04:57:26.716106 29470 status_update_manager.cpp:530] Cleaning up status update stream for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.716197 29467 master.cpp:1125] Framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 disconnected
> I1019 04:57:26.716222 29467 master.cpp:2481] Disconnecting framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:26.716248 29467 master.cpp:2505] Deactivating framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763
> I1019 04:57:26.716359 29467 master.cpp:1149] Giving framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 (default) at scheduler-e1cb738e-750f-424e-8e03-d6006b558423@172.17.2.49:42763 0ns to failover
> I1019 04:57:26.716401 29475 hierarchical.cpp:263] Deactivated framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.716675 29469 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: 1fbacc3d-0fc8-4017-8b8e-68aae5fa22f6) for task 2 of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.716728 29469 slave.cpp:5330] Completing task 2
> I1019 04:57:26.717442 29468 master.cpp:925] Master terminating
> I1019 04:57:26.717738 29467 hierarchical.cpp:364] Removed slave 2f8cca9b-a727-4199-bec3-1529d3456817-S0
> I1019 04:57:26.717835 29467 hierarchical.cpp:220] Removed framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.718152 29472 slave.cpp:3258] master@172.17.2.49:42763 exited
> W1019 04:57:26.718269 29472 slave.cpp:3261] Master disconnected! Waiting for a new master to be elected
> I1019 04:57:26.720774 29478 containerizer.cpp:1278] Executor for container '3983ba52-b308-4411-899d-8640ae410369' has exited
> I1019 04:57:26.720800 29478 containerizer.cpp:1095] Destroying container '3983ba52-b308-4411-899d-8640ae410369'
> I1019 04:57:26.724529 29480 slave.cpp:3542] Executor '1' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 exited with status 0
> I1019 04:57:26.724604 29480 slave.cpp:3646] Cleaning up executor '1' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.724980 29466 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/3983ba52-b308-4411-899d-8640ae410369' for gc 6.99999161052148days in the future
> I1019 04:57:26.725137 29472 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1' for gc 6.99999160806519days in the future
> I1019 04:57:26.725244 29472 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1/runs/3983ba52-b308-4411-899d-8640ae410369' for gc 6.99999160661037days in the future
> I1019 04:57:26.725389 29466 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/1' for gc 6.99999160517333days in the future
> I1019 04:57:26.725872 29470 containerizer.cpp:1095] Destroying container '2805d07d-71a7-48bb-be21-7e29d6db6e84'
> I1019 04:57:26.822458 29480 containerizer.cpp:1278] Executor for container '2805d07d-71a7-48bb-be21-7e29d6db6e84' has exited
> I1019 04:57:26.824055 29470 slave.cpp:3542] Executor '2' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000 terminated with signal Killed
> I1019 04:57:26.824193 29470 slave.cpp:3646] Cleaning up executor '2' of framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.824849 29465 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/2805d07d-71a7-48bb-be21-7e29d6db6e84' for gc 6.9999904570163days in the future
> I1019 04:57:26.824972 29465 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2' for gc 6.99999045238518days in the future
> I1019 04:57:26.825067 29465 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2/runs/2805d07d-71a7-48bb-be21-7e29d6db6e84' for gc 6.99999045114667days in the future
> I1019 04:57:26.825165 29470 slave.cpp:3735] Cleaning up framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.825168 29465 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000/executors/2' for gc 6.9999904501037days in the future
> I1019 04:57:26.825330 29471 status_update_manager.cpp:284] Closing status update streams for framework 2f8cca9b-a727-4199-bec3-1529d3456817-0000
> I1019 04:57:26.825388 29465 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000' for gc 6.99999044772148days in the future
> I1019 04:57:26.825474 29470 slave.cpp:606] Slave terminating
> I1019 04:57:26.825489 29465 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_Xd4U3v/meta/slaves/2f8cca9b-a727-4199-bec3-1529d3456817-S0/frameworks/2f8cca9b-a727-4199-bec3-1529d3456817-0000' for gc 6.99999044666667days in the future
> ../../3rdparty/libprocess/include/process/gmock.hpp:365: Failure
> Actual function call count doesn't match EXPECT_CALL(filter->mock, filter(testing::A<const MessageEvent&>()))...
> Expected args: message matcher (8-byte object <C8-CB 03-10 F7-2A 00-00>, 1-byte object <CB>, 1-byte object <C8>)
> Expected: to be called once
> Actual: never called - unsatisfied and active
> [ FAILED ] FetcherCacheTest.FallbackFromEviction (17545 ms)
> {code}
> From a known good run:
> {code}
> [ RUN ] FetcherCacheTest.FallbackFromEviction
> Using temporary directory '/tmp/FetcherCacheTest_FallbackFromEviction_6oznNz'
> I1016 17:57:01.213835 29276 leveldb.cpp:176] Opened db in 112.366346ms
> I1016 17:57:01.247596 29276 leveldb.cpp:183] Compacted db in 33.684787ms
> I1016 17:57:01.247676 29276 leveldb.cpp:198] Created db iterator in 22737ns
> I1016 17:57:01.247689 29276 leveldb.cpp:204] Seeked to beginning of db in 2855ns
> I1016 17:57:01.247697 29276 leveldb.cpp:273] Iterated through 0 keys in the db in 279ns
> I1016 17:57:01.247741 29276 replica.cpp:746] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I1016 17:57:01.248479 29298 recover.cpp:449] Starting replica recovery
> I1016 17:57:01.248714 29298 recover.cpp:475] Replica is in EMPTY status
> I1016 17:57:01.249816 29295 replica.cpp:642] Replica in EMPTY status received a broadcasted recover request from (1574)@172.17.8.10:43676
> I1016 17:57:01.250239 29308 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I1016 17:57:01.250677 29296 recover.cpp:566] Updating replica status to STARTING
> I1016 17:57:01.252535 29299 master.cpp:376] Master 3a885ce0-812c-47ba-92d3-39d407ceba84 (342169b6513e) started on 172.17.8.10:43676
> I1016 17:57:01.252560 29299 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/FetcherCacheTest_FallbackFromEviction_6oznNz/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" --work_dir="/tmp/FetcherCacheTest_FallbackFromEviction_6oznNz/master" --zk_session_timeout="10secs"
> I1016 17:57:01.252809 29299 master.cpp:423] Master only allowing authenticated frameworks to register
> I1016 17:57:01.252817 29299 master.cpp:428] Master only allowing authenticated slaves to register
> I1016 17:57:01.252823 29299 credentials.hpp:37] Loading credentials for authentication from '/tmp/FetcherCacheTest_FallbackFromEviction_6oznNz/credentials'
> I1016 17:57:01.253057 29299 master.cpp:467] Using default 'crammd5' authenticator
> I1016 17:57:01.253173 29299 master.cpp:504] Authorization enabled
> I1016 17:57:01.253401 29298 hierarchical.cpp:140] Initialized hierarchical allocator process
> I1016 17:57:01.253463 29298 whitelist_watcher.cpp:79] No whitelist given
> I1016 17:57:01.255034 29299 master.cpp:1609] The newly elected leader is master@172.17.8.10:43676 with id 3a885ce0-812c-47ba-92d3-39d407ceba84
> I1016 17:57:01.255141 29299 master.cpp:1622] Elected as the leading master!
> I1016 17:57:01.255266 29299 master.cpp:1382] Recovering from registrar
> I1016 17:57:01.255596 29299 registrar.cpp:309] Recovering registrar
> I1016 17:57:01.281302 29300 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 30.459618ms
> I1016 17:57:01.281361 29300 replica.cpp:323] Persisted replica status to STARTING
> I1016 17:57:01.281741 29309 recover.cpp:475] Replica is in STARTING status
> I1016 17:57:01.282929 29307 replica.cpp:642] Replica in STARTING status received a broadcasted recover request from (1575)@172.17.8.10:43676
> I1016 17:57:01.283435 29309 recover.cpp:195] Received a recover response from a replica in STARTING status
> I1016 17:57:01.283996 29304 recover.cpp:566] Updating replica status to VOTING
> I1016 17:57:01.318516 29309 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 34.242489ms
> I1016 17:57:01.318580 29309 replica.cpp:323] Persisted replica status to VOTING
> I1016 17:57:01.318824 29309 recover.cpp:580] Successfully joined the Paxos group
> I1016 17:57:01.319133 29309 recover.cpp:464] Recover process terminated
> I1016 17:57:01.319748 29309 log.cpp:661] Attempting to start the writer
> I1016 17:57:01.321024 29308 replica.cpp:478] Replica received implicit promise request from (1576)@172.17.8.10:43676 with proposal 1
> I1016 17:57:01.356518 29308 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 35.36074ms
> I1016 17:57:01.356585 29308 replica.cpp:345] Persisted promised to 1
> I1016 17:57:01.357509 29297 coordinator.cpp:231] Coordinator attemping to fill missing position
> I1016 17:57:01.358799 29300 replica.cpp:378] Replica received explicit promise request from (1577)@172.17.8.10:43676 for position 0 with proposal 2
> I1016 17:57:01.390066 29300 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 31.120724ms
> I1016 17:57:01.390141 29300 replica.cpp:681] Persisted action at 0
> I1016 17:57:01.391612 29306 replica.cpp:512] Replica received write request for position 0 from (1578)@172.17.8.10:43676
> I1016 17:57:01.391722 29306 leveldb.cpp:438] Reading position from leveldb took 49139ns
> I1016 17:57:01.423485 29306 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 31.561909ms
> I1016 17:57:01.423554 29306 replica.cpp:681] Persisted action at 0
> I1016 17:57:01.424459 29295 replica.cpp:660] Replica received learned notice for position 0 from @0.0.0.0:0
> I1016 17:57:01.452146 29295 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 27.4992ms
> I1016 17:57:01.452211 29295 replica.cpp:681] Persisted action at 0
> I1016 17:57:01.452245 29295 replica.cpp:666] Replica learned NOP action at position 0
> I1016 17:57:01.453264 29295 log.cpp:677] Writer started with ending position 0
> I1016 17:57:01.454457 29307 leveldb.cpp:438] Reading position from leveldb took 45468ns
> I1016 17:57:01.455494 29297 registrar.cpp:342] Successfully fetched the registry (0B) in 199.79008ms
> I1016 17:57:01.455626 29297 registrar.cpp:441] Applied 1 operations in 38407ns; attempting to update the 'registry'
> I1016 17:57:01.456485 29297 log.cpp:685] Attempting to append 173 bytes to the log
> I1016 17:57:01.456702 29304 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
> I1016 17:57:01.457643 29295 replica.cpp:512] Replica received write request for position 1 from (1579)@172.17.8.10:43676
> I1016 17:57:01.485620 29295 leveldb.cpp:343] Persisting action (192 bytes) to leveldb took 27.922642ms
> I1016 17:57:01.485687 29295 replica.cpp:681] Persisted action at 1
> I1016 17:57:01.486821 29300 replica.cpp:660] Replica received learned notice for position 1 from @0.0.0.0:0
> I1016 17:57:01.510773 29300 leveldb.cpp:343] Persisting action (194 bytes) to leveldb took 23.91035ms
> I1016 17:57:01.510831 29300 replica.cpp:681] Persisted action at 1
> I1016 17:57:01.510864 29300 replica.cpp:666] Replica learned APPEND action at position 1
> I1016 17:57:01.512274 29297 registrar.cpp:486] Successfully updated the 'registry' in 56.574976ms
> I1016 17:57:01.512473 29297 registrar.cpp:372] Successfully recovered registrar
> I1016 17:57:01.512955 29295 master.cpp:1419] Recovered 0 slaves from the Registry (134B) ; allowing 10mins for slaves to re-register
> I1016 17:57:01.513331 29295 log.cpp:704] Attempting to truncate the log to 1
> I1016 17:57:01.513661 29300 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
> I1016 17:57:01.514889 29296 replica.cpp:512] Replica received write request for position 2 from (1580)@172.17.8.10:43676
> I1016 17:57:01.541324 29296 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 26.355788ms
> I1016 17:57:01.541398 29296 replica.cpp:681] Persisted action at 2
> I1016 17:57:01.542723 29296 replica.cpp:660] Replica received learned notice for position 2 from @0.0.0.0:0
> I1016 17:57:01.566422 29296 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 23.655552ms
> I1016 17:57:01.566550 29296 leveldb.cpp:401] Deleting ~1 keys from leveldb took 64211ns
> I1016 17:57:01.566679 29296 replica.cpp:681] Persisted action at 2
> I1016 17:57:01.566812 29296 replica.cpp:666] Replica learned TRUNCATE action at position 2
> I1016 17:57:01.575363 29276 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W1016 17:57:01.575906 29276 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
> I1016 17:57:01.580909 29306 slave.cpp:191] Slave started on 50)@172.17.8.10:43676
> I1016 17:57:01.581384 29306 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --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_FallbackFromEviction_HSOl47/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/fetch" --fetcher_cache_size="40B" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.26.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_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47"
> I1016 17:57:01.581734 29306 credentials.hpp:85] Loading credential for authentication from '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/credential'
> I1016 17:57:01.581954 29306 slave.cpp:322] Slave using credential for: test-principal
> I1016 17:57:01.582610 29306 slave.cpp:392] Slave resources: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I1016 17:57:01.582670 29306 slave.cpp:400] Slave attributes: [ ]
> I1016 17:57:01.582687 29306 slave.cpp:405] Slave hostname: 342169b6513e
> I1016 17:57:01.582700 29306 slave.cpp:410] Slave checkpoint: true
> I1016 17:57:01.583614 29298 state.cpp:54] Recovering state from '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta'
> I1016 17:57:01.584198 29303 status_update_manager.cpp:202] Recovering status update manager
> I1016 17:57:01.584591 29298 containerizer.cpp:385] Recovering containerizer
> I1016 17:57:01.585608 29308 slave.cpp:4222] Finished recovery
> I1016 17:57:01.586120 29308 slave.cpp:4379] Querying resource estimator for oversubscribable resources
> I1016 17:57:01.586423 29303 status_update_manager.cpp:176] Pausing sending status updates
> I1016 17:57:01.586438 29308 slave.cpp:726] New master detected at master@172.17.8.10:43676
> I1016 17:57:01.586601 29308 slave.cpp:789] Authenticating with master master@172.17.8.10:43676
> I1016 17:57:01.586720 29308 slave.cpp:794] Using default CRAM-MD5 authenticatee
> I1016 17:57:01.587007 29308 slave.cpp:762] Detecting new master
> I1016 17:57:01.587209 29308 slave.cpp:4393] Received oversubscribable resources from the resource estimator
> I1016 17:57:01.587520 29301 authenticatee.cpp:115] Creating new client SASL connection
> I1016 17:57:01.587851 29308 master.cpp:5144] Authenticating slave(50)@172.17.8.10:43676
> I1016 17:57:01.588045 29301 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(145)@172.17.8.10:43676
> I1016 17:57:01.588340 29308 authenticator.cpp:92] Creating new server SASL connection
> I1016 17:57:01.588768 29308 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
> I1016 17:57:01.588801 29308 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1016 17:57:01.588925 29308 authenticator.cpp:197] Received SASL authentication start
> I1016 17:57:01.589120 29308 authenticator.cpp:319] Authentication requires more steps
> I1016 17:57:01.589370 29296 authenticatee.cpp:252] Received SASL authentication step
> I1016 17:57:01.589560 29305 authenticator.cpp:225] Received SASL authentication step
> I1016 17:57:01.589597 29305 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '342169b6513e' server FQDN: '342169b6513e' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1016 17:57:01.589615 29305 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
> I1016 17:57:01.589679 29305 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1016 17:57:01.589874 29305 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '342169b6513e' server FQDN: '342169b6513e' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1016 17:57:01.590000 29305 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1016 17:57:01.590148 29305 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1016 17:57:01.590283 29305 authenticator.cpp:311] Authentication success
> I1016 17:57:01.590529 29306 authenticatee.cpp:292] Authentication success
> I1016 17:57:01.590575 29299 master.cpp:5174] Successfully authenticated principal 'test-principal' at slave(50)@172.17.8.10:43676
> I1016 17:57:01.590831 29306 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(145)@172.17.8.10:43676
> I1016 17:57:01.591042 29298 slave.cpp:857] Successfully authenticated with master master@172.17.8.10:43676
> I1016 17:57:01.591215 29298 slave.cpp:1251] Will retry registration in 17.464328ms if necessary
> I1016 17:57:01.591423 29297 master.cpp:3868] Registering slave at slave(50)@172.17.8.10:43676 (342169b6513e) with id 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:01.591894 29308 registrar.cpp:441] Applied 1 operations in 72279ns; attempting to update the 'registry'
> I1016 17:57:01.592896 29302 log.cpp:685] Attempting to append 342 bytes to the log
> I1016 17:57:01.593189 29297 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
> I1016 17:57:01.594249 29310 replica.cpp:512] Replica received write request for position 3 from (1593)@172.17.8.10:43676
> I1016 17:57:01.609988 29304 slave.cpp:1251] Will retry registration in 13.052209ms if necessary
> I1016 17:57:01.610172 29300 master.cpp:3856] Ignoring register slave message from slave(50)@172.17.8.10:43676 (342169b6513e) as admission is already in progress
> I1016 17:57:01.619891 29310 leveldb.cpp:343] Persisting action (361 bytes) to leveldb took 25.582585ms
> I1016 17:57:01.619952 29310 replica.cpp:681] Persisted action at 3
> I1016 17:57:01.621100 29298 replica.cpp:660] Replica received learned notice for position 3 from @0.0.0.0:0
> I1016 17:57:01.624150 29306 master.cpp:3856] Ignoring register slave message from slave(50)@172.17.8.10:43676 (342169b6513e) as admission is already in progress
> I1016 17:57:01.623952 29310 slave.cpp:1251] Will retry registration in 63.227499ms if necessary
> I1016 17:57:01.642056 29298 leveldb.cpp:343] Persisting action (363 bytes) to leveldb took 20.819406ms
> I1016 17:57:01.642140 29298 replica.cpp:681] Persisted action at 3
> I1016 17:57:01.642180 29298 replica.cpp:666] Replica learned APPEND action at position 3
> I1016 17:57:01.644009 29302 registrar.cpp:486] Successfully updated the 'registry' in 52.015104ms
> I1016 17:57:01.644443 29298 log.cpp:704] Attempting to truncate the log to 3
> I1016 17:57:01.644709 29298 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
> I1016 17:57:01.645445 29298 slave.cpp:3212] Received ping from slave-observer(47)@172.17.8.10:43676
> I1016 17:57:01.645437 29296 master.cpp:3936] Registered slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I1016 17:57:01.645725 29298 slave.cpp:901] Registered with master master@172.17.8.10:43676; given slave ID 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:01.645764 29298 fetcher.cpp:79] Clearing fetcher cache
> I1016 17:57:01.645936 29307 status_update_manager.cpp:183] Resuming sending status updates
> I1016 17:57:01.646245 29298 slave.cpp:924] Checkpointing SlaveInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/slave.info'
> I1016 17:57:01.646510 29302 replica.cpp:512] Replica received write request for position 4 from (1594)@172.17.8.10:43676
> I1016 17:57:01.646719 29298 slave.cpp:960] Forwarding total oversubscribed resources
> I1016 17:57:01.647002 29309 master.cpp:4278] Received update of slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e) with total oversubscribed resources
> I1016 17:57:01.647157 29296 hierarchical.cpp:335] Added slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 (342169b6513e) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I1016 17:57:01.647406 29296 hierarchical.cpp:952] No resources available to allocate!
> I1016 17:57:01.647464 29296 hierarchical.cpp:1045] No inverse offers to send out!
> I1016 17:57:01.647493 29296 hierarchical.cpp:867] Performed allocation for slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 in 292633ns
> I1016 17:57:01.647745 29296 hierarchical.cpp:391] Slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 (342169b6513e) updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I1016 17:57:01.647802 29276 sched.cpp:166] Version: 0.26.0
> I1016 17:57:01.647914 29296 hierarchical.cpp:952] No resources available to allocate!
> I1016 17:57:01.647958 29296 hierarchical.cpp:1045] No inverse offers to send out!
> I1016 17:57:01.648227 29296 hierarchical.cpp:867] Performed allocation for slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 in 440371ns
> I1016 17:57:01.648685 29306 sched.cpp:264] New master detected at master@172.17.8.10:43676
> I1016 17:57:01.648787 29306 sched.cpp:320] Authenticating with master master@172.17.8.10:43676
> I1016 17:57:01.648814 29306 sched.cpp:327] Using default CRAM-MD5 authenticatee
> I1016 17:57:01.649117 29309 authenticatee.cpp:115] Creating new client SASL connection
> I1016 17:57:01.649430 29304 master.cpp:5144] Authenticating scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:01.649539 29298 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(146)@172.17.8.10:43676
> I1016 17:57:01.649777 29304 authenticator.cpp:92] Creating new server SASL connection
> I1016 17:57:01.650189 29295 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
> I1016 17:57:01.650224 29295 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
> I1016 17:57:01.650323 29295 authenticator.cpp:197] Received SASL authentication start
> I1016 17:57:01.650384 29295 authenticator.cpp:319] Authentication requires more steps
> I1016 17:57:01.650598 29307 authenticatee.cpp:252] Received SASL authentication step
> I1016 17:57:01.650717 29295 authenticator.cpp:225] Received SASL authentication step
> I1016 17:57:01.650854 29295 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '342169b6513e' server FQDN: '342169b6513e' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I1016 17:57:01.650882 29295 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
> I1016 17:57:01.650951 29295 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I1016 17:57:01.651017 29295 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '342169b6513e' server FQDN: '342169b6513e' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I1016 17:57:01.651036 29295 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I1016 17:57:01.651064 29295 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I1016 17:57:01.651089 29295 authenticator.cpp:311] Authentication success
> I1016 17:57:01.651427 29301 master.cpp:5174] Successfully authenticated principal 'test-principal' at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:01.651288 29295 authenticatee.cpp:292] Authentication success
> I1016 17:57:01.651530 29308 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(146)@172.17.8.10:43676
> I1016 17:57:01.651937 29295 sched.cpp:409] Successfully authenticated with master master@172.17.8.10:43676
> I1016 17:57:01.652063 29295 sched.cpp:716] Sending SUBSCRIBE call to master@172.17.8.10:43676
> I1016 17:57:01.652176 29295 sched.cpp:749] Will retry registration in 89.397593ms if necessary
> I1016 17:57:01.652354 29310 master.cpp:2185] Received SUBSCRIBE call for framework 'default' at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> W1016 17:57:01.652461 29310 master.cpp:2192] Framework at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> I1016 17:57:01.652541 29310 master.cpp:1648] Authorizing framework principal '' to receive offers for role '*'
> I1016 17:57:01.652818 29310 master.cpp:2256] Subscribing framework default with checkpointing enabled and capabilities [ ]
> I1016 17:57:01.653234 29304 hierarchical.cpp:185] Added framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.653353 29310 sched.cpp:643] Framework registered with 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.653486 29310 sched.cpp:657] Scheduler::registered took 20801ns
> I1016 17:57:01.654063 29304 hierarchical.cpp:1045] No inverse offers to send out!
> I1016 17:57:01.654109 29304 hierarchical.cpp:851] Performed allocation for 1 slaves in 777530ns
> I1016 17:57:01.654424 29301 master.cpp:4973] Sending 1 offers to framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:01.654846 29301 sched.cpp:813] Scheduler::resourceOffers took 108926ns
> I1016 17:57:01.656322 29301 master.cpp:2924] Processing ACCEPT call for offers: [ 3a885ce0-812c-47ba-92d3-39d407ceba84-O0 ] on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e) for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:01.656363 29301 master.cpp:2720] Authorizing framework principal '' to launch task 0 as user 'mesos'
> I1016 17:57:01.657510 29301 master.hpp:176] Adding task 0 with resources cpus(*):1; mem(*):1 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 (342169b6513e)
> I1016 17:57:01.657629 29301 master.cpp:3254] Launching task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 with resources cpus(*):1; mem(*):1 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:01.658023 29307 slave.cpp:1291] Got assigned task 0 for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.658304 29307 slave.cpp:4915] Checkpointing FrameworkInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/framework.info'
> I1016 17:57:01.658334 29296 hierarchical.cpp:739] 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 slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 from framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.658411 29296 hierarchical.cpp:776] Framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 filtered slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 for 5secs
> I1016 17:57:01.659348 29307 slave.cpp:4926] Checkpointing framework pid 'scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676' to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/framework.pid'
> I1016 17:57:01.660055 29307 slave.cpp:1407] Launching task 0 for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.663924 29307 slave.cpp:5351] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0/executor.info'
> I1016 17:57:01.664638 29307 slave.cpp:4994] Launching executor 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0/runs/fef47f49-e3b7-45ed-9386-cc1bff68ea78'
> I1016 17:57:01.665150 29298 containerizer.cpp:639] Starting container 'fef47f49-e3b7-45ed-9386-cc1bff68ea78' for executor '0' of framework '3a885ce0-812c-47ba-92d3-39d407ceba84-0000'
> I1016 17:57:01.665191 29307 slave.cpp:5374] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0/runs/fef47f49-e3b7-45ed-9386-cc1bff68ea78/tasks/0/task.info'
> I1016 17:57:01.665611 29307 slave.cpp:1625] Queuing task '0' for executor 0 of framework '3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.665715 29307 slave.cpp:679] Successfully attached file '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0/runs/fef47f49-e3b7-45ed-9386-cc1bff68ea78'
> I1016 17:57:01.667506 29302 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 20.933572ms
> I1016 17:57:01.667929 29302 replica.cpp:681] Persisted action at 4
> I1016 17:57:01.669432 29298 launcher.cpp:132] Forked child with pid '317' for container 'fef47f49-e3b7-45ed-9386-cc1bff68ea78'
> I1016 17:57:01.669766 29298 containerizer.cpp:872] Checkpointing executor's forked pid 317 to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0/runs/fef47f49-e3b7-45ed-9386-cc1bff68ea78/pids/forked.pid'
> I1016 17:57:01.673074 29302 replica.cpp:660] Replica received learned notice for position 4 from @0.0.0.0:0
> I1016 17:57:01.674523 29305 fetcher.cpp:301] Starting to fetch URIs for container: fef47f49-e3b7-45ed-9386-cc1bff68ea78, directory: /tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0/runs/fef47f49-e3b7-45ed-9386-cc1bff68ea78
> I1016 17:57:01.679756 29305 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd0' with file: c1-cmd0
> I1016 17:57:01.680625 29308 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd0
> I1016 17:57:01.682660 29305 fetcher.cpp:665] Claiming fetcher cache space for: mesos@/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd0
> I1016 17:57:01.682687 29305 fetcher.cpp:1110] Claimed cache space: 30B, now using: 30B
> I1016 17:57:01.699846 29298 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
> I1016 17:57:01.703333 29302 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 30.199115ms
> I1016 17:57:01.704193 29302 leveldb.cpp:401] Deleting ~2 keys from leveldb took 161966ns
> I1016 17:57:01.704607 29302 replica.cpp:681] Persisted action at 4
> I1016 17:57:01.705061 29302 replica.cpp:666] Replica learned TRUNCATE action at position 4
> I1016 17:57:01.879390 29295 fetcher.cpp:1122] Released cache space: 0B, now using: 30B
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1016 17:57:01.940439 356 process.cpp:968] libprocess is initialized on 172.17.8.10:55846 for 16 cpus
> I1016 17:57:01.941334 356 logging.cpp:177] Logging to STDERR
> I1016 17:57:01.943312 356 exec.cpp:136] Version: 0.26.0
> I1016 17:57:01.955253 379 exec.cpp:186] Executor started at: executor(1)@172.17.8.10:55846 with pid 356
> I1016 17:57:01.957324 29300 slave.cpp:2415] Got registration for executor '0' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from executor(1)@172.17.8.10:55846
> I1016 17:57:01.957448 29300 slave.cpp:2501] Checkpointing executor pid 'executor(1)@172.17.8.10:55846' to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0/runs/fef47f49-e3b7-45ed-9386-cc1bff68ea78/pids/libprocess.pid'
> I1016 17:57:01.959606 370 exec.cpp:210] Executor registered on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:01.959820 29298 slave.cpp:1796] Sending queued task '0' to executor '0' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.961714 370 exec.cpp:222] Executor::registered took 241916ns
> Registered executor on 342169b6513e
> I1016 17:57:01.962112 370 exec.cpp:297] Executor asked to run task '0'
> Starting task 0
> I1016 17:57:01.962231 370 exec.cpp:306] Executor::launchTask took 90839ns
> Forked command at 387
> sh -c './cmd0 0'
> I1016 17:57:01.965421 378 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.966485 29303 slave.cpp:2778] Handling status update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from executor(1)@172.17.8.10:55846
> I1016 17:57:01.967038 29303 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.967090 29303 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:01.967692 29303 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.017083 29303 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to the slave
> I1016 17:57:02.017459 29309 slave.cpp:3090] Forwarding the update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to master@172.17.8.10:43676
> I1016 17:57:02.017664 29309 slave.cpp:3014] Status update manager successfully handled status update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.017701 29309 slave.cpp:3020] Sending acknowledgement for status update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to executor(1)@172.17.8.10:55846
> I1016 17:57:02.017823 29296 master.cpp:4421] Status update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:02.018028 29296 master.cpp:4460] Forwarding status update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.018209 29296 master.cpp:6086] Updating the latest state of task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to TASK_RUNNING
> I1016 17:57:02.018524 29295 sched.cpp:920] Scheduler::statusUpdate took 150850ns
> I1016 17:57:02.018944 29309 master.cpp:3612] Processing ACKNOWLEDGE call 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:02.019199 29309 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.019418 29309 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.019906 373 exec.cpp:343] Executor received status update acknowledgement 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> Command exited with status 0 (pid: 387)
> I1016 17:57:02.066104 383 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.067129 29295 slave.cpp:2778] Handling status update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from executor(1)@172.17.8.10:55846
> I1016 17:57:02.067276 29295 slave.cpp:5289] Terminating task 0
> I1016 17:57:02.079252 29307 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: 7408e7ec-762f-42fa-b6ce-cedd4eb00cdf) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.079258 29309 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.079325 29309 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.146287 29309 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to the slave
> I1016 17:57:02.146641 29300 slave.cpp:3090] Forwarding the update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to master@172.17.8.10:43676
> I1016 17:57:02.147054 29300 slave.cpp:3014] Status update manager successfully handled status update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.147095 29300 slave.cpp:3020] Sending acknowledgement for status update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to executor(1)@172.17.8.10:55846
> I1016 17:57:02.147222 29308 master.cpp:4421] Status update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:02.147267 29308 master.cpp:4460] Forwarding status update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.147452 29308 master.cpp:6086] Updating the latest state of task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to TASK_FINISHED
> I1016 17:57:02.147733 29304 sched.cpp:920] Scheduler::statusUpdate took 171563ns
> I1016 17:57:02.147944 29300 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 from framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.148154 29304 master.cpp:6154] Removing task 0 with resources cpus(*):1; mem(*):1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:02.148329 29304 master.cpp:3612] Processing ACKNOWLEDGE call d3b5995c-bc2e-43c8-8762-9b1c9c7caa66 for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:02.148802 29304 status_update_manager.cpp:394] Received status update acknowledgement (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.148944 29304 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FINISHED (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.150213 381 exec.cpp:343] Executor received status update acknowledgement d3b5995c-bc2e-43c8-8762-9b1c9c7caa66 for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.213217 29304 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.213685 29304 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: d3b5995c-bc2e-43c8-8762-9b1c9c7caa66) for task 0 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.213750 29304 slave.cpp:5330] Completing task 0
> I1016 17:57:02.255121 29309 hierarchical.cpp:1045] No inverse offers to send out!
> I1016 17:57:02.255291 29309 hierarchical.cpp:851] Performed allocation for 1 slaves in 850529ns
> I1016 17:57:02.255585 29305 master.cpp:4973] Sending 1 offers to framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:02.256063 29310 sched.cpp:813] Scheduler::resourceOffers took 129427ns
> I1016 17:57:02.257411 29300 master.cpp:2924] Processing ACCEPT call for offers: [ 3a885ce0-812c-47ba-92d3-39d407ceba84-O1 ] on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e) for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:02.257455 29300 master.cpp:2720] Authorizing framework principal '' to launch task 1 as user 'mesos'
> I1016 17:57:02.258564 29300 master.hpp:176] Adding task 1 with resources cpus(*):1; mem(*):1 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 (342169b6513e)
> I1016 17:57:02.258667 29300 master.cpp:3254] Launching task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 with resources cpus(*):1; mem(*):1 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:02.258955 29307 slave.cpp:1291] Got assigned task 1 for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.259320 29300 hierarchical.cpp:739] 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 slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 from framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.259387 29300 hierarchical.cpp:776] Framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 filtered slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 for 5secs
> I1016 17:57:02.259680 29307 slave.cpp:1407] Launching task 1 for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.263445 29307 slave.cpp:5351] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1/executor.info'
> I1016 17:57:02.264060 29307 slave.cpp:4994] Launching executor 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1/runs/161b2ef5-f6df-48f4-9ebc-509bc22bc482'
> I1016 17:57:02.264536 29310 containerizer.cpp:639] Starting container '161b2ef5-f6df-48f4-9ebc-509bc22bc482' for executor '1' of framework '3a885ce0-812c-47ba-92d3-39d407ceba84-0000'
> I1016 17:57:02.264585 29307 slave.cpp:5374] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1/runs/161b2ef5-f6df-48f4-9ebc-509bc22bc482/tasks/1/task.info'
> I1016 17:57:02.264992 29307 slave.cpp:1625] Queuing task '1' for executor 1 of framework '3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.265137 29307 slave.cpp:679] Successfully attached file '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1/runs/161b2ef5-f6df-48f4-9ebc-509bc22bc482'
> I1016 17:57:02.267910 29298 launcher.cpp:132] Forked child with pid '392' for container '161b2ef5-f6df-48f4-9ebc-509bc22bc482'
> I1016 17:57:02.268213 29298 containerizer.cpp:872] Checkpointing executor's forked pid 392 to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1/runs/161b2ef5-f6df-48f4-9ebc-509bc22bc482/pids/forked.pid'
> I1016 17:57:02.271137 29303 fetcher.cpp:301] Starting to fetch URIs for container: 161b2ef5-f6df-48f4-9ebc-509bc22bc482, directory: /tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1/runs/161b2ef5-f6df-48f4-9ebc-509bc22bc482
> I1016 17:57:02.276023 29303 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd1' with file: c2-cmd1
> I1016 17:57:02.277250 29306 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd1
> I1016 17:57:02.279199 29303 fetcher.cpp:1031] Freeing up fetcher cache space for: 30B
> I1016 17:57:02.279259 29303 fetcher.cpp:967] Removing cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd0' with filename: c1-cmd0
> I1016 17:57:02.279405 29303 fetcher.cpp:1122] Released cache space: 30B, now using: 0B
> I1016 17:57:02.279552 29303 fetcher.cpp:665] Claiming fetcher cache space for: mesos@/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd1
> I1016 17:57:02.279646 29303 fetcher.cpp:1110] Claimed cache space: 40B, now using: 40B
> I1016 17:57:02.284525 29309 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
> I1016 17:57:02.383571 29295 fetcher.cpp:1122] Released cache space: 0B, now using: 40B
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1016 17:57:02.445087 431 process.cpp:968] libprocess is initialized on 172.17.8.10:44379 for 16 cpus
> I1016 17:57:02.445777 431 logging.cpp:177] Logging to STDERR
> I1016 17:57:02.448187 431 exec.cpp:136] Version: 0.26.0
> I1016 17:57:02.458098 457 exec.cpp:186] Executor started at: executor(1)@172.17.8.10:44379 with pid 431
> I1016 17:57:02.461271 29302 slave.cpp:2415] Got registration for executor '1' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from executor(1)@172.17.8.10:44379
> I1016 17:57:02.461403 29302 slave.cpp:2501] Checkpointing executor pid 'executor(1)@172.17.8.10:44379' to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1/runs/161b2ef5-f6df-48f4-9ebc-509bc22bc482/pids/libprocess.pid'
> I1016 17:57:02.464042 29303 slave.cpp:1796] Sending queued task '1' to executor '1' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.464826 448 exec.cpp:210] Executor registered on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:02.468703 448 exec.cpp:222] Executor::registered took 310875ns
> Registered executor on 342169b6513e
> I1016 17:57:02.469123 448 exec.cpp:297] Executor asked to run task '1'
> I1016 17:57:02.469352 448 exec.cpp:306] Executor::launchTask took 110032ns
> Starting task 1
> Forked command at 462
> sh -c './cmd1 1'
> I1016 17:57:02.472894 446 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.474066 29307 slave.cpp:2778] Handling status update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from executor(1)@172.17.8.10:44379
> I1016 17:57:02.474390 29297 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.474436 29297 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.474861 29297 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.527706 29297 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to the slave
> I1016 17:57:02.528281 29302 slave.cpp:3090] Forwarding the update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to master@172.17.8.10:43676
> I1016 17:57:02.528481 29302 slave.cpp:3014] Status update manager successfully handled status update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.528517 29302 slave.cpp:3020] Sending acknowledgement for status update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to executor(1)@172.17.8.10:44379
> I1016 17:57:02.529165 29302 master.cpp:4421] Status update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:02.529206 29302 master.cpp:4460] Forwarding status update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.529394 29302 master.cpp:6086] Updating the latest state of task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to TASK_RUNNING
> I1016 17:57:02.529759 29300 sched.cpp:920] Scheduler::statusUpdate took 133642ns
> I1016 17:57:02.530154 458 exec.cpp:343] Executor received status update acknowledgement 32e46b56-7d79-43c4-bf56-7b1bab4a94ba for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.530237 29309 master.cpp:3612] Processing ACKNOWLEDGE call 32e46b56-7d79-43c4-bf56-7b1bab4a94ba for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:02.530652 29300 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.530829 29300 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> Command exited with status 0 (pid: 462)
> I1016 17:57:02.574820 451 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.575861 29309 slave.cpp:2778] Handling status update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from executor(1)@172.17.8.10:44379
> I1016 17:57:02.576027 29309 slave.cpp:5289] Terminating task 1
> I1016 17:57:02.592468 29305 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: 32e46b56-7d79-43c4-bf56-7b1bab4a94ba) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.592461 29300 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.592762 29300 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.659344 29300 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to the slave
> I1016 17:57:02.659807 29310 slave.cpp:3090] Forwarding the update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to master@172.17.8.10:43676
> I1016 17:57:02.660085 29310 slave.cpp:3014] Status update manager successfully handled status update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.660183 29310 slave.cpp:3020] Sending acknowledgement for status update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to executor(1)@172.17.8.10:44379
> I1016 17:57:02.660246 29300 master.cpp:4421] Status update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:02.660389 29300 master.cpp:4460] Forwarding status update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.660997 29308 sched.cpp:920] Scheduler::statusUpdate took 193818ns
> I1016 17:57:02.661329 29300 master.cpp:6086] Updating the latest state of task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to TASK_FINISHED
> I1016 17:57:02.661825 29299 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 from framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.661870 29300 master.cpp:6154] Removing task 1 with resources cpus(*):1; mem(*):1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:02.662722 29300 master.cpp:3612] Processing ACKNOWLEDGE call 319d8457-5e06-4575-bc46-9bef7fd167aa for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:02.662943 457 exec.cpp:343] Executor received status update acknowledgement 319d8457-5e06-4575-bc46-9bef7fd167aa for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.663112 29300 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.663277 29300 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FINISHED (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.730152 29300 status_update_manager.cpp:530] Cleaning up status update stream for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.730635 29310 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: 319d8457-5e06-4575-bc46-9bef7fd167aa) for task 1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:02.730778 29310 slave.cpp:5330] Completing task 1
> I1016 17:57:03.089545 29297 containerizer.cpp:1278] Executor for container 'fef47f49-e3b7-45ed-9386-cc1bff68ea78' has exited
> I1016 17:57:03.089885 29297 containerizer.cpp:1095] Destroying container 'fef47f49-e3b7-45ed-9386-cc1bff68ea78'
> I1016 17:57:03.093544 29309 slave.cpp:3542] Executor '0' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 exited with status 0
> I1016 17:57:03.093636 29309 slave.cpp:3646] Cleaning up executor '0' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.094135 29303 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0/runs/fef47f49-e3b7-45ed-9386-cc1bff68ea78' for gc 6.99999891140148days in the future
> I1016 17:57:03.094295 29303 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0' for gc 6.99999890947852days in the future
> I1016 17:57:03.094451 29303 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0/runs/fef47f49-e3b7-45ed-9386-cc1bff68ea78' for gc 6.9999989082163days in the future
> I1016 17:57:03.094622 29303 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/0' for gc 6.99999890708148days in the future
> I1016 17:57:03.257326 29310 hierarchical.cpp:1045] No inverse offers to send out!
> I1016 17:57:03.257395 29310 hierarchical.cpp:851] Performed allocation for 1 slaves in 755237ns
> I1016 17:57:03.257817 29309 master.cpp:4973] Sending 1 offers to framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:03.258375 29310 sched.cpp:813] Scheduler::resourceOffers took 104511ns
> I1016 17:57:03.260324 29298 master.cpp:2924] Processing ACCEPT call for offers: [ 3a885ce0-812c-47ba-92d3-39d407ceba84-O2 ] on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e) for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:03.260380 29298 master.cpp:2720] Authorizing framework principal '' to launch task 2 as user 'mesos'
> I1016 17:57:03.261878 29297 master.hpp:176] Adding task 2 with resources cpus(*):1; mem(*):1 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 (342169b6513e)
> I1016 17:57:03.262050 29297 master.cpp:3254] Launching task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 with resources cpus(*):1; mem(*):1 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:03.262485 29303 slave.cpp:1291] Got assigned task 2 for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.262892 29299 hierarchical.cpp:739] 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 slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 from framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.263006 29299 hierarchical.cpp:776] Framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 filtered slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 for 5secs
> I1016 17:57:03.263242 29303 slave.cpp:1407] Launching task 2 for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.267714 29303 slave.cpp:5351] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2/executor.info'
> I1016 17:57:03.268465 29303 slave.cpp:4994] Launching executor 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2/runs/3a9e2eac-c090-41de-aaf2-3efc6bc91af9'
> I1016 17:57:03.269114 29295 containerizer.cpp:639] Starting container '3a9e2eac-c090-41de-aaf2-3efc6bc91af9' for executor '2' of framework '3a885ce0-812c-47ba-92d3-39d407ceba84-0000'
> I1016 17:57:03.269314 29303 slave.cpp:5374] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2/runs/3a9e2eac-c090-41de-aaf2-3efc6bc91af9/tasks/2/task.info'
> I1016 17:57:03.269901 29303 slave.cpp:1625] Queuing task '2' for executor 2 of framework '3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.270030 29303 slave.cpp:679] Successfully attached file '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2/runs/3a9e2eac-c090-41de-aaf2-3efc6bc91af9'
> I1016 17:57:03.273615 29295 launcher.cpp:132] Forked child with pid '467' for container '3a9e2eac-c090-41de-aaf2-3efc6bc91af9'
> I1016 17:57:03.273890 29295 containerizer.cpp:872] Checkpointing executor's forked pid 467 to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2/runs/3a9e2eac-c090-41de-aaf2-3efc6bc91af9/pids/forked.pid'
> I1016 17:57:03.276687 29309 fetcher.cpp:301] Starting to fetch URIs for container: 3a9e2eac-c090-41de-aaf2-3efc6bc91af9, directory: /tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2/runs/3a9e2eac-c090-41de-aaf2-3efc6bc91af9
> I1016 17:57:03.280675 29309 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd2' with file: c3-cmd2
> I1016 17:57:03.282135 29299 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd2
> I1016 17:57:03.284399 29309 fetcher.cpp:1031] Freeing up fetcher cache space for: 50B
> I1016 17:57:03.284458 29309 fetcher.cpp:967] Removing cache entry 'mesos@/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd2' with filename: c3-cmd2
> W1016 17:57:03.285248 29301 fetcher.cpp:438] Reverting to fetching directly into the sandbox for '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/mesos-fetcher-test-assets/cmd2', due to failure to fetch through the cache, with error: Failed to reserve space in the cache: Could not free up enough fetcher cache space
> I1016 17:57:03.289115 29301 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I1016 17:57:03.454008 504 process.cpp:968] libprocess is initialized on 172.17.8.10:53643 for 16 cpus
> I1016 17:57:03.456082 504 logging.cpp:177] Logging to STDERR
> I1016 17:57:03.459703 504 exec.cpp:136] Version: 0.26.0
> I1016 17:57:03.464011 526 exec.cpp:186] Executor started at: executor(1)@172.17.8.10:53643 with pid 504
> I1016 17:57:03.466761 29300 slave.cpp:2415] Got registration for executor '2' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from executor(1)@172.17.8.10:53643
> I1016 17:57:03.466905 29300 slave.cpp:2501] Checkpointing executor pid 'executor(1)@172.17.8.10:53643' to '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2/runs/3a9e2eac-c090-41de-aaf2-3efc6bc91af9/pids/libprocess.pid'
> I1016 17:57:03.468960 29300 slave.cpp:1796] Sending queued task '2' to executor '2' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.470702 527 exec.cpp:210] Executor registered on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:03.472708 527 exec.cpp:222] Executor::registered took 299813ns
> Registered executor on 342169b6513e
> I1016 17:57:03.473112 527 exec.cpp:297] Executor asked to run task '2'
> I1016 17:57:03.473335 527 exec.cpp:306] Executor::launchTask took 122300ns
> Starting task 2
> sh -c './cmd2 2'
> Forked command at 535
> I1016 17:57:03.477352 523 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.478691 29295 slave.cpp:2778] Handling status update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from executor(1)@172.17.8.10:53643
> I1016 17:57:03.479089 29298 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.479130 29298 status_update_manager.cpp:499] Creating StatusUpdate stream for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.479606 29298 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.539845 29298 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to the slave
> I1016 17:57:03.540220 29302 slave.cpp:3090] Forwarding the update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to master@172.17.8.10:43676
> I1016 17:57:03.540496 29302 slave.cpp:3014] Status update manager successfully handled status update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.540534 29302 slave.cpp:3020] Sending acknowledgement for status update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to executor(1)@172.17.8.10:53643
> I1016 17:57:03.540668 29305 master.cpp:4421] Status update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:03.540802 29305 master.cpp:4460] Forwarding status update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.541091 29305 master.cpp:6086] Updating the latest state of task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to TASK_RUNNING
> I1016 17:57:03.541402 29302 sched.cpp:920] Scheduler::statusUpdate took 145472ns
> I1016 17:57:03.541643 29305 master.cpp:3612] Processing ACKNOWLEDGE call 7caf2aff-7f6c-4e03-9376-f853a8f91733 for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:03.541883 29305 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.542037 29305 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.542563 525 exec.cpp:343] Executor received status update acknowledgement 7caf2aff-7f6c-4e03-9376-f853a8f91733 for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> Command exited with status 0 (pid: 535)
> I1016 17:57:03.577234 529 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.578189 29302 slave.cpp:2778] Handling status update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from executor(1)@172.17.8.10:53643
> I1016 17:57:03.578336 29302 slave.cpp:5289] Terminating task 2
> I1016 17:57:03.590258 29310 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: 7caf2aff-7f6c-4e03-9376-f853a8f91733) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.590231 29305 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.590471 29305 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.594065 29309 containerizer.cpp:1278] Executor for container '161b2ef5-f6df-48f4-9ebc-509bc22bc482' has exited
> I1016 17:57:03.594941 29309 containerizer.cpp:1095] Destroying container '161b2ef5-f6df-48f4-9ebc-509bc22bc482'
> I1016 17:57:03.600411 29300 slave.cpp:3542] Executor '1' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 exited with status 0
> I1016 17:57:03.600504 29300 slave.cpp:3646] Cleaning up executor '1' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.606884 29303 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1/runs/161b2ef5-f6df-48f4-9ebc-509bc22bc482' for gc 6.9999929773837days in the future
> I1016 17:57:03.607036 29303 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1' for gc 6.99999297571556days in the future
> I1016 17:57:03.607187 29303 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1/runs/161b2ef5-f6df-48f4-9ebc-509bc22bc482' for gc 6.99999297432889days in the future
> I1016 17:57:03.607277 29303 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/1' for gc 6.99999297353185days in the future
> I1016 17:57:03.640436 29305 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to the slave
> I1016 17:57:03.640823 29298 slave.cpp:3090] Forwarding the update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to master@172.17.8.10:43676
> I1016 17:57:03.641196 29304 master.cpp:4421] Status update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 from slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:03.641232 29304 master.cpp:4460] Forwarding status update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.641376 29304 master.cpp:6086] Updating the latest state of task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to TASK_FINISHED
> I1016 17:57:03.641654 29297 sched.cpp:920] Scheduler::statusUpdate took 175376ns
> I1016 17:57:03.641887 29304 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 from framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.642096 29298 slave.cpp:3014] Status update manager successfully handled status update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.642200 29298 slave.cpp:3020] Sending acknowledgement for status update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 to executor(1)@172.17.8.10:53643
> I1016 17:57:03.642765 29276 sched.cpp:1781] Asked to stop the driver
> I1016 17:57:03.642078 29297 master.cpp:6154] Removing task 2 with resources cpus(*):1; mem(*):1 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0 at slave(50)@172.17.8.10:43676 (342169b6513e)
> I1016 17:57:03.643064 29297 master.cpp:3612] Processing ACKNOWLEDGE call 97e333f2-7a6f-4136-9830-c987dd8488e9 for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 on slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:03.643597 29297 master.cpp:1125] Framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 disconnected
> I1016 17:57:03.643697 29297 master.cpp:2481] Disconnecting framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:03.643872 29297 master.cpp:2505] Deactivating framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676
> I1016 17:57:03.644083 526 exec.cpp:343] Executor received status update acknowledgement 97e333f2-7a6f-4136-9830-c987dd8488e9 for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.644268 29295 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.644327 29297 master.cpp:1149] Giving framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 (default) at scheduler-852c6b04-ebf0-4185-845e-4d6df4fd42cd@172.17.8.10:43676 0ns to failover
> I1016 17:57:03.644423 29304 hierarchical.cpp:263] Deactivated framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.644451 29295 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FINISHED (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.645098 29301 master.cpp:925] Master terminating
> I1016 17:57:03.645411 29303 hierarchical.cpp:364] Removed slave 3a885ce0-812c-47ba-92d3-39d407ceba84-S0
> I1016 17:57:03.645505 29303 hierarchical.cpp:220] Removed framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.645882 29302 slave.cpp:3258] master@172.17.8.10:43676 exited
> W1016 17:57:03.645997 29302 slave.cpp:3261] Master disconnected! Waiting for a new master to be elected
> I1016 17:57:03.649463 29303 containerizer.cpp:1095] Destroying container '3a9e2eac-c090-41de-aaf2-3efc6bc91af9'
> I1016 17:57:03.700703 29310 containerizer.cpp:1278] Executor for container '3a9e2eac-c090-41de-aaf2-3efc6bc91af9' has exited
> I1016 17:57:03.704169 29301 slave.cpp:3542] Executor '2' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000 terminated with signal Killed
> I1016 17:57:03.705071 29295 status_update_manager.cpp:530] Cleaning up status update stream for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.705519 29295 slave.cpp:2355] Status update manager successfully handled status update acknowledgement (UUID: 97e333f2-7a6f-4136-9830-c987dd8488e9) for task 2 of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.705584 29295 slave.cpp:5330] Completing task 2
> I1016 17:57:03.705623 29295 slave.cpp:3646] Cleaning up executor '2' of framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.706037 29308 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2/runs/3a9e2eac-c090-41de-aaf2-3efc6bc91af9' for gc 6.99999183032593days in the future
> I1016 17:57:03.706228 29310 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2' for gc 6.99999182694518days in the future
> I1016 17:57:03.706372 29310 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2/runs/3a9e2eac-c090-41de-aaf2-3efc6bc91af9' for gc 6.99999182574222days in the future
> I1016 17:57:03.706395 29295 slave.cpp:3735] Cleaning up framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.706465 29310 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000/executors/2' for gc 6.99999182474667days in the future
> I1016 17:57:03.706521 29304 status_update_manager.cpp:284] Closing status update streams for framework 3a885ce0-812c-47ba-92d3-39d407ceba84-0000
> I1016 17:57:03.706658 29295 slave.cpp:606] Slave terminating
> I1016 17:57:03.706655 29310 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000' for gc 6.9999918229037days in the future
> I1016 17:57:03.706863 29310 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_FallbackFromEviction_HSOl47/meta/slaves/3a885ce0-812c-47ba-92d3-39d407ceba84-S0/frameworks/3a885ce0-812c-47ba-92d3-39d407ceba84-0000' for gc 6.99999182190815days in the future
> [ OK ] FetcherCacheTest.FallbackFromEviction (2617 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)