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