Bernd Mathiske created MESOS-4692:
-------------------------------------
Summary: 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
{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)
