[jira] [Updated] (MESOS-5025) FetcherCacheTest.LocalUncached is flaky

[Anand Mazumdar (JIRA)]

     [ 
https://issues.apache.org/jira/browse/MESOS-5025?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
 ]

Anand Mazumdar updated MESOS-5025:
----------------------------------
    Affects Version/s: 0.29.0

> FetcherCacheTest.LocalUncached is flaky
> ---------------------------------------
>
>                 Key: MESOS-5025
>                 URL: https://issues.apache.org/jira/browse/MESOS-5025
>             Project: Mesos
>          Issue Type: Bug
>          Components: fetcher
>    Affects Versions: 0.29.0
>         Environment: CentOS 7
>            Reporter: Anand Mazumdar
>              Labels: flaky, flaky-test
>
> Showed up on an internal CI:
> {code}
> [17:57:05] :   [Step 11/11] [ RUN      ] FetcherCacheTest.LocalUncached
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.653718  1813 cluster.cpp:139] 
> Creating default 'local' authorizer
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.659001  1813 leveldb.cpp:174] 
> Opened db in 5.09329ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.660393  1813 leveldb.cpp:181] 
> Compacted db in 1.367077ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.660434  1813 leveldb.cpp:196] 
> Created db iterator in 13516ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.660446  1813 leveldb.cpp:202] 
> Seeked to beginning of db in 1531ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.660454  1813 leveldb.cpp:271] 
> Iterated through 0 keys in the db in 284ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.660478  1813 replica.cpp:779] 
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.660815  1831 recover.cpp:447] 
> Starting replica recovery
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.661001  1831 recover.cpp:473] 
> Replica is in EMPTY status
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.661866  1830 replica.cpp:673] 
> Replica in EMPTY status received a broadcasted recover request from 
> (1886)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.662237  1831 recover.cpp:193] 
> Received a recover response from a replica in EMPTY status
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.662652  1827 recover.cpp:564] 
> Updating replica status to STARTING
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.663151  1829 master.cpp:376] 
> Master 2574ed73-b254-4829-9efc-f76d89150396 (ip-172-30-2-131.mesosphere.io) 
> started on 172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.663172  1829 master.cpp:378] Flags 
> at startup: --acls="" --allocation_interval="1secs" 
> --allocator="HierarchicalDRF" --authenticate="true" 
> --authenticate_http="true" --authenticate_slaves="true" 
> --authenticators="crammd5" --authorizers="local" 
> --credentials="/tmp/VRasc1/credentials" --framework_sorter="drf" 
> --help="false" --hostname_lookup="true" --http_authenticators="basic" 
> --initialize_driver_logging="true" --log_auto_initialize="true" 
> --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50" 
> --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" 
> --quiet="false" --recovery_slave_removal_limit="100%" 
> --registry="replicated_log" --registry_fetch_timeout="1mins" 
> --registry_store_timeout="100secs" --registry_strict="true" 
> --root_submissions="true" --slave_ping_timeout="15secs" 
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" 
> --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/VRasc1/master" 
> --zk_session_timeout="10secs"
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.663374  1829 master.cpp:427] 
> Master only allowing authenticated frameworks to register
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.663384  1829 master.cpp:432] 
> Master only allowing authenticated slaves to register
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.663390  1829 credentials.hpp:35] 
> Loading credentials for authentication from '/tmp/VRasc1/credentials'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.663595  1829 master.cpp:474] Using 
> default 'crammd5' authenticator
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.663725  1829 master.cpp:545] Using 
> default 'basic' HTTP authenticator
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.663880  1829 master.cpp:583] 
> Authorization enabled
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.664001  1827 hierarchical.cpp:144] 
> Initialized hierarchical allocator process
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.664010  1831 
> whitelist_watcher.cpp:77] No whitelist given
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.664114  1834 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 1.271881ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.664136  1834 replica.cpp:320] 
> Persisted replica status to STARTING
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.664353  1833 recover.cpp:473] 
> Replica is in STARTING status
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.665315  1833 replica.cpp:673] 
> Replica in STARTING status received a broadcasted recover request from 
> (1888)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.665621  1827 recover.cpp:193] 
> Received a recover response from a replica in STARTING status
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.666237  1833 master.cpp:1826] The 
> newly elected leader is master@172.30.2.131:51675 with id 
> 2574ed73-b254-4829-9efc-f76d89150396
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.666265  1833 master.cpp:1839] 
> Elected as the leading master!
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.666286  1833 master.cpp:1526] 
> Recovering from registrar
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.666302  1829 recover.cpp:564] 
> Updating replica status to VOTING
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.666453  1828 registrar.cpp:307] 
> Recovering registrar
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.667702  1834 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 1.284762ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.667726  1834 replica.cpp:320] 
> Persisted replica status to VOTING
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.667820  1829 recover.cpp:578] 
> Successfully joined the Paxos group
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.667979  1829 recover.cpp:462] 
> Recover process terminated
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.668354  1832 log.cpp:659] 
> Attempting to start the writer
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.669368  1827 replica.cpp:493] 
> Replica received implicit promise request from (1889)@172.30.2.131:51675 with 
> proposal 1
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.670606  1827 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 1.21276ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.670629  1827 replica.cpp:342] 
> Persisted promised to 1
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.671175  1827 coordinator.cpp:238] 
> Coordinator attempting to fill missing positions
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.672204  1828 replica.cpp:388] 
> Replica received explicit promise request from (1890)@172.30.2.131:51675 for 
> position 0 with proposal 2
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.673405  1828 leveldb.cpp:341] 
> Persisting action (8 bytes) to leveldb took 1.162883ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.673429  1828 replica.cpp:712] 
> Persisted action at 0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.674235  1828 replica.cpp:537] 
> Replica received write request for position 0 from (1891)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.674288  1828 leveldb.cpp:436] 
> Reading position from leveldb took 23327ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.675454  1828 leveldb.cpp:341] 
> Persisting action (14 bytes) to leveldb took 1.136428ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.675477  1828 replica.cpp:712] 
> Persisted action at 0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.675941  1829 replica.cpp:691] 
> Replica received learned notice for position 0 from @0.0.0.0:0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.677085  1829 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 1.115099ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.677109  1829 replica.cpp:712] 
> Persisted action at 0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.677124  1829 replica.cpp:697] 
> Replica learned NOP action at position 0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.677489  1834 log.cpp:675] Writer 
> started with ending position 0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.678406  1830 leveldb.cpp:436] 
> Reading position from leveldb took 29311ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.679182  1833 registrar.cpp:340] 
> Successfully fetched the registry (0B) in 12.684288ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.679265  1833 registrar.cpp:439] 
> Applied 1 operations in 19954ns; attempting to update the 'registry'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.679831  1832 log.cpp:683] 
> Attempting to append 210 bytes to the log
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.679929  1831 coordinator.cpp:348] 
> Coordinator attempting to write APPEND action at position 1
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.680533  1830 replica.cpp:537] 
> Replica received write request for position 1 from (1892)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.683586  1830 leveldb.cpp:341] 
> Persisting action (229 bytes) to leveldb took 3.018164ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.683609  1830 replica.cpp:712] 
> Persisted action at 1
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.684149  1828 replica.cpp:691] 
> Replica received learned notice for position 1 from @0.0.0.0:0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.685715  1828 leveldb.cpp:341] 
> Persisting action (231 bytes) to leveldb took 1.542509ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.685739  1828 replica.cpp:712] 
> Persisted action at 1
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.685753  1828 replica.cpp:697] 
> Replica learned APPEND action at position 1
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.686549  1829 registrar.cpp:484] 
> Successfully updated the 'registry' in 7.241984ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.686678  1829 registrar.cpp:370] 
> Successfully recovered registrar
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.686734  1834 log.cpp:702] 
> Attempting to truncate the log to 1
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.686836  1831 coordinator.cpp:348] 
> Coordinator attempting to write TRUNCATE action at position 2
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.687144  1830 master.cpp:1634] 
> Recovered 0 slaves from the Registry (171B) ; allowing 10mins for slaves to 
> re-register
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.687191  1828 hierarchical.cpp:171] 
> Skipping recovery of hierarchical allocator: nothing to recover
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.687652  1828 replica.cpp:537] 
> Replica received write request for position 2 from (1893)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.688832  1828 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 1.150168ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.688855  1828 replica.cpp:712] 
> Persisted action at 2
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.689348  1832 replica.cpp:691] 
> Replica received learned notice for position 2 from @0.0.0.0:0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.690568  1832 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 1.190974ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.690620  1832 leveldb.cpp:399] 
> Deleting ~1 keys from leveldb took 28009ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.690636  1832 replica.cpp:712] 
> Persisted action at 2
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.690651  1832 replica.cpp:697] 
> Replica learned TRUNCATE action at position 2
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.698376  1813 
> containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.705034  1813 
> linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy 
> for the Linux launcher
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.708708  1829 slave.cpp:200] Slave 
> started on 46)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.708725  1829 slave.cpp:201] Flags 
> at startup: --appc_simple_discovery_uri_prefix="http://"; 
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" 
> --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_LocalUncached_XP781E/credential" 
> --default_role="*" --disk_watch_interval="1mins" --docker="docker" 
> --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io"; 
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" 
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" 
> --enforce_container_disk_quota="false" 
> --executor_registration_timeout="1mins" 
> --executor_shutdown_grace_period="5secs" 
> --fetcher_cache_dir="/tmp/FetcherCacheTest_LocalUncached_XP781E/fetch" 
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" 
> --gc_disk_headroom="0.1" --hadoop_home="" --help="true" 
> --hostname_lookup="true" --http_authenticators="basic" 
> --http_credentials="/tmp/FetcherCacheTest_LocalUncached_XP781E/http_credentials"
>  --image_provisioner_backend="copy" --initialize_driver_logging="true" 
> --isolation="posix/cpu,posix/mem" 
> --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" 
> --logbufsecs="0" --logging_level="INFO" 
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs" 
> --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" 
> --recover="reconnect" --recovery_timeout="15mins" 
> --registration_backoff_factor="10ms" --resources="cpus:1000;mem:1000" 
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" 
> --strict="true" --switch_user="true" --systemd_enable_support="true" 
> --systemd_runtime_directory="/run/systemd/system" --version="false" 
> --work_dir="/tmp/FetcherCacheTest_LocalUncached_XP781E"
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.709116  1829 credentials.hpp:83] 
> Loading credential for authentication from 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/credential'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.709246  1829 slave.cpp:338] Slave 
> using credential for: test-principal
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.709270  1829 credentials.hpp:35] 
> Loading credentials for authentication from 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/http_credentials'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.709431  1829 slave.cpp:390] Using 
> default 'basic' HTTP authenticator
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.709714  1829 resources.cpp:572] 
> Parsing resources as JSON failed: cpus:1000;mem:1000
> [17:57:05]W:   [Step 11/11] Trying semicolon-delimited string format instead
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.710072  1829 slave.cpp:589] Slave 
> resources: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000]
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.710126  1829 slave.cpp:597] Slave 
> attributes: [  ]
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.710136  1829 slave.cpp:602] Slave 
> hostname: ip-172-30-2-131.mesosphere.io
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.711079  1834 state.cpp:58] 
> Recovering state from '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.711343  1828 
> status_update_manager.cpp:200] Recovering status update manager
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.711530  1831 
> containerizer.cpp:407] Recovering containerizer
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.713354  1828 provisioner.cpp:245] 
> Provisioner recovery complete
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.713668  1827 slave.cpp:4726] 
> Finished recovery
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.713943  1827 slave.cpp:4898] 
> Querying resource estimator for oversubscribable resources
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.714146  1832 
> status_update_manager.cpp:174] Pausing sending status updates
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.714148  1827 slave.cpp:928] New 
> master detected at master@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.714213  1827 slave.cpp:991] 
> Authenticating with master master@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.714228  1827 slave.cpp:996] Using 
> default CRAM-MD5 authenticatee
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.714349  1827 slave.cpp:964] 
> Detecting new master
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.714381  1828 
> authenticatee.cpp:121] Creating new client SASL connection
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.714493  1827 slave.cpp:4912] 
> Received oversubscribable resources  from the resource estimator
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.714701  1832 master.cpp:5679] 
> Authenticating slave(46)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.714797  1830 
> authenticator.cpp:413] Starting authentication session for 
> crammd5_authenticatee(137)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715004  1833 authenticator.cpp:98] 
> Creating new server SASL connection
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715246  1828 
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715270  1828 
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715348  1828 
> authenticator.cpp:203] Received SASL authentication start
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715390  1828 
> authenticator.cpp:325] Authentication requires more steps
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715466  1828 
> authenticatee.cpp:258] Received SASL authentication step
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715585  1832 
> authenticator.cpp:231] Received SASL authentication step
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715620  1832 auxprop.cpp:107] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-131.mesosphere.io' server FQDN: 'ip-172-30-2-131.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715636  1832 auxprop.cpp:179] 
> Looking up auxiliary property '*userPassword'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715677  1832 auxprop.cpp:179] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715734  1832 auxprop.cpp:107] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-131.mesosphere.io' server FQDN: 'ip-172-30-2-131.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715751  1832 auxprop.cpp:129] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715761  1832 auxprop.cpp:129] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715778  1832 
> authenticator.cpp:317] Authentication success
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715862  1828 
> authenticatee.cpp:298] Authentication success
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.715942  1833 master.cpp:5709] 
> Successfully authenticated principal 'test-principal' at 
> slave(46)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.716002  1828 
> authenticator.cpp:431] Authentication session cleanup for 
> crammd5_authenticatee(137)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.716163  1829 slave.cpp:1061] 
> Successfully authenticated with master master@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.716281  1829 slave.cpp:1457] Will 
> retry registration in 3.158987ms if necessary
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.716405  1833 master.cpp:4390] 
> Registering slave at slave(46)@172.30.2.131:51675 
> (ip-172-30-2-131.mesosphere.io) with id 
> 2574ed73-b254-4829-9efc-f76d89150396-S0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.716760  1834 registrar.cpp:439] 
> Applied 1 operations in 46146ns; attempting to update the 'registry'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.717321  1834 log.cpp:683] 
> Attempting to append 396 bytes to the log
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.717409  1830 coordinator.cpp:348] 
> Coordinator attempting to write APPEND action at position 3
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.717975  1828 replica.cpp:537] 
> Replica received write request for position 3 from (1910)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.719166  1828 leveldb.cpp:341] 
> Persisting action (415 bytes) to leveldb took 1.158936ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.719189  1828 replica.cpp:712] 
> Persisted action at 3
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.719735  1829 replica.cpp:691] 
> Replica received learned notice for position 3 from @0.0.0.0:0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.719853  1827 slave.cpp:1457] Will 
> retry registration in 750973ns if necessary
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.719950  1828 master.cpp:4378] 
> Ignoring register slave message from slave(46)@172.30.2.131:51675 
> (ip-172-30-2-131.mesosphere.io) as admission is already in progress
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.720948  1829 leveldb.cpp:341] 
> Persisting action (417 bytes) to leveldb took 1.184121ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.720969  1829 replica.cpp:712] 
> Persisted action at 3
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.720984  1829 replica.cpp:697] 
> Replica learned APPEND action at position 3
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.721307  1830 slave.cpp:1457] Will 
> retry registration in 66.736924ms if necessary
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.721436  1833 master.cpp:4378] 
> Ignoring register slave message from slave(46)@172.30.2.131:51675 
> (ip-172-30-2-131.mesosphere.io) as admission is already in progress
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.722131  1827 registrar.cpp:484] 
> Successfully updated the 'registry' in 5.325056ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.722312  1830 log.cpp:702] 
> Attempting to truncate the log to 3
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.722414  1831 coordinator.cpp:348] 
> Coordinator attempting to write TRUNCATE action at position 4
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.722780  1827 slave.cpp:3618] 
> Received ping from slave-observer(45)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.722901  1833 master.cpp:4458] 
> Registered slave 2574ed73-b254-4829-9efc-f76d89150396-S0 at 
> slave(46)@172.30.2.131:51675 (ip-172-30-2-131.mesosphere.io) with 
> cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000]
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723099  1827 slave.cpp:1105] 
> Registered with master master@172.30.2.131:51675; given slave ID 
> 2574ed73-b254-4829-9efc-f76d89150396-S0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723124  1827 fetcher.cpp:81] 
> Clearing fetcher cache
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723160  1828 hierarchical.cpp:473] 
> Added slave 2574ed73-b254-4829-9efc-f76d89150396-S0 
> (ip-172-30-2-131.mesosphere.io) with cpus(*):1000; mem(*):1000; 
> disk(*):15342; ports(*):[31000-32000] (allocated: )
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723296  1831 replica.cpp:537] 
> Replica received write request for position 4 from (1911)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723310  1829 
> status_update_manager.cpp:181] Resuming sending status updates
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723318  1828 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723383  1828 
> hierarchical.cpp:1161] Performed allocation for slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 in 179141ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723459  1827 slave.cpp:1128] 
> Checkpointing SlaveInfo to 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/slave.info'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723779  1827 slave.cpp:1165] 
> Forwarding total oversubscribed resources 
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723881  1813 sched.cpp:222] 
> Version: 0.29.0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.723970  1827 master.cpp:4802] 
> Received update of slave 2574ed73-b254-4829-9efc-f76d89150396-S0 at 
> slave(46)@172.30.2.131:51675 (ip-172-30-2-131.mesosphere.io) with total 
> oversubscribed resources 
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724351  1827 sched.cpp:326] New 
> master detected at master@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724434  1827 sched.cpp:382] 
> Authenticating with master master@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724452  1827 sched.cpp:389] Using 
> default CRAM-MD5 authenticatee
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724459  1829 hierarchical.cpp:531] 
> Slave 2574ed73-b254-4829-9efc-f76d89150396-S0 (ip-172-30-2-131.mesosphere.io) 
> updated with oversubscribed resources  (total: cpus(*):1000; mem(*):1000; 
> disk(*):15342; ports(*):[31000-32000], allocated: )
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724562  1829 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724560  1831 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 1.226528ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724588  1831 replica.cpp:712] 
> Persisted action at 4
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724606  1829 
> hierarchical.cpp:1161] Performed allocation for slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 in 117017ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724692  1833 
> authenticatee.cpp:121] Creating new client SASL connection
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.724995  1829 master.cpp:5679] 
> Authenticating 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.725083  1831 
> authenticator.cpp:413] Starting authentication session for 
> crammd5_authenticatee(138)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.725359  1830 replica.cpp:691] 
> Replica received learned notice for position 4 from @0.0.0.0:0
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.725435  1833 authenticator.cpp:98] 
> Creating new server SASL connection
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.725682  1827 
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.725709  1827 
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.725814  1831 
> authenticator.cpp:203] Received SASL authentication start
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.725848  1831 
> authenticator.cpp:325] Authentication requires more steps
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.725919  1831 
> authenticatee.cpp:258] Received SASL authentication step
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726004  1831 
> authenticator.cpp:231] Received SASL authentication step
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726027  1831 auxprop.cpp:107] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-131.mesosphere.io' server FQDN: 'ip-172-30-2-131.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726034  1831 auxprop.cpp:179] 
> Looking up auxiliary property '*userPassword'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726058  1831 auxprop.cpp:179] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726079  1831 auxprop.cpp:107] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-131.mesosphere.io' server FQDN: 'ip-172-30-2-131.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726088  1831 auxprop.cpp:129] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726094  1831 auxprop.cpp:129] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726104  1831 
> authenticator.cpp:317] Authentication success
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726196  1834 
> authenticatee.cpp:298] Authentication success
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726238  1828 master.cpp:5709] 
> Successfully authenticated principal 'test-principal' at 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726310  1833 
> authenticator.cpp:431] Authentication session cleanup for 
> crammd5_authenticatee(138)@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726505  1830 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 1.117222ms
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726516  1831 sched.cpp:472] 
> Successfully authenticated with master master@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726533  1831 sched.cpp:777] 
> Sending SUBSCRIBE call to master@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726580  1830 leveldb.cpp:399] 
> Deleting ~2 keys from leveldb took 47012ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726600  1830 replica.cpp:712] 
> Persisted action at 4
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726603  1831 sched.cpp:810] Will 
> retry registration in 479.464188ms if necessary
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726620  1830 replica.cpp:697] 
> Replica learned TRUNCATE action at position 4
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726689  1828 master.cpp:2346] 
> Received SUBSCRIBE call for framework 'default' at 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] W0324 17:57:05.726716  1828 master.cpp:2353] 
> Framework at 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675 
> (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726766  1828 master.cpp:1865] 
> Authorizing framework principal '' to receive offers for role '*'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.726979  1830 master.cpp:2417] 
> Subscribing framework default with checkpointing enabled and capabilities [  ]
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.727299  1827 hierarchical.cpp:265] 
> Added framework 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.727388  1830 sched.cpp:704] 
> Framework registered with 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.727426  1830 sched.cpp:718] 
> Scheduler::registered took 15985ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.727911  1827 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.727977  1827 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 654777ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.728184  1833 master.cpp:5508] 
> Sending 1 offers to framework 2574ed73-b254-4829-9efc-f76d89150396-0000 
> (default) at scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.728536  1834 sched.cpp:874] 
> Scheduler::resourceOffers took 96103ns
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.728922  1813 resources.cpp:572] 
> Parsing resources as JSON failed: cpus:1;mem:1
> [17:57:05]W:   [Step 11/11] Trying semicolon-delimited string format instead
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.730013  1834 master.cpp:3288] 
> Processing ACCEPT call for offers: [ 2574ed73-b254-4829-9efc-f76d89150396-O0 
> ] on slave 2574ed73-b254-4829-9efc-f76d89150396-S0 at 
> slave(46)@172.30.2.131:51675 (ip-172-30-2-131.mesosphere.io) for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.730049  1834 master.cpp:2891] 
> Authorizing framework principal '' to launch task 0 as user 'root'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.731073  1834 master.hpp:177] 
> Adding task 0 with resources cpus(*):1; mem(*):1 on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 (ip-172-30-2-131.mesosphere.io)
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.731160  1834 master.cpp:3773] 
> Launching task 0 of framework 2574ed73-b254-4829-9efc-f76d89150396-0000 
> (default) at 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675 with 
> resources cpus(*):1; mem(*):1 on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 at slave(46)@172.30.2.131:51675 
> (ip-172-30-2-131.mesosphere.io)
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.731400  1829 slave.cpp:1497] Got 
> assigned task 0 for framework 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.731499  1829 slave.cpp:5448] 
> Checkpointing FrameworkInfo to 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/framework.info'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.731719  1829 slave.cpp:5459] 
> Checkpointing framework pid 
> 'scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675' to 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/framework.pid'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.731758  1832 hierarchical.cpp:890] 
> Recovered cpus(*):999; mem(*):999; disk(*):15342; ports(*):[31000-32000] 
> (total: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000], 
> allocated: cpus(*):1; mem(*):1) on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 from framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.731803  1832 hierarchical.cpp:927] 
> Framework 2574ed73-b254-4829-9efc-f76d89150396-0000 filtered slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for 5secs
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.731899  1829 resources.cpp:572] 
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [17:57:05]W:   [Step 11/11] Trying semicolon-delimited string format instead
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.732260  1829 slave.cpp:1616] 
> Launching task 0 for framework 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.732321  1829 resources.cpp:572] 
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [17:57:05]W:   [Step 11/11] Trying semicolon-delimited string format instead
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.732815  1829 paths.cpp:528] Trying 
> to chown 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
>  to user 'root'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.736246  1829 slave.cpp:5900] 
> Checkpointing ExecutorInfo to 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/executor.info'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.736605  1829 slave.cpp:5528] 
> Launching executor 0 of framework 2574ed73-b254-4829-9efc-f76d89150396-0000 
> with resources cpus(*):0.1; mem(*):32 in work directory 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.737045  1830 
> containerizer.cpp:666] Starting container 
> 'dec4d561-2aee-4468-a2e1-ef0a76586d45' for executor '0' of framework 
> '2574ed73-b254-4829-9efc-f76d89150396-0000'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.737095  1829 slave.cpp:5923] 
> Checkpointing TaskInfo to 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/tasks/0/task.info'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.737313  1829 slave.cpp:1834] 
> Queuing task '0' for executor '0' of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.737398  1829 slave.cpp:881] 
> Successfully attached file 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.741648  1830 
> linux_launcher.cpp:304] Cloning child process with flags = 
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.743307  1830 
> containerizer.cpp:1147] Checkpointing executor's forked pid 3809 to 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/pids/forked.pid'
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.744854  1828 fetcher.cpp:323] 
> Starting to fetch URIs for container: dec4d561-2aee-4468-a2e1-ef0a76586d45, 
> directory: 
> /tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45
> [17:57:05]W:   [Step 11/11] I0324 17:57:05.753646  1828 fetcher.cpp:785] 
> Fetching URIs using command 
> '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
> [17:57:06]W:   [Step 11/11] I0324 17:57:06.665369  1834 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:06]W:   [Step 11/11] I0324 17:57:06.665452  1834 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:06]W:   [Step 11/11] I0324 17:57:06.665495  1834 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:06]W:   [Step 11/11] I0324 17:57:06.665580  1834 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 934998ns
> [17:57:06]W:   [Step 11/11] II0324 17:57:06.855301  3770 exec.cpp:98] 
> Committing suicide by killing the process group
> [17:57:06]W:   [Step 11/11] 0324 17:57:06.855304  3774 exec.cpp:98] 
> Committing suicide by killing the process group
> [17:57:06]W:   [Step 11/11] I0324 17:57:06.855320  3784 exec.cpp:98] 
> Committing suicide by killing the process group
> [17:57:07]W:   [Step 11/11] I0324 17:57:07.667490  1831 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:07]W:   [Step 11/11] I0324 17:57:07.667592  1831 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:07]W:   [Step 11/11] I0324 17:57:07.667650  1831 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:07]W:   [Step 11/11] I0324 17:57:07.667773  1831 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 1.240959ms
> [17:57:08]W:   [Step 11/11] WARNING: Logging before InitGoogleLogging() is 
> written to STDERR
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.410621  3809 process.cpp:986] 
> libprocess is initialized on 172.30.2.131:58574 for 8 cpus
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.411312  3809 logging.cpp:195] 
> Logging to STDERR
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.412731  3809 exec.cpp:150] 
> Version: 0.29.0
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.418478  3859 exec.cpp:200] 
> Executor started at: executor(1)@172.30.2.131:58574 with pid 3809
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.420289  1829 slave.cpp:2779] Got 
> registration for executor '0' of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 from executor(1)@172.30.2.131:58574
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.420810  1829 slave.cpp:2865] 
> Checkpointing executor pid 'executor(1)@172.30.2.131:58574' to 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/pids/libprocess.pid'
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.422251  3861 exec.cpp:225] 
> Executor registered on slave 2574ed73-b254-4829-9efc-f76d89150396-S0
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.422477  1829 slave.cpp:1999] 
> Sending queued task '0' to executor '0' of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 at executor(1)@172.30.2.131:58574
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.423581  3861 exec.cpp:237] 
> Executor::registered took 236929ns
> [17:57:08] :   [Step 11/11] Registered executor on 
> ip-172-30-2-131.mesosphere.io
> [17:57:08] :   [Step 11/11] Starting task 0
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.423842  3861 exec.cpp:312] 
> Executor asked to run task '0'
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.423938  3861 exec.cpp:321] 
> Executor::launchTask took 73921ns
> [17:57:08] :   [Step 11/11] Forked command at 3868
> [17:57:08] :   [Step 11/11] sh -c './mesos-fetcher-test-cmd 0'
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.426338  3863 exec.cpp:535] 
> Executor sending status update TASK_RUNNING (UUID: 
> 0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.427075  1827 slave.cpp:3138] 
> Handling status update TASK_RUNNING (UUID: 
> 0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 from executor(1)@172.30.2.131:58574
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.428362  1831 
> status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 
> 0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.428397  1831 
> status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of 
> framework 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.428829  1831 
> status_update_manager.cpp:824] Checkpointing UPDATE for status update 
> TASK_RUNNING (UUID: 0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of 
> framework 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:08] :   [Step 11/11] Command exited with status 0 (pid: 3868)
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.526938  3861 exec.cpp:535] 
> Executor sending status update TASK_FINISHED (UUID: 
> 53dcf02a-3319-4f33-9334-9f2e485036ef) for task 0 of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.527662  1828 slave.cpp:3138] 
> Handling status update TASK_FINISHED (UUID: 
> 53dcf02a-3319-4f33-9334-9f2e485036ef) for task 0 of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 from executor(1)@172.30.2.131:58574
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.528662  1828 slave.cpp:5838] 
> Terminating task 0
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.668975  1830 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.669055  1830 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.669098  1830 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:08]W:   [Step 11/11] I0324 17:57:08.669176  1830 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 906316ns
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.530968  1833 slave.cpp:3664] 
> executor(1)@172.30.2.131:58574 exited
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.570600  1828 
> containerizer.cpp:1656] Executor for container 
> 'dec4d561-2aee-4468-a2e1-ef0a76586d45' has exited
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.570631  1828 
> containerizer.cpp:1421] Destroying container 
> 'dec4d561-2aee-4468-a2e1-ef0a76586d45'
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.573117  1829 cgroups.cpp:2427] 
> Freezing cgroup 
> /sys/fs/cgroup/freezer/mesos/dec4d561-2aee-4468-a2e1-ef0a76586d45
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.575049  1828 cgroups.cpp:1409] 
> Successfully froze cgroup 
> /sys/fs/cgroup/freezer/mesos/dec4d561-2aee-4468-a2e1-ef0a76586d45 after 
> 1.881856ms
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.577164  1827 cgroups.cpp:2445] 
> Thawing cgroup 
> /sys/fs/cgroup/freezer/mesos/dec4d561-2aee-4468-a2e1-ef0a76586d45
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.579040  1827 cgroups.cpp:1438] 
> Successfullly thawed cgroup 
> /sys/fs/cgroup/freezer/mesos/dec4d561-2aee-4468-a2e1-ef0a76586d45 after 
> 1.83296ms
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.581919  1833 provisioner.cpp:306] 
> Ignoring destroy request for unknown container 
> dec4d561-2aee-4468-a2e1-ef0a76586d45
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.582213  1827 slave.cpp:4039] 
> Executor '0' of framework 2574ed73-b254-4829-9efc-f76d89150396-0000 exited 
> with status 0
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.670363  1832 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.670410  1832 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.670450  1832 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:09]W:   [Step 11/11] I0324 17:57:09.670526  1832 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 755961ns
> [17:57:10]W:   [Step 11/11] I0324 17:57:10.671383  1833 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:10]W:   [Step 11/11] I0324 17:57:10.671463  1833 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:10]W:   [Step 11/11] I0324 17:57:10.671505  1833 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:10]W:   [Step 11/11] I0324 17:57:10.671603  1833 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 865268ns
> [17:57:11]W:   [Step 11/11] I0324 17:57:11.673375  1828 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:11]W:   [Step 11/11] I0324 17:57:11.673506  1828 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 1.052611ms
> [17:57:11]W:   [Step 11/11] I0324 17:57:11.673781  1827 master.cpp:5508] 
> Sending 1 offers to framework 2574ed73-b254-4829-9efc-f76d89150396-0000 
> (default) at scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:11]W:   [Step 11/11] I0324 17:57:11.674330  1834 sched.cpp:874] 
> Scheduler::resourceOffers took 137578ns
> [17:57:11]W:   [Step 11/11] I0324 17:57:11.674687  1827 master.cpp:3825] 
> Processing DECLINE call for offers: [ 2574ed73-b254-4829-9efc-f76d89150396-O1 
> ] for framework 2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:11]W:   [Step 11/11] I0324 17:57:11.675212  1834 hierarchical.cpp:890] 
> Recovered cpus(*):999; mem(*):999; disk(*):15342; ports(*):[31000-32000] 
> (total: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000], 
> allocated: cpus(*):1; mem(*):1) on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 from framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:11]W:   [Step 11/11] I0324 17:57:11.675263  1834 hierarchical.cpp:927] 
> Framework 2574ed73-b254-4829-9efc-f76d89150396-0000 filtered slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for 5secs
> [17:57:12]W:   [Step 11/11] I0324 17:57:12.674986  1832 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:12]W:   [Step 11/11] I0324 17:57:12.675068  1832 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:12]W:   [Step 11/11] I0324 17:57:12.675112  1832 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:12]W:   [Step 11/11] I0324 17:57:12.675192  1832 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 907825ns
> [17:57:13]W:   [Step 11/11] I0324 17:57:13.676286  1833 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:13]W:   [Step 11/11] I0324 17:57:13.676365  1833 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:13]W:   [Step 11/11] I0324 17:57:13.676409  1833 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:13]W:   [Step 11/11] I0324 17:57:13.676487  1833 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 888181ns
> [17:57:14]W:   [Step 11/11] I0324 17:57:14.678243  1833 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:14]W:   [Step 11/11] I0324 17:57:14.678321  1833 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:14]W:   [Step 11/11] I0324 17:57:14.678377  1833 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:14]W:   [Step 11/11] I0324 17:57:14.678460  1833 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 883895ns
> [17:57:15]W:   [Step 11/11] I0324 17:57:15.680117  1828 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:15]W:   [Step 11/11] I0324 17:57:15.680197  1828 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:15]W:   [Step 11/11] I0324 17:57:15.680241  1828 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:15]W:   [Step 11/11] I0324 17:57:15.680321  1828 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 894275ns
> [17:57:16]W:   [Step 11/11] I0324 17:57:16.681751  1827 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:16]W:   [Step 11/11] I0324 17:57:16.681871  1827 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 983355ns
> [17:57:16]W:   [Step 11/11] I0324 17:57:16.682093  1832 master.cpp:5508] 
> Sending 1 offers to framework 2574ed73-b254-4829-9efc-f76d89150396-0000 
> (default) at scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:16]W:   [Step 11/11] I0324 17:57:16.682575  1828 sched.cpp:874] 
> Scheduler::resourceOffers took 80669ns
> [17:57:16]W:   [Step 11/11] I0324 17:57:16.682859  1828 master.cpp:3825] 
> Processing DECLINE call for offers: [ 2574ed73-b254-4829-9efc-f76d89150396-O2 
> ] for framework 2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:16]W:   [Step 11/11] I0324 17:57:16.683562  1830 hierarchical.cpp:890] 
> Recovered cpus(*):999; mem(*):999; disk(*):15342; ports(*):[31000-32000] 
> (total: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000], 
> allocated: cpus(*):1; mem(*):1) on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 from framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:16]W:   [Step 11/11] I0324 17:57:16.683617  1830 hierarchical.cpp:927] 
> Framework 2574ed73-b254-4829-9efc-f76d89150396-0000 filtered slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for 5secs
> [17:57:17]W:   [Step 11/11] I0324 17:57:17.683616  1827 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:17]W:   [Step 11/11] I0324 17:57:17.683712  1827 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:17]W:   [Step 11/11] I0324 17:57:17.683758  1827 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:17]W:   [Step 11/11] I0324 17:57:17.683840  1827 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 870485ns
> [17:57:18]W:   [Step 11/11] I0324 17:57:18.685564  1834 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:18]W:   [Step 11/11] I0324 17:57:18.685636  1834 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:18]W:   [Step 11/11] I0324 17:57:18.685675  1834 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:18]W:   [Step 11/11] I0324 17:57:18.685780  1834 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 822978ns
> [17:57:19]W:   [Step 11/11] I0324 17:57:19.686969  1832 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:19]W:   [Step 11/11] I0324 17:57:19.687032  1832 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:19]W:   [Step 11/11] I0324 17:57:19.687069  1832 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:19]W:   [Step 11/11] I0324 17:57:19.687140  1832 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 808659ns
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.688407  1832 
> hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.688484  1832 
> hierarchical.cpp:1487] No resources available to allocate!
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.688524  1832 
> hierarchical.cpp:1582] No inverse offers to send out!
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.688611  1832 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 835708ns
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.715385  1834 slave.cpp:4898] 
> Querying resource estimator for oversubscribable resources
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.715633  1834 slave.cpp:4912] 
> Received oversubscribable resources  from the resource estimator
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.723800  1832 slave.cpp:3618] 
> Received ping from slave-observer(45)@172.30.2.131:51675
> [17:57:20] :   [Step 11/11] ../../src/tests/fetcher_cache_tests.cpp:617: 
> Failure
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.730820  1813 sched.cpp:1904] Asked 
> to stop the driver
> [17:57:20] :   [Step 11/11] Failed to wait 15secs for 
> awaitFinished(task.get())
> [17:57:20] :   [Step 11/11] Begin listing sandboxes
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.730908  1833 sched.cpp:1144] 
> Stopping framework '2574ed73-b254-4829-9efc-f76d89150396-0000'
> [17:57:20] :   [Step 11/11] Begin listing sandbox 
> `/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/latest`:
> [17:57:20] :   [Step 11/11] Begin file contents of `stdout`:
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.731181  1832 master.cpp:6081] 
> Processing TEARDOWN call for framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:20] :   [Step 11/11] 
> [17:57:20] :   [Step 11/11] End file
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.731218  1832 master.cpp:6093] 
> Removing framework 2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at 
> scheduler-86b94c69-50b0-4a2c-a075-2622caee08bc@172.30.2.131:51675
> [17:57:20] :   [Step 11/11] Begin file contents of `stderr`:
> [17:57:20] :   [Step 11/11] I0324 17:57:08.306455  3825 logging.cpp:195] 
> Logging to STDERR
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.731464  1834 hierarchical.cpp:375] 
> Deactivated framework 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:20] :   [Step 11/11] I0324 17:57:08.306619  3825 fetcher.cpp:430] 
> Fetcher Info: 
> {"cache_directory":"\/tmp\/FetcherCacheTest_LocalUncached_XP781E\/fetch\/slaves\/2574ed73-b254-4829-9efc-f76d89150396-S0\/root","items":[{"action":"BYPASS_CACHE","uri":{"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_LocalUncached_XP781E\/mesos-fetcher-test-assets\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_LocalUncached_XP781E\/slaves\/2574ed73-b254-4829-9efc-f76d89150396-S0\/frameworks\/2574ed73-b254-4829-9efc-f76d89150396-0000\/executors\/0\/runs\/dec4d561-2aee-4468-a2e1-ef0a76586d45","user":"root"}
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.731489  1833 slave.cpp:2215] Asked 
> to shut down framework 2574ed73-b254-4829-9efc-f76d89150396-0000 by 
> master@172.30.2.131:51675
> [17:57:20] :   [Step 11/11] I0324 17:57:08.312544  3825 fetcher.cpp:385] 
> Fetching URI 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.731530  1833 slave.cpp:2240] 
> Shutting down framework 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:20] :   [Step 11/11] I0324 17:57:08.312567  3825 fetcher.cpp:250] 
> Fetching directly into the sandbox directory
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.731570  1832 master.cpp:6608] 
> Updating the state of task 0 of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 (latest state: TASK_KILLED, status 
> update state: TASK_KILLED)
> [17:57:20] :   [Step 11/11] I0324 17:57:08.312592  3825 fetcher.cpp:187] 
> Fetching URI 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.731607  1833 slave.cpp:4143] 
> Cleaning up executor '0' of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 at executor(1)@172.30.2.131:58574
> [17:57:20] :   [Step 11/11] I0324 17:57:08.312630  3825 fetcher.cpp:167] 
> Copying resource with command:cp 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
>  
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/mesos-fetcher-test-cmd'
> [17:57:20] :   [Step 11/11] I0324 17:57:08.315564  3825 fetcher.cpp:462] 
> Fetched 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
>  to 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/mesos-fetcher-test-cmd'
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732023  1834 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
>  for gc 6.99999152859852days in the future
> [17:57:20] :   [Step 11/11] 
> [17:57:20] :   [Step 11/11] End file
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732002  1832 master.cpp:6674] 
> Removing task 0 with resources cpus(*):1; mem(*):1 of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 at slave(46)@172.30.2.131:51675 
> (ip-172-30-2-131.mesosphere.io)
> [17:57:20] :   [Step 11/11] Begin file contents of `mesos-fetcher-test-cmd`:
> [17:57:20] :   [Step 11/11] touch mesos-fetcher-test-cmd$1
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732062  1827 hierarchical.cpp:890] 
> Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; 
> disk(*):15342; ports(*):[31000-32000], allocated: ) on slave 
> 2574ed73-b254-4829-9efc-f76d89150396-S0 from framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:20] :   [Step 11/11] End file
> [17:57:20] :   [Step 11/11] Begin file contents of `mesos-fetcher-test-cmd0`:
> [17:57:20] :   [Step 11/11] 
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732177  1834 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0'
>  for gc 6.99999152667852days in the future
> [17:57:20] :   [Step 11/11] End file
> [17:57:20] :   [Step 11/11] End sandbox
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732273  1833 slave.cpp:4231] 
> Cleaning up framework 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:20] :   [Step 11/11] End sandboxes
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732314  1834 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
>  for gc 6.99999152579852days in the future
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732450  1834 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0'
>  for gc 6.99999152519704days in the future
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732465  1832 master.cpp:1083] 
> Master terminating
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732508  1827 hierarchical.cpp:326] 
> Removed framework 2574ed73-b254-4829-9efc-f76d89150396-0000
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732548  1834 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000'
>  for gc 6.99999152388741days in the future
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732643  1834 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000'
>  for gc 6.99999152215407days in the future
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.732834  1827 hierarchical.cpp:505] 
> Removed slave 2574ed73-b254-4829-9efc-f76d89150396-S0
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.733188  1828 slave.cpp:3664] 
> master@172.30.2.131:51675 exited
> [17:57:20]W:   [Step 11/11] W0324 17:57:20.733211  1828 slave.cpp:3667] 
> Master disconnected! Waiting for a new master to be elected
> [17:57:20]W:   [Step 11/11] I0324 17:57:20.737687  1827 slave.cpp:800] Slave 
> terminating
> [17:57:21]W:   [Step 11/11] I0324 17:57:21.864037  1831 
> status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 
> 0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of framework 
> 2574ed73-b254-4829-9efc-f76d89150396-0000 to the slave
> [17:57:21] :   [Step 11/11] [  FAILED  ] FetcherCacheTest.LocalUncached 
> (16222 ms)
> {code}
> Logs from a good previous run
> {code}
> [12:21:04] :   [Step 11/11] [ RUN      ] FetcherCacheTest.LocalUncached
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.567256  1814 cluster.cpp:139] 
> Creating default 'local' authorizer
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.571188  1814 leveldb.cpp:174] 
> Opened db in 3.736423ms
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.572331  1814 leveldb.cpp:181] 
> Compacted db in 1.117018ms
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.572370  1814 leveldb.cpp:196] 
> Created db iterator in 13259ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.572381  1814 leveldb.cpp:202] 
> Seeked to beginning of db in 1417ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.572387  1814 leveldb.cpp:271] 
> Iterated through 0 keys in the db in 270ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.572413  1814 replica.cpp:779] 
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.572785  1833 recover.cpp:447] 
> Starting replica recovery
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.573035  1833 recover.cpp:473] 
> Replica is in EMPTY status
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.573856  1830 replica.cpp:673] 
> Replica in EMPTY status received a broadcasted recover request from 
> (1889)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.574309  1832 recover.cpp:193] 
> Received a recover response from a replica in EMPTY status
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.574671  1835 recover.cpp:564] 
> Updating replica status to STARTING
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.575477  1828 master.cpp:376] 
> Master bc02c3e1-1349-4721-827f-b111f17ad00d (ip-172-30-2-102.mesosphere.io) 
> started on 172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.575500  1828 master.cpp:378] Flags 
> at startup: --acls="" --allocation_interval="1secs" 
> --allocator="HierarchicalDRF" --authenticate="true" 
> --authenticate_http="true" --authenticate_slaves="true" 
> --authenticators="crammd5" --authorizers="local" 
> --credentials="/tmp/B6KjIF/credentials" --framework_sorter="drf" 
> --help="false" --hostname_lookup="true" --http_authenticators="basic" 
> --initialize_driver_logging="true" --log_auto_initialize="true" 
> --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50" 
> --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" 
> --quiet="false" --recovery_slave_removal_limit="100%" 
> --registry="replicated_log" --registry_fetch_timeout="1mins" 
> --registry_store_timeout="100secs" --registry_strict="true" 
> --root_submissions="true" --slave_ping_timeout="15secs" 
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" 
> --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/B6KjIF/master" 
> --zk_session_timeout="10secs"
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.575721  1828 master.cpp:427] 
> Master only allowing authenticated frameworks to register
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.575731  1828 master.cpp:432] 
> Master only allowing authenticated slaves to register
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.575736  1828 credentials.hpp:35] 
> Loading credentials for authentication from '/tmp/B6KjIF/credentials'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.575953  1828 master.cpp:474] Using 
> default 'crammd5' authenticator
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.576073  1828 master.cpp:545] Using 
> default 'basic' HTTP authenticator
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.576164  1830 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 1.327792ms
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.576186  1830 replica.cpp:320] 
> Persisted replica status to STARTING
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.576200  1828 master.cpp:583] 
> Authorization enabled
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.576340  1833 hierarchical.cpp:144] 
> Initialized hierarchical allocator process
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.576367  1832 
> whitelist_watcher.cpp:77] No whitelist given
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.576372  1834 recover.cpp:473] 
> Replica is in STARTING status
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.577231  1831 replica.cpp:673] 
> Replica in STARTING status received a broadcasted recover request from 
> (1891)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.577499  1830 recover.cpp:193] 
> Received a recover response from a replica in STARTING status
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.577994  1835 recover.cpp:564] 
> Updating replica status to VOTING
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.578761  1831 master.cpp:1826] The 
> newly elected leader is master@172.30.2.102:40940 with id 
> bc02c3e1-1349-4721-827f-b111f17ad00d
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.578784  1831 master.cpp:1839] 
> Elected as the leading master!
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.578796  1831 master.cpp:1526] 
> Recovering from registrar
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.578905  1830 registrar.cpp:307] 
> Recovering registrar
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.579027  1833 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 918129ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.579046  1833 replica.cpp:320] 
> Persisted replica status to VOTING
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.579139  1835 recover.cpp:578] 
> Successfully joined the Paxos group
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.579337  1835 recover.cpp:462] 
> Recover process terminated
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.579701  1830 log.cpp:659] 
> Attempting to start the writer
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.580749  1834 replica.cpp:493] 
> Replica received implicit promise request from (1892)@172.30.2.102:40940 with 
> proposal 1
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.581714  1834 leveldb.cpp:304] 
> Persisting metadata (8 bytes) to leveldb took 936238ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.581732  1834 replica.cpp:342] 
> Persisted promised to 1
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.582298  1833 coordinator.cpp:238] 
> Coordinator attempting to fill missing positions
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.583406  1828 replica.cpp:388] 
> Replica received explicit promise request from (1893)@172.30.2.102:40940 for 
> position 0 with proposal 2
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.584342  1828 leveldb.cpp:341] 
> Persisting action (8 bytes) to leveldb took 904348ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.584362  1828 replica.cpp:712] 
> Persisted action at 0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.585230  1835 replica.cpp:537] 
> Replica received write request for position 0 from (1894)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.585275  1835 leveldb.cpp:436] 
> Reading position from leveldb took 21110ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.586259  1835 leveldb.cpp:341] 
> Persisting action (14 bytes) to leveldb took 952672ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.586278  1835 replica.cpp:712] 
> Persisted action at 0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.586763  1834 replica.cpp:691] 
> Replica received learned notice for position 0 from @0.0.0.0:0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.587682  1834 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 893753ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.587700  1834 replica.cpp:712] 
> Persisted action at 0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.587714  1834 replica.cpp:697] 
> Replica learned NOP action at position 0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.588202  1828 log.cpp:675] Writer 
> started with ending position 0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.589071  1832 leveldb.cpp:436] 
> Reading position from leveldb took 28408ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.589875  1828 registrar.cpp:340] 
> Successfully fetched the registry (0B) in 10.928896ms
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.589977  1828 registrar.cpp:439] 
> Applied 1 operations in 22584ns; attempting to update the 'registry'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.590565  1835 log.cpp:683] 
> Attempting to append 210 bytes to the log
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.590685  1829 coordinator.cpp:348] 
> Coordinator attempting to write APPEND action at position 1
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.591286  1834 replica.cpp:537] 
> Replica received write request for position 1 from (1895)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.592260  1834 leveldb.cpp:341] 
> Persisting action (229 bytes) to leveldb took 940368ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.592279  1834 replica.cpp:712] 
> Persisted action at 1
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.592784  1832 replica.cpp:691] 
> Replica received learned notice for position 1 from @0.0.0.0:0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.593720  1832 leveldb.cpp:341] 
> Persisting action (231 bytes) to leveldb took 912364ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.593739  1832 replica.cpp:712] 
> Persisted action at 1
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.593755  1832 replica.cpp:697] 
> Replica learned APPEND action at position 1
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.594544  1833 registrar.cpp:484] 
> Successfully updated the 'registry' in 4.509952ms
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.594656  1833 registrar.cpp:370] 
> Successfully recovered registrar
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.594738  1835 log.cpp:702] 
> Attempting to truncate the log to 1
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.594861  1831 coordinator.cpp:348] 
> Coordinator attempting to write TRUNCATE action at position 2
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.595152  1828 master.cpp:1634] 
> Recovered 0 slaves from the Registry (171B) ; allowing 10mins for slaves to 
> re-register
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.595176  1835 hierarchical.cpp:171] 
> Skipping recovery of hierarchical allocator: nothing to recover
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.595652  1832 replica.cpp:537] 
> Replica received write request for position 2 from (1896)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.596577  1832 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 896605ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.596597  1832 replica.cpp:712] 
> Persisted action at 2
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.597105  1828 replica.cpp:691] 
> Replica received learned notice for position 2 from @0.0.0.0:0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.598078  1828 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 943692ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.598124  1828 leveldb.cpp:399] 
> Deleting ~1 keys from leveldb took 26966ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.598139  1828 replica.cpp:712] 
> Persisted action at 2
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.598153  1828 replica.cpp:697] 
> Replica learned TRUNCATE action at position 2
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.606338  1814 
> containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.612812  1814 
> linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy 
> for the Linux launcher
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.617058  1835 slave.cpp:199] Slave 
> started on 46)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.617077  1835 slave.cpp:200] Flags 
> at startup: --appc_simple_discovery_uri_prefix="http://"; 
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" 
> --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_LocalUncached_GCYrPs/credential" 
> --default_role="*" --disk_watch_interval="1mins" --docker="docker" 
> --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io"; 
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" 
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" 
> --enforce_container_disk_quota="false" 
> --executor_registration_timeout="1mins" 
> --executor_shutdown_grace_period="5secs" 
> --fetcher_cache_dir="/tmp/FetcherCacheTest_LocalUncached_GCYrPs/fetch" 
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" 
> --gc_disk_headroom="0.1" --hadoop_home="" --help="true" 
> --hostname_lookup="true" --http_authenticators="basic" 
> --http_credentials="/tmp/FetcherCacheTest_LocalUncached_GCYrPs/http_credentials"
>  --image_provisioner_backend="copy" --initialize_driver_logging="true" 
> --isolation="posix/cpu,posix/mem" 
> --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" 
> --logbufsecs="0" --logging_level="INFO" 
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs" 
> --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" 
> --recover="reconnect" --recovery_timeout="15mins" 
> --registration_backoff_factor="10ms" --resources="cpus:1000;mem:1000" 
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" 
> --strict="true" --switch_user="true" --systemd_enable_support="true" 
> --systemd_runtime_directory="/run/systemd/system" --version="false" 
> --work_dir="/tmp/FetcherCacheTest_LocalUncached_GCYrPs"
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.617379  1835 credentials.hpp:83] 
> Loading credential for authentication from 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/credential'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.617516  1835 slave.cpp:337] Slave 
> using credential for: test-principal
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.617538  1835 credentials.hpp:35] 
> Loading credentials for authentication from 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/http_credentials'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.617687  1835 slave.cpp:389] Using 
> default 'basic' HTTP authenticator
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.617929  1835 resources.cpp:572] 
> Parsing resources as JSON failed: cpus:1000;mem:1000
> [12:21:04]W:   [Step 11/11] Trying semicolon-delimited string format instead
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.618314  1835 slave.cpp:588] Slave 
> resources: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000]
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.618369  1835 slave.cpp:596] Slave 
> attributes: [  ]
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.618378  1835 slave.cpp:601] Slave 
> hostname: ip-172-30-2-102.mesosphere.io
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.619313  1833 state.cpp:58] 
> Recovering state from '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.619479  1828 
> status_update_manager.cpp:200] Recovering status update manager
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.619710  1832 
> containerizer.cpp:407] Recovering containerizer
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.621534  1831 provisioner.cpp:245] 
> Provisioner recovery complete
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.621827  1830 slave.cpp:4700] 
> Finished recovery
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622120  1830 slave.cpp:4872] 
> Querying resource estimator for oversubscribable resources
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622316  1831 
> status_update_manager.cpp:174] Pausing sending status updates
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622315  1830 slave.cpp:927] New 
> master detected at master@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622382  1830 slave.cpp:990] 
> Authenticating with master master@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622397  1830 slave.cpp:995] Using 
> default CRAM-MD5 authenticatee
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622514  1830 slave.cpp:963] 
> Detecting new master
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622555  1834 
> authenticatee.cpp:121] Creating new client SASL connection
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622681  1830 slave.cpp:4886] 
> Received oversubscribable resources  from the resource estimator
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622889  1830 master.cpp:5679] 
> Authenticating slave(46)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.622972  1831 
> authenticator.cpp:413] Starting authentication session for 
> crammd5_authenticatee(137)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623136  1834 authenticator.cpp:98] 
> Creating new server SASL connection
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623353  1830 
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623373  1830 
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623450  1830 
> authenticator.cpp:203] Received SASL authentication start
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623492  1830 
> authenticator.cpp:325] Authentication requires more steps
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623566  1830 
> authenticatee.cpp:258] Received SASL authentication step
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623667  1830 
> authenticator.cpp:231] Received SASL authentication step
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623693  1830 auxprop.cpp:107] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-102.mesosphere.io' server FQDN: 'ip-172-30-2-102.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623703  1830 auxprop.cpp:179] 
> Looking up auxiliary property '*userPassword'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623729  1830 auxprop.cpp:179] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623749  1830 auxprop.cpp:107] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-102.mesosphere.io' server FQDN: 'ip-172-30-2-102.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623757  1830 auxprop.cpp:129] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623762  1830 auxprop.cpp:129] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623774  1830 
> authenticator.cpp:317] Authentication success
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623845  1833 
> authenticatee.cpp:298] Authentication success
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623888  1828 master.cpp:5709] 
> Successfully authenticated principal 'test-principal' at 
> slave(46)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.623942  1829 
> authenticator.cpp:431] Authentication session cleanup for 
> crammd5_authenticatee(137)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.624183  1832 slave.cpp:1060] 
> Successfully authenticated with master master@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.624276  1832 slave.cpp:1456] Will 
> retry registration in 4.413456ms if necessary
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.624439  1834 master.cpp:4390] 
> Registering slave at slave(46)@172.30.2.102:40940 
> (ip-172-30-2-102.mesosphere.io) with id 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.624773  1833 registrar.cpp:439] 
> Applied 1 operations in 45733ns; attempting to update the 'registry'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.625387  1831 log.cpp:683] 
> Attempting to append 396 bytes to the log
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.625485  1829 coordinator.cpp:348] 
> Coordinator attempting to write APPEND action at position 3
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.626085  1835 replica.cpp:537] 
> Replica received write request for position 3 from (1913)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.627172  1835 leveldb.cpp:341] 
> Persisting action (415 bytes) to leveldb took 1.049909ms
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.627197  1835 replica.cpp:712] 
> Persisted action at 3
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.627661  1830 replica.cpp:691] 
> Replica received learned notice for position 3 from @0.0.0.0:0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.628654  1830 leveldb.cpp:341] 
> Persisting action (417 bytes) to leveldb took 965890ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.628672  1830 replica.cpp:712] 
> Persisted action at 3
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.628687  1830 replica.cpp:697] 
> Replica learned APPEND action at position 3
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.629813  1829 registrar.cpp:484] 
> Successfully updated the 'registry' in 4.983296ms
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.629850  1833 slave.cpp:1456] Will 
> retry registration in 25.88132ms if necessary
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.629941  1832 master.cpp:4378] 
> Ignoring register slave message from slave(46)@172.30.2.102:40940 
> (ip-172-30-2-102.mesosphere.io) as admission is already in progress
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.629984  1830 log.cpp:702] 
> Attempting to truncate the log to 3
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.630095  1833 coordinator.cpp:348] 
> Coordinator attempting to write TRUNCATE action at position 4
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.630491  1829 slave.cpp:3617] 
> Received ping from slave-observer(45)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.630549  1828 master.cpp:4458] 
> Registered slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at 
> slave(46)@172.30.2.102:40940 (ip-172-30-2-102.mesosphere.io) with 
> cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000]
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.630758  1829 slave.cpp:1104] 
> Registered with master master@172.30.2.102:40940; given slave ID 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.630782  1829 fetcher.cpp:81] 
> Clearing fetcher cache
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.630846  1833 hierarchical.cpp:473] 
> Added slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0 
> (ip-172-30-2-102.mesosphere.io) with cpus(*):1000; mem(*):1000; 
> disk(*):15342; ports(*):[31000-32000] (allocated: )
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.630884  1830 
> status_update_manager.cpp:181] Resuming sending status updates
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.631034  1833 
> hierarchical.cpp:1466] No resources available to allocate!
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.631054  1829 slave.cpp:1127] 
> Checkpointing SlaveInfo to 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/slave.info'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.631098  1833 
> hierarchical.cpp:1161] Performed allocation for slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 in 208473ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.631265  1829 slave.cpp:1164] 
> Forwarding total oversubscribed resources 
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.631383  1829 master.cpp:4802] 
> Received update of slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at 
> slave(46)@172.30.2.102:40940 (ip-172-30-2-102.mesosphere.io) with total 
> oversubscribed resources 
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.631742  1829 hierarchical.cpp:531] 
> Slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0 (ip-172-30-2-102.mesosphere.io) 
> updated with oversubscribed resources  (total: cpus(*):1000; mem(*):1000; 
> disk(*):15342; ports(*):[31000-32000], allocated: )
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.631842  1829 
> hierarchical.cpp:1466] No resources available to allocate!
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.631886  1829 
> hierarchical.cpp:1161] Performed allocation for slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 in 114128ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.632283  1831 replica.cpp:537] 
> Replica received write request for position 4 from (1914)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.632951  1814 sched.cpp:222] 
> Version: 0.29.0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.633296  1831 leveldb.cpp:341] 
> Persisting action (16 bytes) to leveldb took 976640ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.633316  1831 replica.cpp:712] 
> Persisted action at 4
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.633411  1833 sched.cpp:326] New 
> master detected at master@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.633487  1833 sched.cpp:382] 
> Authenticating with master master@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.633502  1833 sched.cpp:389] Using 
> default CRAM-MD5 authenticatee
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.633780  1830 
> authenticatee.cpp:121] Creating new client SASL connection
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.633889  1833 replica.cpp:691] 
> Replica received learned notice for position 4 from @0.0.0.0:0
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634055  1834 master.cpp:5679] 
> Authenticating 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634155  1829 
> authenticator.cpp:413] Starting authentication session for 
> crammd5_authenticatee(138)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634340  1835 authenticator.cpp:98] 
> Creating new server SASL connection
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634572  1830 
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634593  1830 
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634670  1830 
> authenticator.cpp:203] Received SASL authentication start
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634707  1830 
> authenticator.cpp:325] Authentication requires more steps
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634778  1830 
> authenticatee.cpp:258] Received SASL authentication step
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634822  1833 leveldb.cpp:341] 
> Persisting action (18 bytes) to leveldb took 901985ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634884  1828 
> authenticator.cpp:231] Received SASL authentication step
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634887  1833 leveldb.cpp:399] 
> Deleting ~2 keys from leveldb took 39949ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634909  1833 replica.cpp:712] 
> Persisted action at 4
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634908  1828 auxprop.cpp:107] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-102.mesosphere.io' server FQDN: 'ip-172-30-2-102.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: false 
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634920  1828 auxprop.cpp:179] 
> Looking up auxiliary property '*userPassword'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634927  1833 replica.cpp:697] 
> Replica learned TRUNCATE action at position 4
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634944  1828 auxprop.cpp:179] 
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634963  1828 auxprop.cpp:107] 
> Request to lookup properties for user: 'test-principal' realm: 
> 'ip-172-30-2-102.mesosphere.io' server FQDN: 'ip-172-30-2-102.mesosphere.io' 
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
> SASL_AUXPROP_AUTHZID: true 
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634973  1828 auxprop.cpp:129] 
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634977  1828 auxprop.cpp:129] 
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since 
> SASL_AUXPROP_AUTHZID == true
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.634987  1828 
> authenticator.cpp:317] Authentication success
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.635072  1835 
> authenticatee.cpp:298] Authentication success
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.635123  1829 master.cpp:5709] 
> Successfully authenticated principal 'test-principal' at 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.635221  1835 
> authenticator.cpp:431] Authentication session cleanup for 
> crammd5_authenticatee(138)@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.635397  1832 sched.cpp:472] 
> Successfully authenticated with master master@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.635418  1832 sched.cpp:777] 
> Sending SUBSCRIBE call to master@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.635510  1832 sched.cpp:810] Will 
> retry registration in 160.331175ms if necessary
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.635594  1833 master.cpp:2346] 
> Received SUBSCRIBE call for framework 'default' at 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] W0324 12:21:04.635619  1833 master.cpp:2353] 
> Framework at 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940 
> (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.635656  1833 master.cpp:1865] 
> Authorizing framework principal '' to receive offers for role '*'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.635871  1828 master.cpp:2417] 
> Subscribing framework default with checkpointing enabled and capabilities [  ]
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.636237  1830 hierarchical.cpp:265] 
> Added framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.636337  1829 sched.cpp:704] 
> Framework registered with bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.636379  1829 sched.cpp:718] 
> Scheduler::registered took 19088ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.636812  1830 
> hierarchical.cpp:1561] No inverse offers to send out!
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.636881  1830 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 623607ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.637100  1828 master.cpp:5508] 
> Sending 1 offers to framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 
> (default) at scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.637449  1828 sched.cpp:874] 
> Scheduler::resourceOffers took 95352ns
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.637784  1814 resources.cpp:572] 
> Parsing resources as JSON failed: cpus:1;mem:1
> [12:21:04]W:   [Step 11/11] Trying semicolon-delimited string format instead
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.638835  1831 master.cpp:3288] 
> Processing ACCEPT call for offers: [ bc02c3e1-1349-4721-827f-b111f17ad00d-O0 
> ] on slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at 
> slave(46)@172.30.2.102:40940 (ip-172-30-2-102.mesosphere.io) for framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.638870  1831 master.cpp:2891] 
> Authorizing framework principal '' to launch task 0 as user 'root'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.639928  1831 master.hpp:177] 
> Adding task 0 with resources cpus(*):1; mem(*):1 on slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 (ip-172-30-2-102.mesosphere.io)
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.640027  1831 master.cpp:3773] 
> Launching task 0 of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 
> (default) at 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940 with 
> resources cpus(*):1; mem(*):1 on slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at slave(46)@172.30.2.102:40940 
> (ip-172-30-2-102.mesosphere.io)
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.640288  1828 slave.cpp:1496] Got 
> assigned task 0 for framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.640427  1828 slave.cpp:5422] 
> Checkpointing FrameworkInfo to 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/framework.info'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.640698  1828 slave.cpp:5433] 
> Checkpointing framework pid 
> 'scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940' to 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/framework.pid'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.640852  1830 hierarchical.cpp:890] 
> Recovered cpus(*):999; mem(*):999; disk(*):15342; ports(*):[31000-32000] 
> (total: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000], 
> allocated: cpus(*):1; mem(*):1) on slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 from framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.640918  1828 resources.cpp:572] 
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:21:04]W:   [Step 11/11] Trying semicolon-delimited string format instead
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.640920  1830 hierarchical.cpp:927] 
> Framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 filtered slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 for 5secs
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.641340  1828 slave.cpp:1615] 
> Launching task 0 for framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.641399  1828 resources.cpp:572] 
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:21:04]W:   [Step 11/11] Trying semicolon-delimited string format instead
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.641849  1828 paths.cpp:528] Trying 
> to chown 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
>  to user 'root'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.645509  1828 slave.cpp:5874] 
> Checkpointing ExecutorInfo to 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/executor.info'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.645871  1828 slave.cpp:5502] 
> Launching executor 0 of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 
> with resources cpus(*):0.1; mem(*):32 in work directory 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.646260  1831 
> containerizer.cpp:666] Starting container 
> '379d8df6-a66d-4b37-990b-8295d2f9fe51' for executor '0' of framework 
> 'bc02c3e1-1349-4721-827f-b111f17ad00d-0000'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.646313  1828 slave.cpp:5897] 
> Checkpointing TaskInfo to 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51/tasks/0/task.info'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.646567  1828 slave.cpp:1833] 
> Queuing task '0' for executor '0' of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.646651  1828 slave.cpp:880] 
> Successfully attached file 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.650753  1831 
> linux_launcher.cpp:304] Cloning child process with flags = 
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.652362  1831 
> containerizer.cpp:1147] Checkpointing executor's forked pid 3810 to 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51/pids/forked.pid'
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.653764  1830 fetcher.cpp:323] 
> Starting to fetch URIs for container: 379d8df6-a66d-4b37-990b-8295d2f9fe51, 
> directory: 
> /tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51
> [12:21:04]W:   [Step 11/11] I0324 12:21:04.663184  1830 fetcher.cpp:785] 
> Fetching URIs using command 
> '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
> [12:21:05]W:   [Step 11/11] I0324 12:21:05.578089  1832 
> hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 for framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:05]W:   [Step 11/11] I0324 12:21:05.578176  1832 
> hierarchical.cpp:1466] No resources available to allocate!
> [12:21:05]W:   [Step 11/11] I0324 12:21:05.578214  1832 
> hierarchical.cpp:1561] No inverse offers to send out!
> [12:21:05]W:   [Step 11/11] I0324 12:21:05.578284  1832 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 815775ns
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.579536  1831 
> hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; 
> disk(*):15342; ports(*):[31000-32000] on slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 for framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.579607  1831 
> hierarchical.cpp:1466] No resources available to allocate!
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.579643  1831 
> hierarchical.cpp:1561] No inverse offers to send out!
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.579723  1831 
> hierarchical.cpp:1138] Performed allocation for 1 slaves in 724631ns
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.760300  3775 exec.cpp:98] 
> Committing suicide by killing the process group
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.764399  3768 exec.cpp:98] 
> Committing suicide by killing the process group
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.764401  3774 exec.cpp:98] 
> Committing suicide by killing the process group
> [12:21:06]W:   [Step 11/11] WARNING: Logging before InitGoogleLogging() is 
> written to STDERR
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.835119  3810 process.cpp:986] 
> libprocess is initialized on 172.30.2.102:37168 for 8 cpus
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.835714  3810 logging.cpp:195] 
> Logging to STDERR
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.837157  3810 exec.cpp:150] 
> Version: 0.29.0
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.842833  3865 exec.cpp:200] 
> Executor started at: executor(1)@172.30.2.102:37168 with pid 3810
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.844568  1835 slave.cpp:2778] Got 
> registration for executor '0' of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from executor(1)@172.30.2.102:37168
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.844990  1835 slave.cpp:2864] 
> Checkpointing executor pid 'executor(1)@172.30.2.102:37168' to 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51/pids/libprocess.pid'
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.846287  3867 exec.cpp:225] 
> Executor registered on slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.846424  1828 slave.cpp:1998] 
> Sending queued task '0' to executor '0' of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 at executor(1)@172.30.2.102:37168
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.847616  3867 exec.cpp:237] 
> Executor::registered took 221040ns
> [12:21:06] :   [Step 11/11] Registered executor on 
> ip-172-30-2-102.mesosphere.io
> [12:21:06] :   [Step 11/11] Starting task 0
> [12:21:06] :   [Step 11/11] Forked command at 3869
> [12:21:06] :   [Step 11/11] sh -c './mesos-fetcher-test-cmd 0'
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.847834  3867 exec.cpp:312] 
> Executor asked to run task '0'
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.847920  3867 exec.cpp:321] 
> Executor::launchTask took 67647ns
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.850314  3860 exec.cpp:535] 
> Executor sending status update TASK_RUNNING (UUID: 
> edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.851021  1832 slave.cpp:3137] 
> Handling status update TASK_RUNNING (UUID: 
> edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from executor(1)@172.30.2.102:37168
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.852288  1830 
> status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 
> edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.852325  1830 
> status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of 
> framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.852639  1830 
> status_update_manager.cpp:824] Checkpointing UPDATE for status update 
> TASK_RUNNING (UUID: edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of 
> framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.855361  1830 
> status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 
> edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to the slave
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.855587  1829 slave.cpp:3535] 
> Forwarding the update TASK_RUNNING (UUID: 
> edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to master@172.30.2.102:40940
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.855747  1829 slave.cpp:3429] 
> Status update manager successfully handled status update TASK_RUNNING (UUID: 
> edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.855793  1829 slave.cpp:3445] 
> Sending acknowledgement for status update TASK_RUNNING (UUID: 
> edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to executor(1)@172.30.2.102:37168
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.855891  1831 master.cpp:4947] 
> Status update TASK_RUNNING (UUID: edf46287-7b64-4e88-acba-b13d0df48d76) for 
> task 0 of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at slave(46)@172.30.2.102:40940 
> (ip-172-30-2-102.mesosphere.io)
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.855934  1831 master.cpp:4995] 
> Forwarding status update TASK_RUNNING (UUID: 
> edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.856156  1831 master.cpp:6608] 
> Updating the state of task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (latest state: TASK_RUNNING, status 
> update state: TASK_RUNNING)
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.856299  3862 exec.cpp:358] 
> Executor received status update acknowledgement 
> edf46287-7b64-4e88-acba-b13d0df48d76 for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.856359  1833 sched.cpp:982] 
> Scheduler::statusUpdate took 128769ns
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.856580  1835 master.cpp:4102] 
> Processing ACKNOWLEDGE call edf46287-7b64-4e88-acba-b13d0df48d76 for task 0 
> of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940 on slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.856812  1835 
> status_update_manager.cpp:392] Received status update acknowledgement (UUID: 
> edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.856919  1835 
> status_update_manager.cpp:824] Checkpointing ACK for status update 
> TASK_RUNNING (UUID: edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of 
> framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.859555  1834 slave.cpp:2547] 
> Status update manager successfully handled status update acknowledgement 
> (UUID: edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06] :   [Step 11/11] Command exited with status 0 (pid: 3869)
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.951278  3866 exec.cpp:535] 
> Executor sending status update TASK_FINISHED (UUID: 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.951813  1833 slave.cpp:3137] 
> Handling status update TASK_FINISHED (UUID: 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from executor(1)@172.30.2.102:37168
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.952723  1829 slave.cpp:5812] 
> Terminating task 0
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.953763  1832 
> status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.953805  1832 
> status_update_manager.cpp:824] Checkpointing UPDATE for status update 
> TASK_FINISHED (UUID: eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of 
> framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.955874  1832 
> status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to the slave
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.956120  1828 slave.cpp:3535] 
> Forwarding the update TASK_FINISHED (UUID: 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to master@172.30.2.102:40940
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.956321  1828 slave.cpp:3429] 
> Status update manager successfully handled status update TASK_FINISHED (UUID: 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.956365  1828 slave.cpp:3445] 
> Sending acknowledgement for status update TASK_FINISHED (UUID: 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to executor(1)@172.30.2.102:37168
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.956405  1830 master.cpp:4947] 
> Status update TASK_FINISHED (UUID: eec13fa8-9db6-4140-97b2-150a4a5f7e02) for 
> task 0 of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at slave(46)@172.30.2.102:40940 
> (ip-172-30-2-102.mesosphere.io)
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.956439  1830 master.cpp:4995] 
> Forwarding status update TASK_FINISHED (UUID: 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.956568  1830 master.cpp:6608] 
> Updating the state of task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (latest state: TASK_FINISHED, 
> status update state: TASK_FINISHED)
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.956862  3864 exec.cpp:358] 
> Executor received status update acknowledgement 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02 for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.956899  1828 sched.cpp:982] 
> Scheduler::statusUpdate took 217593ns
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957033  1835 hierarchical.cpp:890] 
> Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; 
> disk(*):15342; ports(*):[31000-32000], allocated: ) on slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 from framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957149  1833 master.cpp:4102] 
> Processing ACKNOWLEDGE call eec13fa8-9db6-4140-97b2-150a4a5f7e02 for task 0 
> of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940 on slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957195  1833 master.cpp:6674] 
> Removing task 0 with resources cpus(*):1; mem(*):1 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 on slave 
> bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at slave(46)@172.30.2.102:40940 
> (ip-172-30-2-102.mesosphere.io)
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957273  1814 sched.cpp:1904] Asked 
> to stop the driver
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957351  1828 sched.cpp:1144] 
> Stopping framework 'bc02c3e1-1349-4721-827f-b111f17ad00d-0000'
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957505  1831 
> status_update_manager.cpp:392] Received status update acknowledgement (UUID: 
> eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957535  1833 master.cpp:6081] 
> Processing TEARDOWN call for framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957566  1833 master.cpp:6093] 
> Removing framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at 
> scheduler-b5ca505e-52ad-4b90-8f30-519b1c6515c2@172.30.2.102:40940
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957608  1831 
> status_update_manager.cpp:824] Checkpointing ACK for status update 
> TASK_FINISHED (UUID: eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of 
> framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957799  1829 hierarchical.cpp:375] 
> Deactivated framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957862  1830 slave.cpp:2214] Asked 
> to shut down framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 by 
> master@172.30.2.102:40940
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957890  1830 slave.cpp:2239] 
> Shutting down framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.957936  1830 slave.cpp:4333] 
> Shutting down executor '0' of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 at executor(1)@172.30.2.102:37168
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.958137  1833 master.cpp:1083] 
> Master terminating
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.958210  1835 hierarchical.cpp:326] 
> Removed framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.958403  3865 exec.cpp:399] 
> Executor asked to shutdown
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.958534  3865 exec.cpp:414] 
> Executor::shutdown took 17709ns
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.958570  3865 exec.cpp:91] 
> Scheduling shutdown of the executor in 5secs
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.958643  1835 hierarchical.cpp:505] 
> Removed slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.958860  1835 slave.cpp:3663] 
> master@172.30.2.102:40940 exited
> [12:21:06]W:   [Step 11/11] W0324 12:21:06.958878  1835 slave.cpp:3666] 
> Master disconnected! Waiting for a new master to be elected
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.959537  1831 
> status_update_manager.cpp:528] Cleaning up status update stream for task 0 of 
> framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.959825  1830 slave.cpp:2547] 
> Status update manager successfully handled status update acknowledgement 
> (UUID: eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.959870  1830 slave.cpp:5853] 
> Completing task 0
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.962960  1833 
> containerizer.cpp:1421] Destroying container 
> '379d8df6-a66d-4b37-990b-8295d2f9fe51'
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.965121  1829 cgroups.cpp:2427] 
> Freezing cgroup 
> /sys/fs/cgroup/freezer/mesos/379d8df6-a66d-4b37-990b-8295d2f9fe51
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.967097  1830 cgroups.cpp:1409] 
> Successfully froze cgroup 
> /sys/fs/cgroup/freezer/mesos/379d8df6-a66d-4b37-990b-8295d2f9fe51 after 
> 1.923072ms
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.969279  1828 cgroups.cpp:2445] 
> Thawing cgroup 
> /sys/fs/cgroup/freezer/mesos/379d8df6-a66d-4b37-990b-8295d2f9fe51
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.971179  1828 cgroups.cpp:1438] 
> Successfullly thawed cgroup 
> /sys/fs/cgroup/freezer/mesos/379d8df6-a66d-4b37-990b-8295d2f9fe51 after 
> 1.859072ms
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.972476  1831 slave.cpp:3663] 
> executor(1)@172.30.2.102:37168 exited
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.989403  1829 
> containerizer.cpp:1656] Executor for container 
> '379d8df6-a66d-4b37-990b-8295d2f9fe51' has exited
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.991936  1834 provisioner.cpp:306] 
> Ignoring destroy request for unknown container 
> 379d8df6-a66d-4b37-990b-8295d2f9fe51
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.992169  1830 slave.cpp:4021] 
> Executor '0' of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 
> terminated with signal Killed
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.992208  1830 slave.cpp:4125] 
> Cleaning up executor '0' of framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000 at executor(1)@172.30.2.102:37168
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.992606  1835 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
>  for gc 6.99998851291556days in the future
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.992734  1835 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0'
>  for gc 6.99998851076444days in the future
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.992883  1835 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
>  for gc 6.99998850980148days in the future
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.992899  1830 slave.cpp:4213] 
> Cleaning up framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.992959  1835 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0'
>  for gc 6.99998850917926days in the future
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.992996  1833 
> status_update_manager.cpp:282] Closing status update streams for framework 
> bc02c3e1-1349-4721-827f-b111f17ad00d-0000
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.993069  1835 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000'
>  for gc 6.9999885072563days in the future
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.993089  1830 slave.cpp:799] Slave 
> terminating
> [12:21:06]W:   [Step 11/11] I0324 12:21:06.993139  1835 gc.cpp:55] Scheduling 
> '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000'
>  for gc 6.99998850644741days in the future
> [12:21:06] :   [Step 11/11] [       OK ] FetcherCacheTest.LocalUncached (2438 
> ms)
> {code}



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)