[MESOS-4692] FetcherCacheHttpTest.HttpCachedSerialized flaky again. - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Accepted
Priority: Minor
Resolution: Unresolved
Affects Version/s: None
Fix Version/s: None
Component/s: fetcher, test
Labels:
- flaky
- test
Environment:

CentOS 7, plain

Description

[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)

Attachments

Issue Links

relates to

MESOS-5805 FetcherCacheTest.CachedCustomOutputFileWithSubdirectory is flaky

Accepted

Activity

People

Assignee:: Unassigned

Reporter:: Bernd Mathiske

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 17/Feb/16 13:14

Updated:: 19/Aug/19 12:38