You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "haosdent (JIRA)" <ji...@apache.org> on 2016/05/02 14:39:12 UTC
[jira] [Commented] (MESOS-5025) FetcherCacheTest.LocalUncached is
flaky
[ https://issues.apache.org/jira/browse/MESOS-5025?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15266519#comment-15266519 ]
haosdent commented on MESOS-5025:
---------------------------------
According to the log, the problem for error cases is {{StatusUpdateStream}} spent too much time on write status. This make {{TASK_RUNNING}} and {{TASK_FINISHED}} didn't forward to slave->master->framework in time. So the test case could not pass.
> 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)