[
https://issues.apache.org/jira/browse/MESOS-4692?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15150628#comment-15150628
]
Bernd Mathiske commented on MESOS-4692:
---------------------------------------
If so then not likely because of changes in fetcher code or fetcher cache test
code. This code has been stable except for how many tasks get run. Running less
tasks should not make this more flaky. No idea yet what is causing it this
time, though.
> FetcherCacheHttpTest.HttpCachedSerialized flaky again.
> ------------------------------------------------------
>
> Key: MESOS-4692
> URL: https://issues.apache.org/jira/browse/MESOS-4692
> Project: Mesos
> Issue Type: Bug
> Components: fetcher, test
> Environment: CentOS 7, plain
> Reporter: Bernd Mathiske
> Priority: Minor
> Labels: flaky, test
>
> {noformat}
> [12:20:50] : [Step 8/8] [ RUN ]
> FetcherCacheHttpTest.HttpCachedSerialized
> [12:20:50]W: [Step 8/8] I0217 12:20:50.842162 32498 leveldb.cpp:174] Opened
> db in 4.973489ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843670 32498 leveldb.cpp:181]
> Compacted db in 1.48087ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843709 32498 leveldb.cpp:196]
> Created db iterator in 15661ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843720 32498 leveldb.cpp:202] Seeked
> to beginning of db in 1401ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843729 32498 leveldb.cpp:271]
> Iterated through 0 keys in the db in 357ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843760 32498 replica.cpp:779]
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [12:20:50]W: [Step 8/8] I0217 12:20:50.844228 32513 recover.cpp:447]
> Starting replica recovery
> [12:20:50]W: [Step 8/8] I0217 12:20:50.844411 32513 recover.cpp:473]
> Replica is in EMPTY status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.845355 32516 replica.cpp:673]
> Replica in EMPTY status received a broadcasted recover request from
> (2089)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.845825 32518 recover.cpp:193]
> Received a recover response from a replica in EMPTY status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.846307 32517 recover.cpp:564]
> Updating replica status to STARTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.846789 32518 master.cpp:374] Master
> 0941887d-60f1-4ff3-85f0-5d19ffee8005 (ip-172-30-2-21.mesosphere.io) started
> on 172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.846810 32518 master.cpp:376] Flags
> at startup: --acls="" --allocation_interval="1secs"
> --allocator="HierarchicalDRF" --authenticate="true"
> --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/YFwdSN/credentials" --framework_sorter="drf"
> --help="false" --hostname_lookup="true" --http_authenticators="basic"
> --initialize_driver_logging="true" --log_auto_initialize="true"
> --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
> --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
> --quiet="false" --recovery_slave_removal_limit="100%"
> --registry="replicated_log" --registry_fetch_timeout="1mins"
> --registry_store_timeout="25secs" --registry_strict="true"
> --root_submissions="true" --slave_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/YFwdSN/master"
> --zk_session_timeout="10secs"
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847057 32518 master.cpp:421] Master
> only allowing authenticated frameworks to register
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847066 32518 master.cpp:426] Master
> only allowing authenticated slaves to register
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847072 32518 credentials.hpp:35]
> Loading credentials for authentication from '/tmp/YFwdSN/credentials'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847286 32518 master.cpp:466] Using
> default 'crammd5' authenticator
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847395 32518 master.cpp:535] Using
> default 'basic' HTTP authenticator
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847511 32518 master.cpp:569]
> Authorization enabled
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847642 32517 hierarchical.cpp:144]
> Initialized hierarchical allocator process
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847646 32519
> whitelist_watcher.cpp:77] No whitelist given
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847795 32514 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.368308ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847825 32514 replica.cpp:320]
> Persisted replica status to STARTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.848002 32512 recover.cpp:473]
> Replica is in STARTING status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849025 32516 master.cpp:1710] The
> newly elected leader is [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914115 32516 sched.cpp:382]
> Authenticating with master [email protected]: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
> [email protected]: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
> [email protected]: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 [email protected]:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915868 32512 sched.cpp:780] Sending
> SUBSCRIBE call to [email protected]: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
> [email protected]:33004
> [12:20:50]W: [Step 8/8] W0217 12:20:50.916038 32516 master.cpp:2285]
> Framework at [email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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
> '[email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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 [email protected]: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
> [email protected]: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 [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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
> [email protected]: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]
> [email protected]: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)
