You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Anand Mazumdar (JIRA)" <ji...@apache.org> on 2016/03/24 19:53:25 UTC
[jira] [Commented] (MESOS-4692)
FetcherCacheHttpTest.HttpCachedSerialized flaky again.
[ https://issues.apache.org/jira/browse/MESOS-4692?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15210760#comment-15210760 ]
Anand Mazumdar commented on MESOS-4692:
---------------------------------------
Logs from our internal CI where it failed again on {{HEAD}}
{code}
[00:59:41] : [Step 10/10] [ RUN ] FetcherCacheHttpTest.HttpCachedSerialized
[00:59:41]W: [Step 10/10] I0324 00:59:41.172647 28491 cluster.cpp:139] Creating default 'local' authorizer
[00:59:42]W: [Step 10/10] I0324 00:59:42.723875 28491 leveldb.cpp:174] Opened db in 1.551024097secs
[00:59:43]W: [Step 10/10] I0324 00:59:43.765609 28491 leveldb.cpp:181] Compacted db in 1.041697066secs
[00:59:43]W: [Step 10/10] I0324 00:59:43.765652 28491 leveldb.cpp:196] Created db iterator in 17477ns
[00:59:43]W: [Step 10/10] I0324 00:59:43.765663 28491 leveldb.cpp:202] Seeked to beginning of db in 1791ns
[00:59:43]W: [Step 10/10] I0324 00:59:43.765671 28491 leveldb.cpp:271] Iterated through 0 keys in the db in 317ns
[00:59:43]W: [Step 10/10] I0324 00:59:43.765704 28491 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[00:59:43]W: [Step 10/10] I0324 00:59:43.766197 28508 recover.cpp:447] Starting replica recovery
[00:59:43]W: [Step 10/10] I0324 00:59:43.766402 28508 recover.cpp:473] Replica is in EMPTY status
[00:59:43]W: [Step 10/10] I0324 00:59:43.767355 28513 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (2369)@172.30.2.14:52746
[00:59:43]W: [Step 10/10] I0324 00:59:43.767721 28509 recover.cpp:193] Received a recover response from a replica in EMPTY status
[00:59:43]W: [Step 10/10] I0324 00:59:43.768079 28508 recover.cpp:564] Updating replica status to STARTING
[00:59:43]W: [Step 10/10] I0324 00:59:43.769402 28508 master.cpp:376] Master bcf64276-69f3-422e-82e7-6668fa62f035 (ip-172-30-2-14.mesosphere.io) started on 172.30.2.14:52746
[00:59:43]W: [Step 10/10] I0324 00:59:43.769415 28508 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/Zq1knT/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/Zq1knT/master" --zk_session_timeout="10secs"
[00:59:43]W: [Step 10/10] I0324 00:59:43.769659 28508 master.cpp:423] Master only allowing authenticated frameworks to register
[00:59:43]W: [Step 10/10] I0324 00:59:43.769667 28508 master.cpp:428] Master only allowing authenticated slaves to register
[00:59:43]W: [Step 10/10] I0324 00:59:43.769673 28508 credentials.hpp:35] Loading credentials for authentication from '/tmp/Zq1knT/credentials'
[00:59:43]W: [Step 10/10] I0324 00:59:43.848915 28508 master.cpp:468] Using default 'crammd5' authenticator
[00:59:43]W: [Step 10/10] I0324 00:59:43.849046 28508 master.cpp:537] Using default 'basic' HTTP authenticator
[00:59:43]W: [Step 10/10] I0324 00:59:43.849190 28508 master.cpp:571] Authorization enabled
[00:59:43]W: [Step 10/10] I0324 00:59:43.849334 28511 hierarchical.cpp:144] Initialized hierarchical allocator process
[00:59:43]W: [Step 10/10] I0324 00:59:43.849359 28509 whitelist_watcher.cpp:77] No whitelist given
[00:59:43]W: [Step 10/10] I0324 00:59:43.850589 28506 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 82.315291ms
[00:59:43]W: [Step 10/10] I0324 00:59:43.850612 28506 replica.cpp:320] Persisted replica status to STARTING
[00:59:43]W: [Step 10/10] I0324 00:59:43.851043 28513 recover.cpp:473] Replica is in STARTING status
[00:59:43]W: [Step 10/10] I0324 00:59:43.851492 28507 master.cpp:1806] The newly elected leader is master@172.30.2.14:52746 with id bcf64276-69f3-422e-82e7-6668fa62f035
[00:59:43]W: [Step 10/10] I0324 00:59:43.851529 28507 master.cpp:1819] Elected as the leading master!
[00:59:43]W: [Step 10/10] I0324 00:59:43.851542 28507 master.cpp:1508] Recovering from registrar
[00:59:43]W: [Step 10/10] I0324 00:59:43.851685 28510 registrar.cpp:307] Recovering registrar
[00:59:43]W: [Step 10/10] I0324 00:59:43.852289 28512 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (2371)@172.30.2.14:52746
[00:59:43]W: [Step 10/10] I0324 00:59:43.852752 28510 recover.cpp:193] Received a recover response from a replica in STARTING status
[00:59:45]W: [Step 10/10] I0324 00:59:43.853072 28508 recover.cpp:564] Updating replica status to VOTING
[00:59:45]W: [Step 10/10] I0324 00:59:44.850253 28509 hierarchical.cpp:1466] No resources available to allocate!
[00:59:45]W: [Step 10/10] I0324 00:59:44.850312 28509 hierarchical.cpp:1138] Performed allocation for 0 slaves in 124236ns
[00:59:45]W: [Step 10/10] I0324 00:59:45.821077 28506 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.96782583secs
[00:59:45]W: [Step 10/10] I0324 00:59:45.821105 28506 replica.cpp:320] Persisted replica status to VOTING
[00:59:45]W: [Step 10/10] I0324 00:59:45.821211 28507 recover.cpp:578] Successfully joined the Paxos group
[00:59:45]W: [Step 10/10] I0324 00:59:45.821372 28507 recover.cpp:462] Recover process terminated
[00:59:45]W: [Step 10/10] I0324 00:59:45.821817 28511 log.cpp:659] Attempting to start the writer
[00:59:45]W: [Step 10/10] I0324 00:59:45.822851 28512 replica.cpp:493] Replica received implicit promise request from (2372)@172.30.2.14:52746 with proposal 1
[00:59:45]W: [Step 10/10] I0324 00:59:45.850558 28507 hierarchical.cpp:1466] No resources available to allocate!
[00:59:46]W: [Step 10/10] I0324 00:59:45.850605 28507 hierarchical.cpp:1138] Performed allocation for 0 slaves in 88507ns
[00:59:46]W: [Step 10/10] I0324 00:59:46.851111 28510 hierarchical.cpp:1466] No resources available to allocate!
[00:59:46]W: [Step 10/10] I0324 00:59:46.851156 28510 hierarchical.cpp:1138] Performed allocation for 0 slaves in 84297ns
[00:59:47]W: [Step 10/10] I0324 00:59:47.042377 28512 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.219494327secs
[00:59:47]W: [Step 10/10] I0324 00:59:47.042400 28512 replica.cpp:342] Persisted promised to 1
[00:59:47]W: [Step 10/10] I0324 00:59:47.042959 28509 coordinator.cpp:238] Coordinator attempting to fill missing positions
[00:59:47]W: [Step 10/10] I0324 00:59:47.044039 28511 replica.cpp:388] Replica received explicit promise request from (2373)@172.30.2.14:52746 for position 0 with proposal 2
[00:59:47]W: [Step 10/10] I0324 00:59:47.851681 28508 hierarchical.cpp:1466] No resources available to allocate!
[00:59:48]W: [Step 10/10] I0324 00:59:47.851729 28508 hierarchical.cpp:1138] Performed allocation for 0 slaves in 92211ns
[00:59:48]W: [Step 10/10] I0324 00:59:48.482892 28511 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.438818209secs
[00:59:48]W: [Step 10/10] I0324 00:59:48.482918 28511 replica.cpp:712] Persisted action at 0
[00:59:48]W: [Step 10/10] I0324 00:59:48.483803 28507 replica.cpp:537] Replica received write request for position 0 from (2374)@172.30.2.14:52746
[00:59:48]W: [Step 10/10] I0324 00:59:48.483861 28507 leveldb.cpp:436] Reading position from leveldb took 30030ns
[00:59:48]W: [Step 10/10] I0324 00:59:48.852224 28511 hierarchical.cpp:1466] No resources available to allocate!
[00:59:49]W: [Step 10/10] I0324 00:59:48.852268 28511 hierarchical.cpp:1138] Performed allocation for 0 slaves in 77441ns
[00:59:49]W: [Step 10/10] I0324 00:59:49.802103 28507 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.318206348secs
[00:59:49]W: [Step 10/10] I0324 00:59:49.802126 28507 replica.cpp:712] Persisted action at 0
[00:59:49]W: [Step 10/10] I0324 00:59:49.802733 28507 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
[00:59:49]W: [Step 10/10] I0324 00:59:49.852725 28509 hierarchical.cpp:1466] No resources available to allocate!
[00:59:50]W: [Step 10/10] I0324 00:59:49.852782 28509 hierarchical.cpp:1138] Performed allocation for 0 slaves in 93185ns
[00:59:50]W: [Step 10/10] I0324 00:59:50.771888 28507 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 969.125283ms
[00:59:50]W: [Step 10/10] I0324 00:59:50.771913 28507 replica.cpp:712] Persisted action at 0
[00:59:50]W: [Step 10/10] I0324 00:59:50.771927 28507 replica.cpp:697] Replica learned NOP action at position 0
[00:59:50]W: [Step 10/10] I0324 00:59:50.772404 28507 log.cpp:675] Writer started with ending position 0
[00:59:50]W: [Step 10/10] I0324 00:59:50.773452 28508 leveldb.cpp:436] Reading position from leveldb took 23493ns
[00:59:50]W: [Step 10/10] I0324 00:59:50.774327 28509 registrar.cpp:340] Successfully fetched the registry (0B) in 6.922596864secs
[00:59:50]W: [Step 10/10] I0324 00:59:50.774425 28509 registrar.cpp:439] Applied 1 operations in 25315ns; attempting to update the 'registry'
[00:59:50]W: [Step 10/10] I0324 00:59:50.775090 28511 log.cpp:683] Attempting to append 205 bytes to the log
[00:59:50]W: [Step 10/10] I0324 00:59:50.775188 28507 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
[00:59:50]W: [Step 10/10] I0324 00:59:50.775815 28511 replica.cpp:537] Replica received write request for position 1 from (2375)@172.30.2.14:52746
[00:59:50]W: [Step 10/10] I0324 00:59:50.853250 28506 hierarchical.cpp:1466] No resources available to allocate!
[00:59:52]W: [Step 10/10] I0324 00:59:50.853307 28506 hierarchical.cpp:1138] Performed allocation for 0 slaves in 90895ns
[00:59:52]W: [Step 10/10] I0324 00:59:51.853754 28512 hierarchical.cpp:1466] No resources available to allocate!
[00:59:52]W: [Step 10/10] I0324 00:59:51.853796 28512 hierarchical.cpp:1138] Performed allocation for 0 slaves in 77921ns
[00:59:52]W: [Step 10/10] I0324 00:59:52.730476 28511 leveldb.cpp:341] Persisting action (224 bytes) to leveldb took 1.954631172secs
[00:59:52]W: [Step 10/10] I0324 00:59:52.730500 28511 replica.cpp:712] Persisted action at 1
[00:59:52]W: [Step 10/10] I0324 00:59:52.731000 28507 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
[00:59:53]W: [Step 10/10] I0324 00:59:52.854171 28511 hierarchical.cpp:1466] No resources available to allocate!
[00:59:53]W: [Step 10/10] I0324 00:59:52.854214 28511 hierarchical.cpp:1138] Performed allocation for 0 slaves in 83775ns
[00:59:53]W: [Step 10/10] I0324 00:59:53.620599 28507 leveldb.cpp:341] Persisting action (226 bytes) to leveldb took 889.568145ms
[00:59:53]W: [Step 10/10] I0324 00:59:53.620623 28507 replica.cpp:712] Persisted action at 1
[00:59:53]W: [Step 10/10] I0324 00:59:53.620638 28507 replica.cpp:697] Replica learned APPEND action at position 1
[00:59:53]W: [Step 10/10] I0324 00:59:53.621457 28513 registrar.cpp:484] Successfully updated the 'registry' in 2.846979072secs
[00:59:53]W: [Step 10/10] I0324 00:59:53.621580 28513 registrar.cpp:370] Successfully recovered registrar
[00:59:53]W: [Step 10/10] I0324 00:59:53.621728 28506 log.cpp:702] Attempting to truncate the log to 1
[00:59:53]W: [Step 10/10] I0324 00:59:53.621871 28508 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
[00:59:53]W: [Step 10/10] I0324 00:59:53.622050 28511 master.cpp:1616] Recovered 0 slaves from the Registry (166B) ; allowing 10mins for slaves to re-register
[00:59:53]W: [Step 10/10] I0324 00:59:53.622082 28506 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
[00:59:53]W: [Step 10/10] I0324 00:59:53.622568 28508 replica.cpp:537] Replica received write request for position 2 from (2376)@172.30.2.14:52746
[00:59:54]W: [Step 10/10] I0324 00:59:54.645128 28508 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.022529901secs
[00:59:54]W: [Step 10/10] I0324 00:59:54.645151 28508 replica.cpp:712] Persisted action at 2
[00:59:54]W: [Step 10/10] I0324 00:59:54.645740 28509 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
[00:59:57]W: [Step 10/10] I0324 00:59:57.203039 28509 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 2.55726377secs
[00:59:57]W: [Step 10/10] I0324 00:59:57.203109 28509 leveldb.cpp:399] Deleting ~1 keys from leveldb took 35544ns
[00:59:57]W: [Step 10/10] I0324 00:59:57.203125 28509 replica.cpp:712] Persisted action at 2
[00:59:57]W: [Step 10/10] I0324 00:59:57.203145 28509 replica.cpp:697] Replica learned TRUNCATE action at position 2
[00:59:57]W: [Step 10/10] I0324 00:59:57.203994 28511 hierarchical.cpp:1466] No resources available to allocate!
[00:59:57]W: [Step 10/10] I0324 00:59:57.204059 28511 hierarchical.cpp:1138] Performed allocation for 0 slaves in 151936ns
[00:59:57]W: [Step 10/10] I0324 00:59:57.204982 28491 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
[00:59:57]W: [Step 10/10] I0324 00:59:57.209539 28491 linux_launcher.cpp:101] Using /cgroup/freezer as the freezer hierarchy for the Linux launcher
[00:59:57]W: [Step 10/10] I0324 00:59:57.213275 28506 slave.cpp:193] Slave started on 55)@172.30.2.14:52746
[00:59:57]W: [Step 10/10] I0324 00:59:57.213292 28506 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/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/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --hostname_lookup="true" --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/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb"
[00:59:57]W: [Step 10/10] I0324 00:59:57.213629 28506 credentials.hpp:83] Loading credential for authentication from '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/credential'
[00:59:57]W: [Step 10/10] I0324 00:59:57.213795 28506 slave.cpp:324] Slave using credential for: test-principal
[00:59:57]W: [Step 10/10] I0324 00:59:57.213955 28506 resources.cpp:572] Parsing resources as JSON failed: cpus:1000;mem:1000
[00:59:57]W: [Step 10/10] Trying semicolon-delimited string format instead
[00:59:57]W: [Step 10/10] I0324 00:59:57.214303 28506 slave.cpp:464] Slave resources: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000]
[00:59:57]W: [Step 10/10] I0324 00:59:57.214352 28506 slave.cpp:472] Slave attributes: [ ]
[00:59:57]W: [Step 10/10] I0324 00:59:57.214361 28506 slave.cpp:477] Slave hostname: ip-172-30-2-14.mesosphere.io
[00:59:57]W: [Step 10/10] I0324 00:59:57.215276 28509 state.cpp:58] Recovering state from '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta'
[00:59:57]W: [Step 10/10] I0324 00:59:57.215497 28508 status_update_manager.cpp:200] Recovering status update manager
[00:59:57]W: [Step 10/10] I0324 00:59:57.215682 28506 containerizer.cpp:407] Recovering containerizer
[00:59:57]W: [Step 10/10] I0324 00:59:57.217344 28512 provisioner.cpp:245] Provisioner recovery complete
[00:59:57]W: [Step 10/10] I0324 00:59:57.217679 28511 slave.cpp:4565] Finished recovery
[00:59:57]W: [Step 10/10] I0324 00:59:57.658592 28511 slave.cpp:4737] Querying resource estimator for oversubscribable resources
[00:59:57]W: [Step 10/10] I0324 00:59:57.658800 28508 status_update_manager.cpp:174] Pausing sending status updates
[00:59:57]W: [Step 10/10] I0324 00:59:57.658876 28513 slave.cpp:796] New master detected at master@172.30.2.14:52746
[00:59:57]W: [Step 10/10] I0324 00:59:57.658939 28513 slave.cpp:859] Authenticating with master master@172.30.2.14:52746
[00:59:57]W: [Step 10/10] I0324 00:59:57.658953 28513 slave.cpp:864] Using default CRAM-MD5 authenticatee
[00:59:57]W: [Step 10/10] I0324 00:59:57.659076 28513 slave.cpp:832] Detecting new master
[00:59:57]W: [Step 10/10] I0324 00:59:57.659127 28506 authenticatee.cpp:121] Creating new client SASL connection
[00:59:57]W: [Step 10/10] I0324 00:59:57.659219 28513 slave.cpp:4751] Received oversubscribable resources from the resource estimator
[00:59:57]W: [Step 10/10] I0324 00:59:57.659340 28508 master.cpp:5659] Authenticating slave(55)@172.30.2.14:52746
[00:59:57]W: [Step 10/10] I0324 00:59:57.659430 28511 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(155)@172.30.2.14:52746
[00:59:57]W: [Step 10/10] I0324 00:59:57.659632 28510 authenticator.cpp:98] Creating new server SASL connection
[00:59:57]W: [Step 10/10] I0324 00:59:57.659775 28509 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[00:59:57]W: [Step 10/10] I0324 00:59:57.659793 28509 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[00:59:57]W: [Step 10/10] I0324 00:59:57.659876 28509 authenticator.cpp:203] Received SASL authentication start
[00:59:57]W: [Step 10/10] I0324 00:59:57.659926 28509 authenticator.cpp:325] Authentication requires more steps
[00:59:57]W: [Step 10/10] I0324 00:59:57.660003 28509 authenticatee.cpp:258] Received SASL authentication step
[00:59:57]W: [Step 10/10] I0324 00:59:57.660106 28513 authenticator.cpp:231] Received SASL authentication step
[00:59:57]W: [Step 10/10] I0324 00:59:57.660128 28513 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-14' server FQDN: 'ip-172-30-2-14' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
[00:59:57]W: [Step 10/10] I0324 00:59:57.660136 28513 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[00:59:57]W: [Step 10/10] I0324 00:59:57.660169 28513 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[00:59:57]W: [Step 10/10] I0324 00:59:57.660188 28513 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-14' server FQDN: 'ip-172-30-2-14' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
[00:59:57]W: [Step 10/10] I0324 00:59:57.660195 28513 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[00:59:57]W: [Step 10/10] I0324 00:59:57.660200 28513 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[00:59:57]W: [Step 10/10] I0324 00:59:57.660212 28513 authenticator.cpp:317] Authentication success
[00:59:57]W: [Step 10/10] I0324 00:59:57.660281 28510 authenticatee.cpp:298] Authentication success
[00:59:57]W: [Step 10/10] I0324 00:59:57.660332 28507 master.cpp:5689] Successfully authenticated principal 'test-principal' at slave(55)@172.30.2.14:52746
[00:59:57]W: [Step 10/10] I0324 00:59:57.660418 28511 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(155)@172.30.2.14:52746
[00:59:57]W: [Step 10/10] I0324 00:59:57.660615 28509 slave.cpp:927] Successfully authenticated with master master@172.30.2.14:52746
[00:59:57]W: [Step 10/10] I0324 00:59:57.660720 28509 slave.cpp:1321] Will retry registration in 9.321676ms if necessary
[00:59:57]W: [Step 10/10] I0324 00:59:57.660876 28507 master.cpp:4370] Registering slave at slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) with id bcf64276-69f3-422e-82e7-6668fa62f035-S0
[00:59:57]W: [Step 10/10] I0324 00:59:57.661226 28506 registrar.cpp:439] Applied 1 operations in 53172ns; attempting to update the 'registry'
[00:59:57]W: [Step 10/10] I0324 00:59:57.661852 28506 log.cpp:683] Attempting to append 390 bytes to the log
[00:59:57]W: [Step 10/10] I0324 00:59:57.661967 28507 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
[00:59:57]W: [Step 10/10] I0324 00:59:57.662626 28513 replica.cpp:537] Replica received write request for position 3 from (2393)@172.30.2.14:52746
[00:59:57]W: [Step 10/10] I0324 00:59:57.671103 28508 slave.cpp:1321] Will retry registration in 15.503096ms if necessary
[00:59:58]W: [Step 10/10] I0324 00:59:57.671180 28512 master.cpp:4358] Ignoring register slave message from slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) as admission is already in progress
[00:59:58]W: [Step 10/10] I0324 00:59:57.687448 28506 slave.cpp:1321] Will retry registration in 43.057504ms if necessary
[00:59:58]W: [Step 10/10] I0324 00:59:57.687536 28507 master.cpp:4358] Ignoring register slave message from slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) as admission is already in progress
[00:59:58]W: [Step 10/10] I0324 00:59:57.730849 28509 slave.cpp:1321] Will retry registration in 136.727485ms if necessary
[00:59:58]W: [Step 10/10] I0324 00:59:57.730963 28506 master.cpp:4358] Ignoring register slave message from slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) as admission is already in progress
[00:59:58]W: [Step 10/10] I0324 00:59:57.868247 28510 slave.cpp:1321] Will retry registration in 48.668898ms if necessary
[00:59:58]W: [Step 10/10] I0324 00:59:57.868345 28511 master.cpp:4358] Ignoring register slave message from slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) as admission is already in progress
[00:59:58]W: [Step 10/10] I0324 00:59:57.917629 28512 slave.cpp:1321] Will retry registration in 308.232579ms if necessary
[00:59:58]W: [Step 10/10] I0324 00:59:57.917723 28510 master.cpp:4358] Ignoring register slave message from slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) as admission is already in progress
[00:59:58]W: [Step 10/10] I0324 00:59:58.204352 28507 hierarchical.cpp:1466] No resources available to allocate!
[00:59:58]W: [Step 10/10] I0324 00:59:58.204401 28507 hierarchical.cpp:1138] Performed allocation for 0 slaves in 90260ns
[00:59:58]W: [Step 10/10] I0324 00:59:58.226783 28509 slave.cpp:1321] Will retry registration in 121.328122ms if necessary
[00:59:58]W: [Step 10/10] I0324 00:59:58.226869 28510 master.cpp:4358] Ignoring register slave message from slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) as admission is already in progress
[00:59:58]W: [Step 10/10] I0324 00:59:58.349169 28511 slave.cpp:1321] Will retry registration in 2.001168504secs if necessary
[00:59:58]W: [Step 10/10] I0324 00:59:58.349266 28506 master.cpp:4358] Ignoring register slave message from slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) as admission is already in progress
[00:59:58]W: [Step 10/10] I0324 00:59:58.582892 28513 leveldb.cpp:341] Persisting action (409 bytes) to leveldb took 920.231549ms
[00:59:58]W: [Step 10/10] I0324 00:59:58.582916 28513 replica.cpp:712] Persisted action at 3
[00:59:58]W: [Step 10/10] I0324 00:59:58.583498 28507 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
[00:59:59]W: [Step 10/10] I0324 00:59:59.204789 28512 hierarchical.cpp:1466] No resources available to allocate!
[00:59:59]W: [Step 10/10] I0324 00:59:59.204849 28512 hierarchical.cpp:1138] Performed allocation for 0 slaves in 95603ns
[00:59:59]W: [Step 10/10] I0324 00:59:59.465575 28507 leveldb.cpp:341] Persisting action (411 bytes) to leveldb took 882.046761ms
[00:59:59]W: [Step 10/10] I0324 00:59:59.465605 28507 replica.cpp:712] Persisted action at 3
[00:59:59]W: [Step 10/10] I0324 00:59:59.465623 28507 replica.cpp:697] Replica learned APPEND action at position 3
[00:59:59]W: [Step 10/10] I0324 00:59:59.466985 28511 registrar.cpp:484] Successfully updated the 'registry' in 1.805703936secs
[00:59:59]W: [Step 10/10] I0324 00:59:59.467241 28506 log.cpp:702] Attempting to truncate the log to 3
[00:59:59]W: [Step 10/10] I0324 00:59:59.467341 28511 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
[00:59:59]W: [Step 10/10] I0324 00:59:59.467803 28512 slave.cpp:3482] Received ping from slave-observer(54)@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.467957 28507 master.cpp:4438] Registered slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 at slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000]
[00:59:59]W: [Step 10/10] I0324 00:59:59.468112 28513 slave.cpp:971] Registered with master master@172.30.2.14:52746; given slave ID bcf64276-69f3-422e-82e7-6668fa62f035-S0
[00:59:59]W: [Step 10/10] I0324 00:59:59.468132 28513 fetcher.cpp:81] Clearing fetcher cache
[00:59:59]W: [Step 10/10] I0324 00:59:59.468137 28510 hierarchical.cpp:473] Added slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 (ip-172-30-2-14.mesosphere.io) with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] (allocated: )
[00:59:59]W: [Step 10/10] I0324 00:59:59.468242 28511 replica.cpp:537] Replica received write request for position 4 from (2394)@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.468287 28510 hierarchical.cpp:1466] No resources available to allocate!
[00:59:59]W: [Step 10/10] I0324 00:59:59.468292 28512 status_update_manager.cpp:181] Resuming sending status updates
[00:59:59]W: [Step 10/10] I0324 00:59:59.468350 28510 hierarchical.cpp:1161] Performed allocation for slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 in 173625ns
[00:59:59]W: [Step 10/10] I0324 00:59:59.468477 28513 slave.cpp:994] Checkpointing SlaveInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/slave.info'
[00:59:59]W: [Step 10/10] I0324 00:59:59.469385 28491 sched.cpp:222] Version: 0.29.0
[00:59:59]W: [Step 10/10] I0324 00:59:59.469913 28510 sched.cpp:326] New master detected at master@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.470055 28510 sched.cpp:382] Authenticating with master master@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.470077 28510 sched.cpp:389] Using default CRAM-MD5 authenticatee
[00:59:59]W: [Step 10/10] I0324 00:59:59.470295 28512 authenticatee.cpp:121] Creating new client SASL connection
[00:59:59]W: [Step 10/10] I0324 00:59:59.470476 28510 master.cpp:5659] Authenticating scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.470580 28507 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(156)@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.470769 28512 authenticator.cpp:98] Creating new server SASL connection
[00:59:59]W: [Step 10/10] I0324 00:59:59.470882 28506 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[00:59:59]W: [Step 10/10] I0324 00:59:59.470901 28506 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[00:59:59]W: [Step 10/10] I0324 00:59:59.470970 28506 authenticator.cpp:203] Received SASL authentication start
[00:59:59]W: [Step 10/10] I0324 00:59:59.471012 28506 authenticator.cpp:325] Authentication requires more steps
[00:59:59]W: [Step 10/10] I0324 00:59:59.471078 28506 authenticatee.cpp:258] Received SASL authentication step
[00:59:59]W: [Step 10/10] I0324 00:59:59.471153 28506 authenticator.cpp:231] Received SASL authentication step
[00:59:59]W: [Step 10/10] I0324 00:59:59.471187 28506 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-14' server FQDN: 'ip-172-30-2-14' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
[00:59:59]W: [Step 10/10] I0324 00:59:59.471195 28506 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
[00:59:59]W: [Step 10/10] I0324 00:59:59.471228 28506 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[00:59:59]W: [Step 10/10] I0324 00:59:59.471247 28506 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-14' server FQDN: 'ip-172-30-2-14' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
[00:59:59]W: [Step 10/10] I0324 00:59:59.471254 28506 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[00:59:59]W: [Step 10/10] I0324 00:59:59.471259 28506 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
[00:59:59]W: [Step 10/10] I0324 00:59:59.471271 28506 authenticator.cpp:317] Authentication success
[00:59:59]W: [Step 10/10] I0324 00:59:59.471349 28509 authenticatee.cpp:298] Authentication success
[00:59:59]W: [Step 10/10] I0324 00:59:59.471388 28512 master.cpp:5689] Successfully authenticated principal 'test-principal' at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.471422 28508 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(156)@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.471621 28510 sched.cpp:471] Successfully authenticated with master master@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.471637 28510 sched.cpp:776] Sending SUBSCRIBE call to master@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.471756 28510 sched.cpp:809] Will retry registration in 791.766062ms if necessary
[00:59:59]W: [Step 10/10] I0324 00:59:59.471845 28507 master.cpp:2326] Received SUBSCRIBE call for framework 'default' at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[00:59:59]W: [Step 10/10] W0324 00:59:59.471868 28507 master.cpp:2333] Framework at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746 (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
[00:59:59]W: [Step 10/10] I0324 00:59:59.471905 28507 master.cpp:1845] Authorizing framework principal '' to receive offers for role '*'
[00:59:59]W: [Step 10/10] I0324 00:59:59.472100 28512 master.cpp:2397] Subscribing framework default with checkpointing enabled and capabilities [ ]
[00:59:59]W: [Step 10/10] I0324 00:59:59.472461 28506 hierarchical.cpp:265] Added framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[00:59:59]W: [Step 10/10] I0324 00:59:59.472596 28512 sched.cpp:703] Framework registered with bcf64276-69f3-422e-82e7-6668fa62f035-0000
[00:59:59]W: [Step 10/10] I0324 00:59:59.472630 28512 sched.cpp:717] Scheduler::registered took 16144ns
[00:59:59]W: [Step 10/10] I0324 00:59:59.473068 28506 hierarchical.cpp:1561] No inverse offers to send out!
[00:59:59]W: [Step 10/10] I0324 00:59:59.473129 28506 hierarchical.cpp:1138] Performed allocation for 1 slaves in 644063ns
[00:59:59]W: [Step 10/10] I0324 00:59:59.473328 28508 master.cpp:5488] Sending 1 offers to framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.473758 28508 sched.cpp:873] Scheduler::resourceOffers took 94996ns
[00:59:59]W: [Step 10/10] I0324 00:59:59.474115 28491 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:1
[00:59:59]W: [Step 10/10] Trying semicolon-delimited string format instead
[00:59:59]W: [Step 10/10] I0324 00:59:59.475178 28507 master.cpp:3268] Processing ACCEPT call for offers: [ bcf64276-69f3-422e-82e7-6668fa62f035-O0 ] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 at slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[00:59:59]W: [Step 10/10] I0324 00:59:59.475214 28507 master.cpp:2871] Authorizing framework principal '' to launch task 0 as user 'root'
[00:59:59]W: [Step 10/10] I0324 00:59:59.476213 28507 master.hpp:177] Adding task 0 with resources cpus(*):1; mem(*):1 on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 (ip-172-30-2-14.mesosphere.io)
[00:59:59]W: [Step 10/10] I0324 00:59:59.476292 28507 master.cpp:3753] Launching task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746 with resources cpus(*):1; mem(*):1 on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 at slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io)
[00:59:59]W: [Step 10/10] I0324 00:59:59.476793 28510 hierarchical.cpp:890] Recovered cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 from framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[00:59:59]W: [Step 10/10] I0324 00:59:59.476833 28510 hierarchical.cpp:927] Framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 filtered slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for 5secs
[01:00:00]W: [Step 10/10] I0324 01:00:00.205763 28512 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:06]W: [Step 10/10] I0324 01:00:00.205803 28512 hierarchical.cpp:1466] No resources available to allocate!
[01:00:06]W: [Step 10/10] I0324 01:00:00.205832 28512 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:06]W: [Step 10/10] I0324 01:00:00.205878 28512 hierarchical.cpp:1138] Performed allocation for 1 slaves in 515828ns
[01:00:06]W: [Step 10/10] I0324 01:00:01.207253 28510 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:06]W: [Step 10/10] I0324 01:00:01.207319 28510 hierarchical.cpp:1466] No resources available to allocate!
[01:00:06]W: [Step 10/10] I0324 01:00:01.207356 28510 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:06]W: [Step 10/10] I0324 01:00:01.207422 28510 hierarchical.cpp:1138] Performed allocation for 1 slaves in 700505ns
[01:00:06]W: [Step 10/10] I0324 01:00:02.208920 28507 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:06]W: [Step 10/10] I0324 01:00:02.208984 28507 hierarchical.cpp:1466] No resources available to allocate!
[01:00:06]W: [Step 10/10] I0324 01:00:02.209020 28507 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:06]W: [Step 10/10] I0324 01:00:02.209086 28507 hierarchical.cpp:1138] Performed allocation for 1 slaves in 709277ns
[01:00:06]W: [Step 10/10] I0324 01:00:03.210207 28508 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:06]W: [Step 10/10] I0324 01:00:03.210264 28508 hierarchical.cpp:1466] No resources available to allocate!
[01:00:06]W: [Step 10/10] I0324 01:00:03.210299 28508 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:06]W: [Step 10/10] I0324 01:00:03.210358 28508 hierarchical.cpp:1138] Performed allocation for 1 slaves in 644240ns
[01:00:06]W: [Step 10/10] I0324 01:00:04.211604 28507 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:06]W: [Step 10/10] I0324 01:00:04.211650 28507 hierarchical.cpp:1466] No resources available to allocate!
[01:00:06]W: [Step 10/10] I0324 01:00:04.211681 28507 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:06]W: [Step 10/10] I0324 01:00:04.211735 28507 hierarchical.cpp:1138] Performed allocation for 1 slaves in 654353ns
[01:00:06]W: [Step 10/10] I0324 01:00:05.213141 28512 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:06]W: [Step 10/10] I0324 01:00:05.213210 28512 hierarchical.cpp:1138] Performed allocation for 1 slaves in 658826ns
[01:00:06]W: [Step 10/10] I0324 01:00:05.213440 28506 master.cpp:5488] Sending 1 offers to framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[01:00:06]W: [Step 10/10] I0324 01:00:05.214046 28508 sched.cpp:873] Scheduler::resourceOffers took 98262ns
[01:00:06]W: [Step 10/10] I0324 01:00:05.214334 28506 master.cpp:3805] Processing DECLINE call for offers: [ bcf64276-69f3-422e-82e7-6668fa62f035-O1 ] for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[01:00:06]W: [Step 10/10] I0324 01:00:05.214777 28508 hierarchical.cpp:890] Recovered cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 from framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:06]W: [Step 10/10] I0324 01:00:05.214821 28508 hierarchical.cpp:927] Framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 filtered slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for 5secs
[01:00:06]W: [Step 10/10] I0324 01:00:06.206972 28513 slave.cpp:1030] Forwarding total oversubscribed resources
[01:00:06]W: [Step 10/10] I0324 01:00:06.207134 28508 master.cpp:4782] Received update of slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 at slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io) with total oversubscribed resources
[01:00:06]W: [Step 10/10] I0324 01:00:06.207247 28513 slave.cpp:1361] Got assigned task 0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:06]W: [Step 10/10] I0324 01:00:06.207382 28513 slave.cpp:5287] Checkpointing FrameworkInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/framework.info'
[01:00:06]W: [Step 10/10] I0324 01:00:06.207489 28508 hierarchical.cpp:531] Slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 (ip-172-30-2-14.mesosphere.io) updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1)
[01:00:06]W: [Step 10/10] I0324 01:00:06.207867 28508 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:06]W: [Step 10/10] I0324 01:00:06.207898 28508 hierarchical.cpp:1466] No resources available to allocate!
[01:00:06]W: [Step 10/10] I0324 01:00:06.207926 28508 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:06]W: [Step 10/10] I0324 01:00:06.207968 28508 hierarchical.cpp:1161] Performed allocation for slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 in 434953ns
[01:00:06]W: [Step 10/10] I0324 01:00:06.214123 28510 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:06]W: [Step 10/10] I0324 01:00:06.214159 28510 hierarchical.cpp:1466] No resources available to allocate!
[01:00:06]W: [Step 10/10] I0324 01:00:06.214184 28510 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:06]W: [Step 10/10] I0324 01:00:06.214227 28510 hierarchical.cpp:1138] Performed allocation for 1 slaves in 428834ns
[01:00:06]W: [Step 10/10] I0324 01:00:06.336431 28511 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 6.868152145secs
[01:00:06]W: [Step 10/10] I0324 01:00:06.336458 28511 replica.cpp:712] Persisted action at 4
[01:00:06]W: [Step 10/10] I0324 01:00:06.337090 28508 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
[01:00:07]W: [Step 10/10] I0324 01:00:07.122704 28513 slave.cpp:5298] Checkpointing framework pid 'scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/framework.pid'
[01:00:07]W: [Step 10/10] I0324 01:00:07.124084 28508 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 786.964055ms
[01:00:07]W: [Step 10/10] I0324 01:00:07.124166 28508 leveldb.cpp:399] Deleting ~2 keys from leveldb took 48991ns
[01:00:07]W: [Step 10/10] I0324 01:00:07.124183 28508 replica.cpp:712] Persisted action at 4
[01:00:07]W: [Step 10/10] I0324 01:00:07.124209 28508 replica.cpp:697] Replica learned TRUNCATE action at position 4
[01:00:07]W: [Step 10/10] I0324 01:00:07.215771 28509 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:07]W: [Step 10/10] I0324 01:00:07.215809 28509 hierarchical.cpp:1466] No resources available to allocate!
[01:00:07]W: [Step 10/10] I0324 01:00:07.215845 28509 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:07]W: [Step 10/10] I0324 01:00:07.215909 28509 hierarchical.cpp:1138] Performed allocation for 1 slaves in 726234ns
[01:00:07]W: [Step 10/10] I0324 01:00:07.472522 28513 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[01:00:07]W: [Step 10/10] Trying semicolon-delimited string format instead
[01:00:07]W: [Step 10/10] I0324 01:00:07.473099 28513 slave.cpp:1480] Launching task 0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:07]W: [Step 10/10] I0324 01:00:07.473165 28513 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
[01:00:07]W: [Step 10/10] Trying semicolon-delimited string format instead
[01:00:07]W: [Step 10/10] I0324 01:00:07.473757 28513 paths.cpp:528] Trying to chown '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88' to user 'root'
[01:00:07]W: [Step 10/10] I0324 01:00:07.477273 28513 slave.cpp:5739] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/executor.info'
[01:00:07]W: [Step 10/10] I0324 01:00:07.477699 28513 slave.cpp:5367] Launching executor 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88'
[01:00:07]W: [Step 10/10] I0324 01:00:07.478165 28507 containerizer.cpp:666] Starting container '73965e91-a0fd-4252-9ed9-3d7e7521ee88' for executor '0' of framework 'bcf64276-69f3-422e-82e7-6668fa62f035-0000'
[01:00:07]W: [Step 10/10] I0324 01:00:07.478206 28513 slave.cpp:5762] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88/tasks/0/task.info'
[01:00:07]W: [Step 10/10] I0324 01:00:07.478437 28513 slave.cpp:1698] Queuing task '0' for executor '0' of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:07]W: [Step 10/10] I0324 01:00:07.478539 28513 slave.cpp:749] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88'
[01:00:07]W: [Step 10/10] I0324 01:00:07.482379 28507 linux_launcher.cpp:304] Cloning child process with flags =
[01:00:07]W: [Step 10/10] I0324 01:00:07.483891 28507 containerizer.cpp:1147] Checkpointing executor's forked pid 31725 to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88/pids/forked.pid'
[01:00:07]W: [Step 10/10] I0324 01:00:07.816279 28506 fetcher.cpp:323] Starting to fetch URIs for container: 73965e91-a0fd-4252-9ed9-3d7e7521ee88, directory: /tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88
[01:00:07]W: [Step 10/10] I0324 01:00:07.819640 28506 fetcher.cpp:912] Created cache entry 'root@http://172.30.2.14:52746/(2378)/mesos-fetcher-test-cmd' with file: c1-mesos-fetc_r-test-cmd
[01:00:07]W: [Step 10/10] I0324 01:00:07.820302 28512 fetcher.cpp:271] Fetching size for URI: http://172.30.2.14:52746/(2378)/mesos-fetcher-test-cmd
[01:00:07]W: [Step 10/10] I0324 01:00:07.968307 28509 process.cpp:3136] Handling HTTP event for process '(2378)' with path: '/(2378)/mesos-fetcher-test-cmd'
[01:00:07]W: [Step 10/10] I0324 01:00:07.968683 28510 process.cpp:1176] Sending file at '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
[01:00:07] : [Step 10/10] HTTP/1.1 200 OK
[01:00:07]W: [Step 10/10] I0324 01:00:07.969099 28513 fetcher.cpp:687] Claiming fetcher cache space for: root@http://172.30.2.14:52746/(2378)/mesos-fetcher-test-cmd
[01:00:07] : [Step 10/10] Date: Thu, 24 Mar 2016 01:00:07 GMT
[01:00:07] : [Step 10/10] Content-Length: 30
[01:00:07]W: [Step 10/10] I0324 01:00:07.969115 28513 fetcher.cpp:1132] Claimed cache space: 30B, now using: 30B
[01:00:07] : [Step 10/10]
[01:00:07]W: [Step 10/10] I0324 01:00:07.973572 28506 fetcher.cpp:785] Fetching URIs using command '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
[01:00:08]W: [Step 10/10] I0324 01:00:08.024727 28510 process.cpp:3136] Handling HTTP event for process '(2378)' with path: '/(2378)/mesos-fetcher-test-cmd'
[01:00:08]W: [Step 10/10] I0324 01:00:08.025022 28507 process.cpp:1176] Sending file at '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
[01:00:08]W: [Step 10/10] I0324 01:00:08.043277 28513 fetcher.cpp:1144] Released cache space: 0B, now using: 30B
[01:00:08]W: [Step 10/10] WARNING: Logging before InitGoogleLogging() is written to STDERR
[01:00:08]W: [Step 10/10] I0324 01:00:08.089668 31725 process.cpp:986] libprocess is initialized on 172.30.2.14:47763 for 8 cpus
[01:00:08]W: [Step 10/10] I0324 01:00:08.090456 31725 logging.cpp:193] Logging to STDERR
[01:00:08]W: [Step 10/10] I0324 01:00:08.092907 31725 exec.cpp:150] Version: 0.29.0
[01:00:08]W: [Step 10/10] I0324 01:00:08.100939 31773 exec.cpp:200] Executor started at: executor(1)@172.30.2.14:47763 with pid 31725
[01:00:08]W: [Step 10/10] I0324 01:00:08.102859 28509 slave.cpp:2643] Got registration for executor '0' of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 from executor(1)@172.30.2.14:47763
[01:00:08]W: [Step 10/10] I0324 01:00:08.103420 28509 slave.cpp:2729] Checkpointing executor pid 'executor(1)@172.30.2.14:47763' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88/pids/libprocess.pid'
[01:00:08]W: [Step 10/10] I0324 01:00:08.104809 31776 exec.cpp:225] Executor registered on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0
[01:00:08]W: [Step 10/10] I0324 01:00:08.105002 28511 slave.cpp:1863] Sending queued task '0' to executor '0' of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 at executor(1)@172.30.2.14:47763
[01:00:08]W: [Step 10/10] I0324 01:00:08.106415 31776 exec.cpp:237] Executor::registered took 234311ns
[01:00:08]W: [Step 10/10] I0324 01:00:08.106652 31776 exec.cpp:312] Executor asked to run task '0'
[01:00:08]W: [Step 10/10] I0324 01:00:08.106736 31776 exec.cpp:321] Executor::launchTask took 64392ns
[01:00:08] : [Step 10/10] Registered executor on ip-172-30-2-14.mesosphere.io
[01:00:08] : [Step 10/10] Starting task 0
[01:00:08] : [Step 10/10] Forked command at 31782
[01:00:08] : [Step 10/10] sh -c './mesos-fetcher-test-cmd 0'
[01:00:08]W: [Step 10/10] I0324 01:00:08.109361 31779 exec.cpp:535] Executor sending status update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:08]W: [Step 10/10] I0324 01:00:08.110277 28513 slave.cpp:3002] Handling status update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 from executor(1)@172.30.2.14:47763
[01:00:08]W: [Step 10/10] I0324 01:00:08.111502 28507 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:08]W: [Step 10/10] I0324 01:00:08.111541 28507 status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:08]W: [Step 10/10] I0324 01:00:08.111896 28507 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:08] : [Step 10/10] Command exited with status 0 (pid: 31782)
[01:00:08]W: [Step 10/10] I0324 01:00:08.210984 31775 exec.cpp:535] Executor sending status update TASK_FINISHED (UUID: 5246568e-22f4-4d48-b62c-08d0f483b970) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:09]W: [Step 10/10] I0324 01:00:08.211985 28512 slave.cpp:3002] Handling status update TASK_FINISHED (UUID: 5246568e-22f4-4d48-b62c-08d0f483b970) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 from executor(1)@172.30.2.14:47763
[01:00:09]W: [Step 10/10] I0324 01:00:08.213042 28513 slave.cpp:5677] Terminating task 0
[01:00:09]W: [Step 10/10] I0324 01:00:08.216620 28512 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:09]W: [Step 10/10] I0324 01:00:08.216663 28512 hierarchical.cpp:1466] No resources available to allocate!
[01:00:09]W: [Step 10/10] I0324 01:00:08.216698 28512 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:09]W: [Step 10/10] I0324 01:00:08.216760 28512 hierarchical.cpp:1138] Performed allocation for 1 slaves in 618043ns
[01:00:09]W: [Step 10/10] I0324 01:00:09.213533 28512 slave.cpp:3528] executor(1)@172.30.2.14:47763 exited
[01:00:09]W: [Step 10/10] I0324 01:00:09.218444 28506 hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:09]W: [Step 10/10] I0324 01:00:09.218523 28506 hierarchical.cpp:1466] No resources available to allocate!
[01:00:09]W: [Step 10/10] I0324 01:00:09.218565 28506 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:09]W: [Step 10/10] I0324 01:00:09.218632 28506 hierarchical.cpp:1138] Performed allocation for 1 slaves in 731376ns
[01:00:09]W: [Step 10/10] I0324 01:00:09.248484 28508 containerizer.cpp:1656] Executor for container '73965e91-a0fd-4252-9ed9-3d7e7521ee88' has exited
[01:00:09]W: [Step 10/10] I0324 01:00:09.248551 28508 containerizer.cpp:1421] Destroying container '73965e91-a0fd-4252-9ed9-3d7e7521ee88'
[01:00:09]W: [Step 10/10] I0324 01:00:09.250182 28513 cgroups.cpp:2427] Freezing cgroup /cgroup/freezer/mesos/73965e91-a0fd-4252-9ed9-3d7e7521ee88
[01:00:09]W: [Step 10/10] I0324 01:00:09.251570 28506 cgroups.cpp:1409] Successfully froze cgroup /cgroup/freezer/mesos/73965e91-a0fd-4252-9ed9-3d7e7521ee88 after 1.334016ms
[01:00:09]W: [Step 10/10] I0324 01:00:09.252980 28511 cgroups.cpp:2445] Thawing cgroup /cgroup/freezer/mesos/73965e91-a0fd-4252-9ed9-3d7e7521ee88
[01:00:09]W: [Step 10/10] I0324 01:00:09.254159 28511 cgroups.cpp:1438] Successfullly thawed cgroup /cgroup/freezer/mesos/73965e91-a0fd-4252-9ed9-3d7e7521ee88 after 1.13792ms
[01:00:09]W: [Step 10/10] I0324 01:00:09.256676 28508 provisioner.cpp:306] Ignoring destroy request for unknown container 73965e91-a0fd-4252-9ed9-3d7e7521ee88
[01:00:09]W: [Step 10/10] I0324 01:00:09.256921 28508 slave.cpp:3886] Executor '0' of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 exited with status 0
[01:00:10]W: [Step 10/10] I0324 01:00:10.220257 28510 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:10]W: [Step 10/10] I0324 01:00:10.220367 28510 hierarchical.cpp:1138] Performed allocation for 1 slaves in 933732ns
[01:00:10]W: [Step 10/10] I0324 01:00:10.220603 28509 master.cpp:5488] Sending 1 offers to framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[01:00:10]W: [Step 10/10] I0324 01:00:10.221171 28512 sched.cpp:873] Scheduler::resourceOffers took 73706ns
[01:00:10]W: [Step 10/10] I0324 01:00:10.221431 28512 master.cpp:3805] Processing DECLINE call for offers: [ bcf64276-69f3-422e-82e7-6668fa62f035-O2 ] for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[01:00:10]W: [Step 10/10] I0324 01:00:10.221974 28509 hierarchical.cpp:890] Recovered cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 from framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:10]W: [Step 10/10] I0324 01:00:10.222024 28509 hierarchical.cpp:927] Framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 filtered slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for 5secs
[01:00:10]W: [Step 10/10] I0324 01:00:10.475591 28507 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 to the slave
[01:00:11]W: [Step 10/10] I0324 01:00:10.475859 28508 slave.cpp:3400] Forwarding the update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 to master@172.30.2.14:52746
[01:00:11]W: [Step 10/10] I0324 01:00:10.475972 28507 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 5246568e-22f4-4d48-b62c-08d0f483b970) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:11]W: [Step 10/10] I0324 01:00:10.476040 28507 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 5246568e-22f4-4d48-b62c-08d0f483b970) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:11]W: [Step 10/10] I0324 01:00:10.476086 28508 slave.cpp:3294] Status update manager successfully handled status update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:11]W: [Step 10/10] I0324 01:00:10.476132 28508 slave.cpp:3310] Sending acknowledgement for status update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 to executor(1)@172.30.2.14:47763
[01:00:11]W: [Step 10/10] I0324 01:00:10.476222 28510 master.cpp:4927] Status update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 from slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 at slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io)
[01:00:11]W: [Step 10/10] I0324 01:00:10.476255 28510 master.cpp:4975] Forwarding status update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:11]W: [Step 10/10] I0324 01:00:10.476400 28510 master.cpp:6588] Updating the state of task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (latest state: TASK_FINISHED, status update state: TASK_RUNNING)
[01:00:11]W: [Step 10/10] I0324 01:00:10.476526 28508 poll_socket.cpp:110] Socket error while connecting
[01:00:11]W: [Step 10/10] I0324 01:00:10.476583 28508 process.cpp:1650] Failed to send 'mesos.internal.StatusUpdateAcknowledgementMessage' to '172.30.2.14:47763', connect: Socket error while connecting
[01:00:11]W: [Step 10/10] E0324 01:00:10.476663 28508 process.cpp:1958] Failed to shutdown socket with fd 9: Transport endpoint is not connected
[01:00:11]W: [Step 10/10] I0324 01:00:10.476665 28512 sched.cpp:981] Scheduler::statusUpdate took 108583ns
[01:00:11]W: [Step 10/10] I0324 01:00:10.476729 28513 hierarchical.cpp:890] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: ) on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 from framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:11]W: [Step 10/10] I0324 01:00:10.476871 28513 master.cpp:4082] Processing ACKNOWLEDGE call addc2827-9d7f-4d8c-80e8-865f890237f9 for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746 on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0
[01:00:11]W: [Step 10/10] I0324 01:00:11.221448 28512 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:11]W: [Step 10/10] I0324 01:00:11.221534 28512 hierarchical.cpp:1138] Performed allocation for 1 slaves in 664829ns
[01:00:11]W: [Step 10/10] I0324 01:00:11.221716 28509 master.cpp:5488] Sending 1 offers to framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[01:00:11]W: [Step 10/10] I0324 01:00:11.222095 28506 sched.cpp:873] Scheduler::resourceOffers took 60939ns
[01:00:11]W: [Step 10/10] I0324 01:00:11.222296 28506 master.cpp:3805] Processing DECLINE call for offers: [ bcf64276-69f3-422e-82e7-6668fa62f035-O3 ] for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[01:00:11]W: [Step 10/10] I0324 01:00:11.222801 28509 hierarchical.cpp:890] Recovered cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: ) on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 from framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:11]W: [Step 10/10] I0324 01:00:11.222841 28509 hierarchical.cpp:927] Framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 filtered slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for 5secs
[01:00:12]W: [Step 10/10] I0324 01:00:12.222748 28509 hierarchical.cpp:1652] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:12]W: [Step 10/10] I0324 01:00:12.222786 28509 hierarchical.cpp:1466] No resources available to allocate!
[01:00:12]W: [Step 10/10] I0324 01:00:12.222815 28509 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:12]W: [Step 10/10] I0324 01:00:12.222862 28509 hierarchical.cpp:1138] Performed allocation for 1 slaves in 465515ns
[01:00:12]W: [Step 10/10] I0324 01:00:12.659787 28508 slave.cpp:4737] Querying resource estimator for oversubscribable resources
[01:00:12]W: [Step 10/10] I0324 01:00:12.660032 28512 slave.cpp:4751] Received oversubscribable resources from the resource estimator
[01:00:13]W: [Step 10/10] I0324 01:00:13.112960 28507 status_update_manager.cpp:392] Received status update acknowledgement (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:13]W: [Step 10/10] I0324 01:00:13.112939 28508 slave.cpp:3294] Status update manager successfully handled status update TASK_FINISHED (UUID: 5246568e-22f4-4d48-b62c-08d0f483b970) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:13]W: [Step 10/10] I0324 01:00:13.113020 28508 slave.cpp:3310] Sending acknowledgement for status update TASK_FINISHED (UUID: 5246568e-22f4-4d48-b62c-08d0f483b970) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 to executor(1)@172.30.2.14:47763
[01:00:13]W: [Step 10/10] I0324 01:00:13.113136 28507 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: addc2827-9d7f-4d8c-80e8-865f890237f9) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:13]W: [Step 10/10] I0324 01:00:13.113431 28508 poll_socket.cpp:110] Socket error while connecting
[01:00:13]W: [Step 10/10] I0324 01:00:13.113488 28508 process.cpp:1650] Failed to send 'mesos.internal.StatusUpdateAcknowledgementMessage' to '172.30.2.14:47763', connect: Socket error while connecting
[01:00:13]W: [Step 10/10] E0324 01:00:13.113592 28508 process.cpp:1958] Failed to shutdown socket with fd 9: Transport endpoint is not connected
[01:00:13]W: [Step 10/10] I0324 01:00:13.224217 28511 hierarchical.cpp:1652] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:13]W: [Step 10/10] I0324 01:00:13.224257 28511 hierarchical.cpp:1466] No resources available to allocate!
[01:00:13]W: [Step 10/10] I0324 01:00:13.224290 28511 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:13]W: [Step 10/10] I0324 01:00:13.224345 28511 hierarchical.cpp:1138] Performed allocation for 1 slaves in 531406ns
[01:00:14]W: [Step 10/10] I0324 01:00:14.225653 28511 hierarchical.cpp:1652] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:14] : [Step 10/10] ../../src/tests/fetcher_cache_tests.cpp:962: Failure
[01:00:14]W: [Step 10/10] I0324 01:00:14.225715 28511 hierarchical.cpp:1466] No resources available to allocate!
[01:00:14] : [Step 10/10] Failed to wait 15secs for awaitFinished(task.get())
[01:00:14] : [Step 10/10] Begin listing sandboxes
[01:00:14]W: [Step 10/10] I0324 01:00:14.225751 28511 hierarchical.cpp:1561] No inverse offers to send out!
[01:00:14] : [Step 10/10] Begin listing sandbox `/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/latest`:
[01:00:14]W: [Step 10/10] I0324 01:00:14.225816 28511 hierarchical.cpp:1138] Performed allocation for 1 slaves in 681844ns
[01:00:14] : [Step 10/10] Begin file contents of `stderr`:
[01:00:14] : [Step 10/10] I0324 01:00:08.016748 31742 logging.cpp:193] Logging to STDERR
[01:00:14]W: [Step 10/10] I0324 01:00:14.468258 28506 slave.cpp:3482] Received ping from slave-observer(54)@172.30.2.14:52746
[01:00:14] : [Step 10/10] I0324 01:00:08.016911 31742 fetcher.cpp:430] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb\/fetch\/slaves\/bcf64276-69f3-422e-82e7-6668fa62f035-S0\/root","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-mesos-fetc_r-test-cmd","uri":{"cache":true,"executable":true,"extract":true,"value":"http:\/\/172.30.2.14:52746\/(2378)\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb\/slaves\/bcf64276-69f3-422e-82e7-6668fa62f035-S0\/frameworks\/bcf64276-69f3-422e-82e7-6668fa62f035-0000\/executors\/0\/runs\/73965e91-a0fd-4252-9ed9-3d7e7521ee88","user":"root"}
[01:00:14] : [Step 10/10] I0324 01:00:08.023162 31742 fetcher.cpp:385] Fetching URI 'http://172.30.2.14:52746/(2378)/mesos-fetcher-test-cmd'
[01:00:14] : [Step 10/10] I0324 01:00:08.023185 31742 fetcher.cpp:355] Downloading into cache
[01:00:14] : [Step 10/10] I0324 01:00:08.023391 31742 fetcher.cpp:187] Fetching URI 'http://172.30.2.14:52746/(2378)/mesos-fetcher-test-cmd'
[01:00:14] : [Step 10/10] I0324 01:00:08.023429 31742 fetcher.cpp:134] Downloading resource from 'http://172.30.2.14:52746/(2378)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/fetch/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/root/c1-mesos-fetc_r-test-cmd'
[01:00:14] : [Step 10/10] I0324 01:00:08.025457 31742 fetcher.cpp:292] Fetching from cache
[01:00:14] : [Step 10/10] I0324 01:00:08.025492 31742 fetcher.cpp:167] Copying resource with command:cp '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/fetch/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/root/c1-mesos-fetc_r-test-cmd' '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88/mesos-fetcher-test-cmd'
[01:00:14] : [Step 10/10] I0324 01:00:08.028329 31742 fetcher.cpp:462] Fetched 'http://172.30.2.14:52746/(2378)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88/mesos-fetcher-test-cmd'
[01:00:14] : [Step 10/10]
[01:00:14] : [Step 10/10] End file
[01:00:14] : [Step 10/10] Begin file contents of `mesos-fetcher-test-cmd`:
[01:00:14] : [Step 10/10] touch mesos-fetcher-test-cmd$1
[01:00:14] : [Step 10/10] End file
[01:00:14] : [Step 10/10] Begin file contents of `stdout`:
[01:00:14] : [Step 10/10]
[01:00:14] : [Step 10/10] End file
[01:00:14] : [Step 10/10] Begin file contents of `mesos-fetcher-test-cmd0`:
[01:00:14] : [Step 10/10]
[01:00:14]W: [Step 10/10] I0324 01:00:14.706742 28491 sched.cpp:1903] Asked to stop the driver
[01:00:14] : [Step 10/10] End file
[01:00:14] : [Step 10/10] End sandbox
[01:00:14]W: [Step 10/10] I0324 01:00:14.706850 28510 sched.cpp:1143] Stopping framework 'bcf64276-69f3-422e-82e7-6668fa62f035-0000'
[01:00:14] : [Step 10/10] End sandboxes
[01:00:14]W: [Step 10/10] I0324 01:00:14.707195 28509 master.cpp:6061] Processing TEARDOWN call for framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[01:00:14]W: [Step 10/10] I0324 01:00:14.707226 28509 master.cpp:6073] Removing framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (default) at scheduler-8f4d1297-5666-4eb6-b06c-ee41e87d7d0b@172.30.2.14:52746
[01:00:14]W: [Step 10/10] I0324 01:00:14.707442 28512 hierarchical.cpp:375] Deactivated framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:14]W: [Step 10/10] I0324 01:00:14.707473 28511 slave.cpp:2079] Asked to shut down framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 by master@172.30.2.14:52746
[01:00:14]W: [Step 10/10] I0324 01:00:14.707512 28511 slave.cpp:2104] Shutting down framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:14]W: [Step 10/10] I0324 01:00:14.707518 28509 master.cpp:6588] Updating the state of task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 (latest state: TASK_FINISHED, status update state: TASK_KILLED)
[01:00:14]W: [Step 10/10] I0324 01:00:14.707576 28509 master.cpp:6654] Removing task 0 with resources cpus(*):1; mem(*):1 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 on slave bcf64276-69f3-422e-82e7-6668fa62f035-S0 at slave(55)@172.30.2.14:52746 (ip-172-30-2-14.mesosphere.io)
[01:00:14]W: [Step 10/10] I0324 01:00:14.707628 28511 slave.cpp:3990] Cleaning up executor '0' of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 at executor(1)@172.30.2.14:47763
[01:00:14]W: [Step 10/10] I0324 01:00:14.707962 28508 gc.cpp:55] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88' for gc 6.99999180704889days in the future
[01:00:14]W: [Step 10/10] I0324 01:00:14.708037 28509 master.cpp:1065] Master terminating
[01:00:14]W: [Step 10/10] I0324 01:00:14.708109 28508 gc.cpp:55] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0' for gc 6.99999180536days in the future
[01:00:14]W: [Step 10/10] I0324 01:00:14.708227 28511 slave.cpp:4078] Cleaning up framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:14]W: [Step 10/10] I0324 01:00:14.708245 28508 gc.cpp:55] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0/runs/73965e91-a0fd-4252-9ed9-3d7e7521ee88' for gc 6.99999180448days in the future
[01:00:14]W: [Step 10/10] I0324 01:00:14.708336 28508 gc.cpp:55] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000/executors/0' for gc 6.99999180368days in the future
[01:00:14]W: [Step 10/10] I0324 01:00:14.708426 28508 gc.cpp:55] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000' for gc 6.99999180200296days in the future
[01:00:14]W: [Step 10/10] I0324 01:00:14.708539 28508 gc.cpp:55] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_EB8yEb/meta/slaves/bcf64276-69f3-422e-82e7-6668fa62f035-S0/frameworks/bcf64276-69f3-422e-82e7-6668fa62f035-0000' for gc 6.99999180129778days in the future
[01:00:14]W: [Step 10/10] I0324 01:00:14.708650 28513 hierarchical.cpp:326] Removed framework bcf64276-69f3-422e-82e7-6668fa62f035-0000
[01:00:14]W: [Step 10/10] I0324 01:00:14.708729 28511 slave.cpp:3528] master@172.30.2.14:52746 exited
[01:00:14]W: [Step 10/10] W0324 01:00:14.708755 28511 slave.cpp:3531] Master disconnected! Waiting for a new master to be elected
[01:00:14]W: [Step 10/10] I0324 01:00:14.708951 28513 hierarchical.cpp:505] Removed slave bcf64276-69f3-422e-82e7-6668fa62f035-S0
[01:00:14]W: [Step 10/10] I0324 01:00:14.713003 28513 slave.cpp:668] Slave terminating
[01:00:14]W: [Step 10/10] I0324 01:00:14.776430 28507 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: 5246568e-22f4-4d48-b62c-08d0f483b970) for task 0 of framework bcf64276-69f3-422e-82e7-6668fa62f035-0000 to the slave
[01:00:14] : [Step 10/10] [ FAILED ] FetcherCacheHttpTest.HttpCachedSerialized (33613 ms)
{code}
> FetcherCacheHttpTest.HttpCachedSerialized flaky again.
> ------------------------------------------------------
>
> Key: MESOS-4692
> URL: https://issues.apache.org/jira/browse/MESOS-4692
> Project: Mesos
> Issue Type: Bug
> Components: fetcher, test
> Environment: CentOS 7, plain
> Reporter: Bernd Mathiske
> Priority: Minor
> Labels: flaky, test
>
> {noformat}
> [12:20:50] : [Step 8/8] [ RUN ] FetcherCacheHttpTest.HttpCachedSerialized
> [12:20:50]W: [Step 8/8] I0217 12:20:50.842162 32498 leveldb.cpp:174] Opened db in 4.973489ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843670 32498 leveldb.cpp:181] Compacted db in 1.48087ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843709 32498 leveldb.cpp:196] Created db iterator in 15661ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843720 32498 leveldb.cpp:202] Seeked to beginning of db in 1401ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843729 32498 leveldb.cpp:271] Iterated through 0 keys in the db in 357ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843760 32498 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [12:20:50]W: [Step 8/8] I0217 12:20:50.844228 32513 recover.cpp:447] Starting replica recovery
> [12:20:50]W: [Step 8/8] I0217 12:20:50.844411 32513 recover.cpp:473] Replica is in EMPTY status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.845355 32516 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (2089)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.845825 32518 recover.cpp:193] Received a recover response from a replica in EMPTY status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.846307 32517 recover.cpp:564] Updating replica status to STARTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.846789 32518 master.cpp:374] Master 0941887d-60f1-4ff3-85f0-5d19ffee8005 (ip-172-30-2-21.mesosphere.io) started on 172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.846810 32518 master.cpp:376] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/YFwdSN/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="25secs" --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/YFwdSN/master" --zk_session_timeout="10secs"
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847057 32518 master.cpp:421] Master only allowing authenticated frameworks to register
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847066 32518 master.cpp:426] Master only allowing authenticated slaves to register
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847072 32518 credentials.hpp:35] Loading credentials for authentication from '/tmp/YFwdSN/credentials'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847286 32518 master.cpp:466] Using default 'crammd5' authenticator
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847395 32518 master.cpp:535] Using default 'basic' HTTP authenticator
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847511 32518 master.cpp:569] Authorization enabled
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847642 32517 hierarchical.cpp:144] Initialized hierarchical allocator process
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847646 32519 whitelist_watcher.cpp:77] No whitelist given
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847795 32514 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.368308ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847825 32514 replica.cpp:320] Persisted replica status to STARTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.848002 32512 recover.cpp:473] Replica is in STARTING status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849025 32516 master.cpp:1710] The newly elected leader is master@172.30.2.21:33004 with id 0941887d-60f1-4ff3-85f0-5d19ffee8005
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849047 32516 master.cpp:1723] Elected as the leading master!
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849061 32516 master.cpp:1468] Recovering from registrar
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849055 32515 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (2091)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849172 32518 registrar.cpp:307] Recovering registrar
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849376 32513 recover.cpp:193] Received a recover response from a replica in STARTING status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849895 32517 recover.cpp:564] Updating replica status to VOTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851344 32512 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.29974ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851366 32512 replica.cpp:320] Persisted replica status to VOTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851455 32519 recover.cpp:578] Successfully joined the Paxos group
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851603 32519 recover.cpp:462] Recover process terminated
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851975 32517 log.cpp:659] Attempting to start the writer
> [12:20:50]W: [Step 8/8] I0217 12:20:50.852934 32516 replica.cpp:493] Replica received implicit promise request from (2092)@172.30.2.21:33004 with proposal 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.854387 32516 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.421154ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.854408 32516 replica.cpp:342] Persisted promised to 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.854923 32517 coordinator.cpp:238] Coordinator attempting to fill missing positions
> [12:20:50]W: [Step 8/8] I0217 12:20:50.855963 32515 replica.cpp:388] Replica received explicit promise request from (2093)@172.30.2.21:33004 for position 0 with proposal 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.857283 32515 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.287784ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.857306 32515 replica.cpp:712] Persisted action at 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.858182 32518 replica.cpp:537] Replica received write request for position 0 from (2094)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.858227 32518 leveldb.cpp:436] Reading position from leveldb took 20803ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.859516 32518 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.260506ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.859539 32518 replica.cpp:712] Persisted action at 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.860041 32513 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.863092 32513 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 3.022825ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.863114 32513 replica.cpp:712] Persisted action at 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.863129 32513 replica.cpp:697] Replica learned NOP action at position 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.863597 32517 log.cpp:675] Writer started with ending position 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.864405 32515 leveldb.cpp:436] Reading position from leveldb took 21575ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.865149 32515 registrar.cpp:340] Successfully fetched the registry (0B) in 15.93984ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.865234 32515 registrar.cpp:439] Applied 1 operations in 20551ns; attempting to update the 'registry'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.865816 32518 log.cpp:683] Attempting to append 206 bytes to the log
> [12:20:50]W: [Step 8/8] I0217 12:20:50.865921 32519 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.866474 32513 replica.cpp:537] Replica received write request for position 1 from (2095)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.873576 32513 leveldb.cpp:341] Persisting action (225 bytes) to leveldb took 7.073358ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.873600 32513 replica.cpp:712] Persisted action at 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.874136 32512 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.876266 32512 leveldb.cpp:341] Persisting action (227 bytes) to leveldb took 2.102934ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.876288 32512 replica.cpp:712] Persisted action at 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.876303 32512 replica.cpp:697] Replica learned APPEND action at position 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877070 32517 registrar.cpp:484] Successfully updated the 'registry' in 11.782912ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877202 32517 registrar.cpp:370] Successfully recovered registrar
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877279 32519 log.cpp:702] Attempting to truncate the log to 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877374 32512 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877605 32513 master.cpp:1520] Recovered 0 slaves from the Registry (167B) ; allowing 10mins for slaves to re-register
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877636 32518 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
> [12:20:50]W: [Step 8/8] I0217 12:20:50.878103 32512 replica.cpp:537] Replica received write request for position 2 from (2096)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.879442 32512 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.313099ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.879464 32512 replica.cpp:712] Persisted action at 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.879961 32513 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.881382 32513 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.393701ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.881433 32513 leveldb.cpp:399] Deleting ~1 keys from leveldb took 27209ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.881448 32513 replica.cpp:712] Persisted action at 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.881463 32513 replica.cpp:697] Replica learned TRUNCATE action at position 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.888675 32498 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,filesystem/posix
> [12:20:50]W: [Step 8/8] I0217 12:20:50.895370 32498 linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
> [12:20:50]W: [Step 8/8] I0217 12:20:50.898412 32516 slave.cpp:192] Slave started on 52)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.898428 32516 slave.cpp:193] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_auth_server="https://auth.docker.io" --docker_kill_orphans="true" --docker_puller_timeout="60" --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/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --hostname_lookup="true" --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/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY"
> [12:20:50]W: [Step 8/8] I0217 12:20:50.898826 32516 credentials.hpp:83] Loading credential for authentication from '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/credential'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.898960 32516 slave.cpp:323] Slave using credential for: test-principal
> [12:20:50]W: [Step 8/8] I0217 12:20:50.899092 32516 resources.cpp:564] Parsing resources as JSON failed: cpus:1000;mem:1000
> [12:20:50]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:50]W: [Step 8/8] I0217 12:20:50.899408 32516 slave.cpp:463] Slave resources: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.899472 32516 slave.cpp:471] Slave attributes: [ ]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.899482 32516 slave.cpp:476] Slave hostname: ip-172-30-2-21.mesosphere.io
> [12:20:50]W: [Step 8/8] I0217 12:20:50.900118 32519 state.cpp:58] Recovering state from '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.900372 32516 status_update_manager.cpp:200] Recovering status update manager
> [12:20:50]W: [Step 8/8] I0217 12:20:50.900516 32516 containerizer.cpp:390] Recovering containerizer
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902184 32512 provisioner.cpp:245] Provisioner recovery complete
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902458 32514 slave.cpp:4495] Finished recovery
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902740 32514 slave.cpp:4667] Querying resource estimator for oversubscribable resources
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902928 32514 slave.cpp:795] New master detected at master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902943 32516 status_update_manager.cpp:174] Pausing sending status updates
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902992 32514 slave.cpp:858] Authenticating with master master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903007 32514 slave.cpp:863] Using default CRAM-MD5 authenticatee
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903121 32514 slave.cpp:831] Detecting new master
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903167 32517 authenticatee.cpp:121] Creating new client SASL connection
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903270 32514 slave.cpp:4681] Received oversubscribable resources from the resource estimator
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903493 32518 master.cpp:5521] Authenticating slave(52)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903594 32519 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(150)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903794 32516 authenticator.cpp:98] Creating new server SASL connection
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904034 32517 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904057 32517 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904134 32517 authenticator.cpp:203] Received SASL authentication start
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904180 32517 authenticator.cpp:325] Authentication requires more steps
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904250 32517 authenticatee.cpp:258] Received SASL authentication step
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904351 32517 authenticator.cpp:231] Received SASL authentication step
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904376 32517 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-21.mesosphere.io' server FQDN: 'ip-172-30-2-21.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904386 32517 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904414 32517 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904433 32517 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-21.mesosphere.io' server FQDN: 'ip-172-30-2-21.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904440 32517 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904445 32517 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904456 32517 authenticator.cpp:317] Authentication success
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904533 32513 authenticatee.cpp:298] Authentication success
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904567 32516 master.cpp:5551] Successfully authenticated principal 'test-principal' at slave(52)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904624 32515 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(150)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904799 32512 slave.cpp:926] Successfully authenticated with master master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904908 32512 slave.cpp:1320] Will retry registration in 14.571781ms if necessary
> [12:20:50]W: [Step 8/8] I0217 12:20:50.905035 32515 master.cpp:4235] Registering slave at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io) with id 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.905369 32513 registrar.cpp:439] Applied 1 operations in 45856ns; attempting to update the 'registry'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.905974 32514 log.cpp:683] Attempting to append 391 bytes to the log
> [12:20:50]W: [Step 8/8] I0217 12:20:50.906070 32517 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.906674 32517 replica.cpp:537] Replica received write request for position 3 from (2113)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.908289 32517 leveldb.cpp:341] Persisting action (410 bytes) to leveldb took 1.586609ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.908313 32517 replica.cpp:712] Persisted action at 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.908833 32517 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.910802 32517 leveldb.cpp:341] Persisting action (412 bytes) to leveldb took 1.947096ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.910825 32517 replica.cpp:712] Persisted action at 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.910840 32517 replica.cpp:697] Replica learned APPEND action at position 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.911844 32516 registrar.cpp:484] Successfully updated the 'registry' in 6.420992ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912017 32519 log.cpp:702] Attempting to truncate the log to 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912127 32515 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912530 32512 slave.cpp:3435] Received ping from slave-observer(49)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912617 32518 master.cpp:4303] Registered slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io) with cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912853 32512 slave.cpp:970] Registered with master master@172.30.2.21:33004; given slave ID 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912856 32519 hierarchical.cpp:473] Added slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 (ip-172-30-2-21.mesosphere.io) with cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000] (allocated: )
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912878 32512 fetcher.cpp:81] Clearing fetcher cache
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912895 32515 replica.cpp:537] Replica received write request for position 4 from (2114)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912968 32519 hierarchical.cpp:1403] No resources available to allocate!
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912999 32519 hierarchical.cpp:1116] Performed allocation for slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 in 114429ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913094 32514 status_update_manager.cpp:181] Resuming sending status updates
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913276 32512 slave.cpp:993] Checkpointing SlaveInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/slave.info'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913524 32512 slave.cpp:1029] Forwarding total oversubscribed resources
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913640 32512 master.cpp:4644] Received update of slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io) with total oversubscribed resources
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913667 32498 sched.cpp:222] Version: 0.27.1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914054 32516 sched.cpp:326] New master detected at master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914115 32516 sched.cpp:382] Authenticating with master master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914129 32516 sched.cpp:389] Using default CRAM-MD5 authenticatee
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914122 32518 hierarchical.cpp:531] Slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 (ip-172-30-2-21.mesosphere.io) updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000], allocated: )
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914211 32518 hierarchical.cpp:1403] No resources available to allocate!
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914229 32518 hierarchical.cpp:1116] Performed allocation for slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 in 79633ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914273 32519 authenticatee.cpp:121] Creating new client SASL connection
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914374 32515 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.451028ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914397 32515 replica.cpp:712] Persisted action at 4
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914518 32516 master.cpp:5521] Authenticating scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914615 32518 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(151)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914798 32512 authenticator.cpp:98] Creating new server SASL connection
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914968 32518 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915048 32519 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915069 32519 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915146 32519 authenticator.cpp:203] Received SASL authentication start
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915176 32519 authenticator.cpp:325] Authentication requires more steps
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915251 32519 authenticatee.cpp:258] Received SASL authentication step
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915354 32513 authenticator.cpp:231] Received SASL authentication step
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915385 32513 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-21.mesosphere.io' server FQDN: 'ip-172-30-2-21.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915402 32513 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915438 32513 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915475 32513 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-21.mesosphere.io' server FQDN: 'ip-172-30-2-21.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915490 32513 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915503 32513 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915520 32513 authenticator.cpp:317] Authentication success
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915606 32517 authenticatee.cpp:298] Authentication success
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915654 32519 master.cpp:5551] Successfully authenticated principal 'test-principal' at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915695 32514 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(151)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915853 32512 sched.cpp:471] Successfully authenticated with master master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915868 32512 sched.cpp:780] Sending SUBSCRIBE call to master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915936 32512 sched.cpp:813] Will retry registration in 1.47153444secs if necessary
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916014 32516 master.cpp:2278] Received SUBSCRIBE call for framework 'default' at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] W0217 12:20:50.916038 32516 master.cpp:2285] Framework at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004 (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916072 32516 master.cpp:1749] Authorizing framework principal '' to receive offers for role '*'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916290 32519 master.cpp:2349] Subscribing framework default with checkpointing enabled and capabilities [ ]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916435 32518 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.438664ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916496 32518 leveldb.cpp:399] Deleting ~2 keys from leveldb took 38041ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916518 32518 replica.cpp:712] Persisted action at 4
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916543 32518 replica.cpp:697] Replica learned TRUNCATE action at position 4
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916612 32516 hierarchical.cpp:265] Added framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916674 32519 sched.cpp:707] Framework registered with 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916707 32519 sched.cpp:721] Scheduler::registered took 15213ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.917186 32516 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:50]W: [Step 8/8] I0217 12:20:50.917228 32516 hierarchical.cpp:1096] Performed allocation for 1 slaves in 591295ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.917448 32515 master.cpp:5350] Sending 1 offers to framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.917795 32518 sched.cpp:877] Scheduler::resourceOffers took 105618ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.918026 32498 resources.cpp:564] Parsing resources as JSON failed: cpus:1;mem:1
> [12:20:50]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:50]W: [Step 8/8] I0217 12:20:50.918958 32518 master.cpp:3136] Processing ACCEPT call for offers: [ 0941887d-60f1-4ff3-85f0-5d19ffee8005-O0 ] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io) for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.918993 32518 master.cpp:2823] Authorizing framework principal '' to launch task 0 as user 'root'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.919986 32516 master.hpp:176] Adding task 0 with resources cpus(*):1; mem(*):1 on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 (ip-172-30-2-21.mesosphere.io)
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920064 32516 master.cpp:3621] Launching task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004 with resources cpus(*):1; mem(*):1 on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io)
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920297 32514 slave.cpp:1360] Got assigned task 0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920392 32514 slave.cpp:5201] Checkpointing FrameworkInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/framework.info'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920485 32515 hierarchical.cpp:892] Recovered cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920526 32515 hierarchical.cpp:929] Framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 filtered slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for 5secs
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920642 32514 slave.cpp:5212] Checkpointing framework pid 'scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/framework.pid'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920826 32514 resources.cpp:564] Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:20:50]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:50]W: [Step 8/8] I0217 12:20:50.921176 32514 slave.cpp:1479] Launching task 0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.921234 32514 resources.cpp:564] Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:20:50]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:50]W: [Step 8/8] I0217 12:20:50.921684 32514 paths.cpp:472] Trying to chown '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e' to user 'root'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.925053 32514 slave.cpp:5653] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/executor.info'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.925425 32514 slave.cpp:5281] Launching executor 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.925781 32519 containerizer.cpp:649] Starting container '31b2084a-64ff-479c-af79-1ee5370efb7e' for executor '0' of framework '0941887d-60f1-4ff3-85f0-5d19ffee8005-0000'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.925837 32514 slave.cpp:5676] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/tasks/0/task.info'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.926038 32514 slave.cpp:1697] Queuing task '0' for executor '0' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.926115 32514 slave.cpp:748] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.929641 32517 linux_launcher.cpp:304] Cloning child process with flags =
> [12:20:50]W: [Step 8/8] I0217 12:20:50.931422 32517 containerizer.cpp:1003] Checkpointing executor's forked pid 3300 to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/pids/forked.pid'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.932808 32518 fetcher.cpp:304] Starting to fetch URIs for container: 31b2084a-64ff-479c-af79-1ee5370efb7e, directory: /tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e
> [12:20:50]W: [Step 8/8] I0217 12:20:50.935529 32518 fetcher.cpp:893] Created cache entry 'root@http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd' with file: c1-mesos-fetc_r-test-cmd
> [12:20:50]W: [Step 8/8] I0217 12:20:50.936242 32515 fetcher.cpp:252] Fetching size for URI: http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd
> [12:20:50]W: [Step 8/8] I0217 12:20:50.937364 32516 process.cpp:3141] Handling HTTP event for process '(2098)' with path: '/(2098)/mesos-fetcher-test-cmd'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.937711 32513 process.cpp:1184] Sending file at '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
> [12:20:50]W: [Step 8/8] I0217 12:20:50.938225 32516 fetcher.cpp:668] Claiming fetcher cache space for: root@http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd
> [12:20:50]W: [Step 8/8] I0217 12:20:50.938241 32516 fetcher.cpp:1113] Claimed cache space: 30B, now using: 30B
> [12:20:50] : [Step 8/8] HTTP/1.1 200 OK
> [12:20:50] : [Step 8/8] Date: Wed, 17 Feb 2016 12:20:50 GMT
> [12:20:50] : [Step 8/8] Content-Length: 30
> [12:20:50] : [Step 8/8]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.942404 32519 fetcher.cpp:766] Fetching URIs using command '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.988598 32514 process.cpp:3141] Handling HTTP event for process '(2098)' with path: '/(2098)/mesos-fetcher-test-cmd'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.988895 32517 process.cpp:1184] Sending file at '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
> [12:20:51]W: [Step 8/8] I0217 12:20:51.026612 32514 fetcher.cpp:1125] Released cache space: 0B, now using: 30B
> [12:20:51]W: [Step 8/8] WARNING: Logging before InitGoogleLogging() is written to STDERR
> [12:20:51]W: [Step 8/8] I0217 12:20:51.072054 3300 process.cpp:994] libprocess is initialized on 172.30.2.21:56710 for 8 cpus
> [12:20:51]W: [Step 8/8] I0217 12:20:51.072721 3300 logging.cpp:193] Logging to STDERR
> [12:20:51]W: [Step 8/8] I0217 12:20:51.074179 3300 exec.cpp:134] Version: 0.27.1
> [12:20:51]W: [Step 8/8] I0217 12:20:51.079038 3348 exec.cpp:184] Executor started at: executor(1)@172.30.2.21:56710 with pid 3300
> [12:20:51]W: [Step 8/8] I0217 12:20:51.080653 32512 slave.cpp:2642] Got registration for executor '0' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.081066 32512 slave.cpp:2728] Checkpointing executor pid 'executor(1)@172.30.2.21:56710' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/pids/libprocess.pid'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.082375 3347 exec.cpp:208] Executor registered on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.082581 32514 slave.cpp:1862] Sending queued task '0' to executor '0' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 at executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.083726 3347 exec.cpp:220] Executor::registered took 223218ns
> [12:20:51] : [Step 8/8] Registered executor on ip-172-30-2-21.mesosphere.io
> [12:20:51] : [Step 8/8] Starting task 0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.083962 3347 exec.cpp:295] Executor asked to run task '0'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.084045 3347 exec.cpp:304] Executor::launchTask took 64910ns
> [12:20:51] : [Step 8/8] Forked command at 3354
> [12:20:51] : [Step 8/8] sh -c './mesos-fetcher-test-cmd 0'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.086417 3346 exec.cpp:517] Executor sending status update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.087159 32512 slave.cpp:3001] Handling status update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.087456 32512 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.087486 32512 status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.087827 32512 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.091712 32512 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to the slave
> [12:20:51]W: [Step 8/8] I0217 12:20:51.091940 32517 slave.cpp:3353] Forwarding the update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to master@172.30.2.21:33004
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092116 32517 slave.cpp:3247] Status update manager successfully handled status update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092162 32517 slave.cpp:3263] Sending acknowledgement for status update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092222 32516 master.cpp:4789] Status update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092257 32516 master.cpp:4837] Forwarding status update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092391 32516 master.cpp:6445] Updating the state of task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092623 32519 sched.cpp:985] Scheduler::statusUpdate took 118299ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092649 3347 exec.cpp:341] Executor received status update acknowledgement 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078 for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092922 32518 master.cpp:3947] Processing ACKNOWLEDGE call 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078 for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004 on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.093154 32518 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.093262 32518 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.096221 32519 slave.cpp:2411] Status update manager successfully handled status update acknowledgement (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51] : [Step 8/8] Command exited with status 0 (pid: 3354)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.187614 3350 exec.cpp:517] Executor sending status update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.188201 32513 slave.cpp:3001] Handling status update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.188304 32513 slave.cpp:5591] Terminating task 0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.189271 32516 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.189324 32516 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.192682 32516 status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to the slave
> [12:20:51]W: [Step 8/8] I0217 12:20:51.192920 32518 slave.cpp:3353] Forwarding the update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to master@172.30.2.21:33004
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193073 32518 slave.cpp:3247] Status update manager successfully handled status update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193120 32518 slave.cpp:3263] Sending acknowledgement for status update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193233 32519 master.cpp:4789] Status update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193277 32519 master.cpp:4837] Forwarding status update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193434 32519 master.cpp:6445] Updating the state of task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193640 3348 exec.cpp:341] Executor received status update acknowledgement a4298b07-b8d3-4bc3-8599-3739f6da2813 for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193684 32514 sched.cpp:985] Scheduler::statusUpdate took 142687ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193855 32516 hierarchical.cpp:892] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000], allocated: ) on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193936 32519 master.cpp:3947] Processing ACKNOWLEDGE call a4298b07-b8d3-4bc3-8599-3739f6da2813 for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004 on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193979 32519 master.cpp:6511] Removing task 0 with resources cpus(*):1; mem(*):1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.194285 32513 status_update_manager.cpp:392] Received status update acknowledgement (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.194447 32513 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.197284 32513 status_update_manager.cpp:528] Cleaning up status update stream for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.197531 32518 slave.cpp:2411] Status update manager successfully handled status update acknowledgement (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.197564 32518 slave.cpp:5632] Completing task 0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.849397 32514 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:51]W: [Step 8/8] I0217 12:20:51.849462 32514 hierarchical.cpp:1096] Performed allocation for 1 slaves in 825551ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.849715 32518 master.cpp:5350] Sending 1 offers to framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:51]W: [Step 8/8] I0217 12:20:51.850183 32517 sched.cpp:877] Scheduler::resourceOffers took 109793ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.850472 32498 resources.cpp:564] Parsing resources as JSON failed: cpus:1;mem:1
> [12:20:51]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:51]W: [Step 8/8] I0217 12:20:51.851595 32517 master.cpp:3136] Processing ACCEPT call for offers: [ 0941887d-60f1-4ff3-85f0-5d19ffee8005-O1 ] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io) for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:51]W: [Step 8/8] I0217 12:20:51.851634 32517 master.cpp:2823] Authorizing framework principal '' to launch task 1 as user 'root'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.852676 32514 master.hpp:176] Adding task 1 with resources cpus(*):1; mem(*):1 on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.852761 32514 master.cpp:3621] Launching task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004 with resources cpus(*):1; mem(*):1 on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853035 32519 slave.cpp:1360] Got assigned task 1 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853128 32519 resources.cpp:564] Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:20:51]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853227 32513 hierarchical.cpp:892] Recovered cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853272 32513 hierarchical.cpp:929] Framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 filtered slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for 5secs
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853509 32519 slave.cpp:1479] Launching task 1 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853567 32519 resources.cpp:564] Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:20:51]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:51]W: [Step 8/8] I0217 12:20:51.854045 32519 paths.cpp:472] Trying to chown '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530' to user 'root'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.857623 32519 slave.cpp:5653] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/executor.info'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858033 32519 slave.cpp:5281] Launching executor 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858469 32514 containerizer.cpp:649] Starting container 'cf539d3e-9c02-438a-b960-44bc00fb3530' for executor '1' of framework '0941887d-60f1-4ff3-85f0-5d19ffee8005-0000'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858515 32519 slave.cpp:5676] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/tasks/1/task.info'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858726 32519 slave.cpp:1697] Queuing task '1' for executor '1' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858824 32519 slave.cpp:748] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.862714 32514 linux_launcher.cpp:304] Cloning child process with flags =
> [12:20:51]W: [Step 8/8] I0217 12:20:51.864408 32514 containerizer.cpp:1003] Checkpointing executor's forked pid 3357 to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/pids/forked.pid'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.866123 32516 fetcher.cpp:304] Starting to fetch URIs for container: cf539d3e-9c02-438a-b960-44bc00fb3530, directory: /tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530
> [12:20:51]W: [Step 8/8] I0217 12:20:51.874403 32516 fetcher.cpp:766] Fetching URIs using command '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
> [12:20:51]W: [Step 8/8] WARNING: Logging before InitGoogleLogging() is written to STDERR
> [12:20:51]W: [Step 8/8] I0217 12:20:51.977840 3357 process.cpp:994] libprocess is initialized on 172.30.2.21:58560 for 8 cpus
> [12:20:51]W: [Step 8/8] I0217 12:20:51.978535 3357 logging.cpp:193] Logging to STDERR
> [12:20:51]W: [Step 8/8] I0217 12:20:51.979935 3357 exec.cpp:134] Version: 0.27.1
> [12:20:51]W: [Step 8/8] I0217 12:20:51.984833 3402 exec.cpp:184] Executor started at: executor(1)@172.30.2.21:58560 with pid 3357
> [12:20:51]W: [Step 8/8] I0217 12:20:51.986431 32519 slave.cpp:2642] Got registration for executor '1' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:58560
> [12:20:51]W: [Step 8/8] I0217 12:20:51.986873 32519 slave.cpp:2728] Checkpointing executor pid 'executor(1)@172.30.2.21:58560' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/pids/libprocess.pid'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.988216 3405 exec.cpp:208] Executor registered on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.988230 32514 slave.cpp:1862] Sending queued task '1' to executor '1' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 at executor(1)@172.30.2.21:58560
> [12:20:51] : [Step 8/8] Registered executor on ip-172-30-2-21.mesosphere.io
> [12:20:51] : [Step 8/8] Starting task 1
> [12:20:51]W: [Step 8/8] I0217 12:20:51.989580 3405 exec.cpp:220] Executor::registered took 221432ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.989831 3405 exec.cpp:295] Executor asked to run task '1'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.989915 3405 exec.cpp:304] Executor::launchTask took 65747ns
> [12:20:51] : [Step 8/8] Forked command at 3411
> [12:20:51] : [Step 8/8] sh -c './mesos-fetcher-test-cmd 1'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.991230 3405 exec.cpp:517] Executor sending status update TASK_RUNNING (UUID: 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.991989 32516 slave.cpp:3001] Handling status update TASK_RUNNING (UUID: 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:58560
> [12:20:51]W: [Step 8/8] I0217 12:20:51.992316 32512 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.992352 32512 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.992666 32512 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:52] : [Step 8/8] Command exited with status 0 (pid: 3411)
> [12:20:52]W: [Step 8/8] I0217 12:20:52.092772 3405 exec.cpp:517] Executor sending status update TASK_FINISHED (UUID: e4e9ef2e-83c8-4b5b-9cd9-f20c2f2ea474) for task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:52]W: [Step 8/8] I0217 12:20:52.093408 32519 slave.cpp:3001] Handling status update TASK_FINISHED (UUID: e4e9ef2e-83c8-4b5b-9cd9-f20c2f2ea474) for task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:58560
> [12:20:52]W: [Step 8/8] I0217 12:20:52.093510 32519 slave.cpp:5591] Terminating task 1
> [12:20:52]W: [Step 8/8] I0217 12:20:52.189762 32514 slave.cpp:3481] executor(1)@172.30.2.21:56710 exited
> [12:20:52]W: [Step 8/8] I0217 12:20:52.234338 32513 containerizer.cpp:1443] Executor for container '31b2084a-64ff-479c-af79-1ee5370efb7e' has exited
> [12:20:52]W: [Step 8/8] I0217 12:20:52.234361 32513 containerizer.cpp:1227] Destroying container '31b2084a-64ff-479c-af79-1ee5370efb7e'
> [12:20:52]W: [Step 8/8] I0217 12:20:52.236660 32513 cgroups.cpp:2427] Freezing cgroup /sys/fs/cgroup/freezer/mesos/31b2084a-64ff-479c-af79-1ee5370efb7e
> [12:20:52]W: [Step 8/8] I0217 12:20:52.238652 32518 cgroups.cpp:1409] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/31b2084a-64ff-479c-af79-1ee5370efb7e after 1.950976ms
> [12:20:52]W: [Step 8/8] I0217 12:20:52.240897 32519 cgroups.cpp:2445] Thawing cgroup /sys/fs/cgroup/freezer/mesos/31b2084a-64ff-479c-af79-1ee5370efb7e
> [12:20:52]W: [Step 8/8] I0217 12:20:52.242872 32519 cgroups.cpp:1438] Successfullly thawed cgroup /sys/fs/cgroup/freezer/mesos/31b2084a-64ff-479c-af79-1ee5370efb7e after 1.935872ms
> [12:20:52]W: [Step 8/8] I0217 12:20:52.245499 32516 provisioner.cpp:306] Ignoring destroy request for unknown container 31b2084a-64ff-479c-af79-1ee5370efb7e
> [12:20:52]W: [Step 8/8] I0217 12:20:52.245748 32513 slave.cpp:3816] Executor '0' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 exited with status 0
> [12:20:52]W: [Step 8/8] I0217 12:20:52.245806 32513 slave.cpp:3920] Cleaning up executor '0' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 at executor(1)@172.30.2.21:56710
> [12:20:52]W: [Step 8/8] I0217 12:20:52.246109 32514 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e' for gc 6.99999715225481days in the future
> [12:20:52]W: [Step 8/8] I0217 12:20:52.246222 32514 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0' for gc 6.99999715108741days in the future
> [12:20:52]W: [Step 8/8] I0217 12:20:52.246287 32514 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e' for gc 6.99999715049778days in the future
> [12:20:52]W: [Step 8/8] I0217 12:20:52.246345 32514 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0' for gc 6.9999971499763days in the future
> [12:20:52]W: [Step 8/8] I0217 12:20:52.850482 32516 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:52]W: [Step 8/8] I0217 12:20:52.850548 32516 hierarchical.cpp:1403] No resources available to allocate!
> [12:20:52]W: [Step 8/8] I0217 12:20:52.850584 32516 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:52]W: [Step 8/8] I0217 12:20:52.850610 32516 hierarchical.cpp:1096] Performed allocation for 1 slaves in 627005ns
> [12:20:53]W: [Step 8/8] I0217 12:20:53.096267 32517 slave.cpp:3481] executor(1)@172.30.2.21:58560 exited
> [12:20:53]W: [Step 8/8] I0217 12:20:53.139739 32514 containerizer.cpp:1443] Executor for container 'cf539d3e-9c02-438a-b960-44bc00fb3530' has exited
> [12:20:53]W: [Step 8/8] I0217 12:20:53.139766 32514 containerizer.cpp:1227] Destroying container 'cf539d3e-9c02-438a-b960-44bc00fb3530'
> [12:20:53]W: [Step 8/8] I0217 12:20:53.142175 32515 cgroups.cpp:2427] Freezing cgroup /sys/fs/cgroup/freezer/mesos/cf539d3e-9c02-438a-b960-44bc00fb3530
> [12:20:53]W: [Step 8/8] I0217 12:20:53.144177 32518 cgroups.cpp:1409] Successfully froze cgroup /sys/fs/cgroup/freezer/mesos/cf539d3e-9c02-438a-b960-44bc00fb3530 after 1.959168ms
> [12:20:53]W: [Step 8/8] I0217 12:20:53.146278 32517 cgroups.cpp:2445] Thawing cgroup /sys/fs/cgroup/freezer/mesos/cf539d3e-9c02-438a-b960-44bc00fb3530
> [12:20:53]W: [Step 8/8] I0217 12:20:53.148144 32517 cgroups.cpp:1438] Successfullly thawed cgroup /sys/fs/cgroup/freezer/mesos/cf539d3e-9c02-438a-b960-44bc00fb3530 after 1.824768ms
> [12:20:53]W: [Step 8/8] I0217 12:20:53.150665 32513 provisioner.cpp:306] Ignoring destroy request for unknown container cf539d3e-9c02-438a-b960-44bc00fb3530
> [12:20:53]W: [Step 8/8] I0217 12:20:53.150898 32513 slave.cpp:3816] Executor '1' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 exited with status 0
> [12:20:53]W: [Step 8/8] I0217 12:20:53.851771 32515 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:53]W: [Step 8/8] I0217 12:20:53.851858 32515 hierarchical.cpp:1403] No resources available to allocate!
> [12:20:53]W: [Step 8/8] I0217 12:20:53.851894 32515 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:53]W: [Step 8/8] I0217 12:20:53.851920 32515 hierarchical.cpp:1096] Performed allocation for 1 slaves in 661166ns
> [12:20:54]W: [Step 8/8] I0217 12:20:54.853108 32518 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:54]W: [Step 8/8] I0217 12:20:54.853176 32518 hierarchical.cpp:1403] No resources available to allocate!
> [12:20:54]W: [Step 8/8] I0217 12:20:54.853212 32518 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:54]W: [Step 8/8] I0217 12:20:54.853238 32518 hierarchical.cpp:1096] Performed allocation for 1 slaves in 662593ns
> [12:20:55]W: [Step 8/8] I0217 12:20:55.854672 32517 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:55]W: [Step 8/8] I0217 12:20:55.854742 32517 hierarchical.cpp:1403] No resources available to allocate!
> [12:20:55]W: [Step 8/8] I0217 12:20:55.854801 32517 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:55]W: [Step 8/8] I0217 12:20:55.854832 32517 hierarchical.cpp:1096] Performed allocation for 1 slaves in 671127ns
> [12:20:56]W: [Step 8/8] I0217 12:20:56.856071 32518 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:56]W: [Step 8/8] I0217 12:20:56.856137 32518 hierarchical.cpp:1096] Performed allocation for 1 slaves in 810678ns
> [12:20:56]W: [Step 8/8] I0217 12:20:56.856375 32514 master.cpp:5350] Sending 1 offers to framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:56]W: [Step 8/8] I0217 12:20:56.856827 32519 sched.cpp:877] Scheduler::resourceOffers took 115450ns
> [12:20:56]W: [Step 8/8] I0217 12:20:56.857096 32514 master.cpp:3673] Processing DECLINE call for offers: [ 0941887d-60f1-4ff3-85f0-5d19ffee8005-O2 ] for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:56]W: [Step 8/8] I0217 12:20:56.857484 32519 hierarchical.cpp:892] Recovered cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:56]W: [Step 8/8] I0217 12:20:56.857534 32519 hierarchical.cpp:929] Framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 filtered slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for 5secs
> [12:20:57]W: [Step 8/8] I0217 12:20:57.857295 32514 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:57]W: [Step 8/8] I0217 12:20:57.857364 32514 hierarchical.cpp:1403] No resources available to allocate!
> [12:20:57]W: [Step 8/8] I0217 12:20:57.857400 32514 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:57]W: [Step 8/8] I0217 12:20:57.857427 32514 hierarchical.cpp:1096] Performed allocation for 1 slaves in 636245ns
> [12:20:58]W: [Step 8/8] I0217 12:20:58.859124 32516 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:58]W: [Step 8/8] I0217 12:20:58.859192 32516 hierarchical.cpp:1403] No resources available to allocate!
> [12:20:58]W: [Step 8/8] I0217 12:20:58.859227 32516 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:58]W: [Step 8/8] I0217 12:20:58.859254 32516 hierarchical.cpp:1096] Performed allocation for 1 slaves in 666607ns
> [12:20:59]W: [Step 8/8] I0217 12:20:59.860666 32513 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:59]W: [Step 8/8] I0217 12:20:59.860735 32513 hierarchical.cpp:1403] No resources available to allocate!
> [12:20:59]W: [Step 8/8] I0217 12:20:59.860771 32513 hierarchical.cpp:1498] No inverse offers to send out!
> [12:20:59]W: [Step 8/8] I0217 12:20:59.860816 32513 hierarchical.cpp:1096] Performed allocation for 1 slaves in 687846ns
> [12:21:00]W: [Step 8/8] I0217 12:21:00.862351 32516 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:00]W: [Step 8/8] I0217 12:21:00.862418 32516 hierarchical.cpp:1403] No resources available to allocate!
> [12:21:00]W: [Step 8/8] I0217 12:21:00.862453 32516 hierarchical.cpp:1498] No inverse offers to send out!
> [12:21:00]W: [Step 8/8] I0217 12:21:00.862479 32516 hierarchical.cpp:1096] Performed allocation for 1 slaves in 636973ns
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864004 32514 hierarchical.cpp:1498] No inverse offers to send out!
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864064 32514 hierarchical.cpp:1096] Performed allocation for 1 slaves in 770250ns
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864317 32513 master.cpp:5350] Sending 1 offers to framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864737 32515 sched.cpp:877] Scheduler::resourceOffers took 70746ns
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864984 32513 master.cpp:3673] Processing DECLINE call for offers: [ 0941887d-60f1-4ff3-85f0-5d19ffee8005-O3 ] for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:21:01]W: [Step 8/8] I0217 12:21:01.865381 32515 hierarchical.cpp:892] Recovered cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:01]W: [Step 8/8] I0217 12:21:01.865432 32515 hierarchical.cpp:929] Framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 filtered slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for 5secs
> [12:21:02]W: [Step 8/8] I0217 12:21:02.865320 32514 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:02]W: [Step 8/8] I0217 12:21:02.865389 32514 hierarchical.cpp:1403] No resources available to allocate!
> [12:21:02]W: [Step 8/8] I0217 12:21:02.865425 32514 hierarchical.cpp:1498] No inverse offers to send out!
> [12:21:02]W: [Step 8/8] I0217 12:21:02.865453 32514 hierarchical.cpp:1096] Performed allocation for 1 slaves in 647129ns
> [12:21:03]W: [Step 8/8] I0217 12:21:03.866272 32517 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:03]W: [Step 8/8] I0217 12:21:03.866341 32517 hierarchical.cpp:1403] No resources available to allocate!
> [12:21:03]W: [Step 8/8] I0217 12:21:03.866377 32517 hierarchical.cpp:1498] No inverse offers to send out!
> [12:21:03]W: [Step 8/8] I0217 12:21:03.866405 32517 hierarchical.cpp:1096] Performed allocation for 1 slaves in 691378ns
> [12:21:04]W: [Step 8/8] I0217 12:21:04.867204 32513 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:04]W: [Step 8/8] I0217 12:21:04.867274 32513 hierarchical.cpp:1403] No resources available to allocate!
> [12:21:04]W: [Step 8/8] I0217 12:21:04.867311 32513 hierarchical.cpp:1498] No inverse offers to send out!
> [12:21:04]W: [Step 8/8] I0217 12:21:04.867336 32513 hierarchical.cpp:1096] Performed allocation for 1 slaves in 663817ns
> [12:21:05]W: [Step 8/8] I0217 12:21:05.868382 32518 hierarchical.cpp:1589] Filtered offer with cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:05]W: [Step 8/8] I0217 12:21:05.868449 32518 hierarchical.cpp:1403] No resources available to allocate!
> [12:21:05]W: [Step 8/8] I0217 12:21:05.868485 32518 hierarchical.cpp:1498] No inverse offers to send out!
> [12:21:05]W: [Step 8/8] I0217 12:21:05.868510 32518 hierarchical.cpp:1096] Performed allocation for 1 slaves in 635348ns
> [12:21:05]W: [Step 8/8] I0217 12:21:05.904500 32514 slave.cpp:4667] Querying resource estimator for oversubscribable resources
> [12:21:05]W: [Step 8/8] I0217 12:21:05.904728 32514 slave.cpp:4681] Received oversubscribable resources from the resource estimator
> [12:21:05]W: [Step 8/8] I0217 12:21:05.912817 32514 slave.cpp:3435] Received ping from slave-observer(49)@172.30.2.21:33004
> [12:21:06] : [Step 8/8] ../../src/tests/fetcher_cache_tests.cpp:916: Failure
> [12:21:06] : [Step 8/8] Failed to wait 15secs for awaitFinished(task.get())
> [12:21:06] : [Step 8/8] Begin listing sandboxes
> [12:21:06] : [Step 8/8] Begin listing sandbox `/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/latest`:
> [12:21:06] : [Step 8/8] Begin file contents of `stdout`:
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] Begin file contents of `stderr`:
> [12:21:06] : [Step 8/8] I0217 12:20:50.982002 3316 logging.cpp:193] Logging to STDERR
> [12:21:06] : [Step 8/8] I0217 12:20:50.982161 3316 fetcher.cpp:424] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY\/fetch\/slaves\/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0\/root","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-mesos-fetc_r-test-cmd","uri":{"cache":true,"executable":true,"extract":true,"value":"http:\/\/172.30.2.21:33004\/(2098)\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY\/slaves\/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0\/frameworks\/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000\/executors\/0\/runs\/31b2084a-64ff-479c-af79-1ee5370efb7e","user":"root"}
> [12:21:06] : [Step 8/8] I0217 12:20:50.987099 3316 fetcher.cpp:379] Fetching URI 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8] I0217 12:20:50.987119 3316 fetcher.cpp:349] Downloading into cache
> [12:21:06] : [Step 8/8] I0217 12:20:50.987370 3316 fetcher.cpp:187] Fetching URI 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd'
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853065 32498 sched.cpp:1907] Asked to stop the driver
> [12:21:06] : [Step 8/8] I0217 12:20:50.987406 3316 fetcher.cpp:134] Downloading resource from 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/fetch/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/root/c1-mesos-fetc_r-test-cmd'
> [12:21:06] : [Step 8/8] I0217 12:20:50.989434 3316 fetcher.cpp:289] Fetching from cache
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853193 32519 sched.cpp:1147] Stopping framework '0941887d-60f1-4ff3-85f0-5d19ffee8005-0000'
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853457 32513 master.cpp:5921] Processing TEARDOWN call for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:21:06] : [Step 8/8] I0217 12:20:50.989460 3316 fetcher.cpp:167] Copying resource with command:cp '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/fetch/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/root/c1-mesos-fetc_r-test-cmd' '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/mesos-fetcher-test-cmd'
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853485 32513 master.cpp:5933] Removing framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:21:06] : [Step 8/8] I0217 12:20:50.992434 3316 fetcher.cpp:456] Fetched 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8]
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853677 32518 hierarchical.cpp:375] Deactivated framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06] : [Step 8/8] End file
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853739 32517 slave.cpp:2078] Asked to shut down framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 by master@172.30.2.21:33004
> [12:21:06] : [Step 8/8] Begin file contents of `mesos-fetcher-test-cmd`:
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853782 32517 slave.cpp:2103] Shutting down framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06] : [Step 8/8] touch mesos-fetcher-test-cmd$1
> [12:21:06] : [Step 8/8] End file
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853806 32513 master.cpp:6445] Updating the state of task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (latest state: TASK_KILLED, status update state: TASK_KILLED)
> [12:21:06] : [Step 8/8] Begin file contents of `mesos-fetcher-test-cmd0`:
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853873 32517 slave.cpp:3920] Cleaning up executor '1' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 at executor(1)@172.30.2.21:58560
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] End sandbox
> [12:21:06] : [Step 8/8] Begin listing sandbox `/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/latest`:
> [12:21:06] : [Step 8/8] Begin file contents of `stdout`:
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] Begin file contents of `stderr`:
> [12:21:06] : [Step 8/8] I0217 12:20:51.914311 3373 logging.cpp:193] Logging to STDERR
> [12:21:06] : [Step 8/8] I0217 12:20:51.914465 3373 fetcher.cpp:424] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY\/fetch\/slaves\/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0\/root","items":[{"action":"RETRIEVE_FROM_CACHE","cache_filename":"c1-mesos-fetc_r-test-cmd","uri":{"cache":true,"executable":true,"extract":true,"value":"http:\/\/172.30.2.21:33004\/(2098)\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY\/slaves\/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0\/frameworks\/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000\/executors\/1\/runs\/cf539d3e-9c02-438a-b960-44bc00fb3530","user":"root"}
> [12:21:06] : [Step 8/8] I0217 12:20:51.919170 3373 fetcher.cpp:379] Fetching URI 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8] I0217 12:20:51.919193 3373 fetcher.cpp:289] Fetching from cache
> [12:21:06] : [Step 8/8] I0217 12:20:51.919214 3373 fetcher.cpp:167] Copying resource with command:cp '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/fetch/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/root/c1-mesos-fetc_r-test-cmd' '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8] I0217 12:20:51.922278 3373 fetcher.cpp:456] Fetched 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] Begin file contents of `mesos-fetcher-test-cmd`:
> [12:21:06] : [Step 8/8] touch mesos-fetcher-test-cmd$1
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] Begin file contents of `mesos-fetcher-test-cmd1`:
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] End sandbox
> [12:21:06] : [Step 8/8] End sandboxes
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854249 32518 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530' for gc 6.99999011384296days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854306 32519 hierarchical.cpp:892] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000], allocated: ) on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854307 32513 master.cpp:6511] Removing task 1 with resources cpus(*):1; mem(*):1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io)
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854398 32514 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1' for gc 6.99999011203556days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854470 32514 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530' for gc 6.9999901109037days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854552 32517 slave.cpp:4008] Cleaning up framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854557 32514 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1' for gc 6.99999011days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854769 32516 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000' for gc 6.99999010776889days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854815 32513 master.cpp:1025] Master terminating
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854843 32516 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000' for gc 6.99999010661926days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854859 32518 hierarchical.cpp:326] Removed framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06]W: [Step 8/8] I0217 12:21:06.855139 32518 hierarchical.cpp:505] Removed slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:21:06]W: [Step 8/8] I0217 12:21:06.855335 32519 slave.cpp:3481] master@172.30.2.21:33004 exited
> [12:21:06]W: [Step 8/8] W0217 12:21:06.855355 32519 slave.cpp:3484] Master disconnected! Waiting for a new master to be elected
> [12:21:06]W: [Step 8/8] I0217 12:21:06.859239 32515 slave.cpp:667] Slave terminating
> [12:21:06]W: [Step 8/8] I0217 12:21:06.881626 32512 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to the slave
> [12:21:06] : [Step 8/8] [ FAILED ] FetcherCacheHttpTest.HttpCachedSerialized (16052 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)