[
https://issues.apache.org/jira/browse/MESOS-4692?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15150483#comment-15150483
]
haosdent commented on MESOS-4692:
---------------------------------
Is it because recently changes?
> FetcherCacheHttpTest.HttpCachedSerialized flaky again.
> ------------------------------------------------------
>
> Key: MESOS-4692
> URL: https://issues.apache.org/jira/browse/MESOS-4692
> Project: Mesos
> Issue Type: Bug
> Components: fetcher, test
> Environment: CentOS 7, plain
> Reporter: Bernd Mathiske
> Priority: Minor
> Labels: flaky, test
>
> {noformat}
> [12:20:50] : [Step 8/8] [ RUN ]
> FetcherCacheHttpTest.HttpCachedSerialized
> [12:20:50]W: [Step 8/8] I0217 12:20:50.842162 32498 leveldb.cpp:174] Opened
> db in 4.973489ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843670 32498 leveldb.cpp:181]
> Compacted db in 1.48087ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843709 32498 leveldb.cpp:196]
> Created db iterator in 15661ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843720 32498 leveldb.cpp:202] Seeked
> to beginning of db in 1401ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843729 32498 leveldb.cpp:271]
> Iterated through 0 keys in the db in 357ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.843760 32498 replica.cpp:779]
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [12:20:50]W: [Step 8/8] I0217 12:20:50.844228 32513 recover.cpp:447]
> Starting replica recovery
> [12:20:50]W: [Step 8/8] I0217 12:20:50.844411 32513 recover.cpp:473]
> Replica is in EMPTY status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.845355 32516 replica.cpp:673]
> Replica in EMPTY status received a broadcasted recover request from
> (2089)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.845825 32518 recover.cpp:193]
> Received a recover response from a replica in EMPTY status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.846307 32517 recover.cpp:564]
> Updating replica status to STARTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.846789 32518 master.cpp:374] Master
> 0941887d-60f1-4ff3-85f0-5d19ffee8005 (ip-172-30-2-21.mesosphere.io) started
> on 172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.846810 32518 master.cpp:376] Flags
> at startup: --acls="" --allocation_interval="1secs"
> --allocator="HierarchicalDRF" --authenticate="true"
> --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/YFwdSN/credentials" --framework_sorter="drf"
> --help="false" --hostname_lookup="true" --http_authenticators="basic"
> --initialize_driver_logging="true" --log_auto_initialize="true"
> --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
> --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
> --quiet="false" --recovery_slave_removal_limit="100%"
> --registry="replicated_log" --registry_fetch_timeout="1mins"
> --registry_store_timeout="25secs" --registry_strict="true"
> --root_submissions="true" --slave_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/YFwdSN/master"
> --zk_session_timeout="10secs"
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847057 32518 master.cpp:421] Master
> only allowing authenticated frameworks to register
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847066 32518 master.cpp:426] Master
> only allowing authenticated slaves to register
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847072 32518 credentials.hpp:35]
> Loading credentials for authentication from '/tmp/YFwdSN/credentials'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847286 32518 master.cpp:466] Using
> default 'crammd5' authenticator
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847395 32518 master.cpp:535] Using
> default 'basic' HTTP authenticator
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847511 32518 master.cpp:569]
> Authorization enabled
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847642 32517 hierarchical.cpp:144]
> Initialized hierarchical allocator process
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847646 32519
> whitelist_watcher.cpp:77] No whitelist given
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847795 32514 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.368308ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.847825 32514 replica.cpp:320]
> Persisted replica status to STARTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.848002 32512 recover.cpp:473]
> Replica is in STARTING status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849025 32516 master.cpp:1710] The
> newly elected leader is master@172.30.2.21:33004 with id
> 0941887d-60f1-4ff3-85f0-5d19ffee8005
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849047 32516 master.cpp:1723]
> Elected as the leading master!
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849061 32516 master.cpp:1468]
> Recovering from registrar
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849055 32515 replica.cpp:673]
> Replica in STARTING status received a broadcasted recover request from
> (2091)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849172 32518 registrar.cpp:307]
> Recovering registrar
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849376 32513 recover.cpp:193]
> Received a recover response from a replica in STARTING status
> [12:20:50]W: [Step 8/8] I0217 12:20:50.849895 32517 recover.cpp:564]
> Updating replica status to VOTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851344 32512 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.29974ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851366 32512 replica.cpp:320]
> Persisted replica status to VOTING
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851455 32519 recover.cpp:578]
> Successfully joined the Paxos group
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851603 32519 recover.cpp:462]
> Recover process terminated
> [12:20:50]W: [Step 8/8] I0217 12:20:50.851975 32517 log.cpp:659] Attempting
> to start the writer
> [12:20:50]W: [Step 8/8] I0217 12:20:50.852934 32516 replica.cpp:493]
> Replica received implicit promise request from (2092)@172.30.2.21:33004 with
> proposal 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.854387 32516 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.421154ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.854408 32516 replica.cpp:342]
> Persisted promised to 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.854923 32517 coordinator.cpp:238]
> Coordinator attempting to fill missing positions
> [12:20:50]W: [Step 8/8] I0217 12:20:50.855963 32515 replica.cpp:388]
> Replica received explicit promise request from (2093)@172.30.2.21:33004 for
> position 0 with proposal 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.857283 32515 leveldb.cpp:341]
> Persisting action (8 bytes) to leveldb took 1.287784ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.857306 32515 replica.cpp:712]
> Persisted action at 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.858182 32518 replica.cpp:537]
> Replica received write request for position 0 from (2094)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.858227 32518 leveldb.cpp:436]
> Reading position from leveldb took 20803ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.859516 32518 leveldb.cpp:341]
> Persisting action (14 bytes) to leveldb took 1.260506ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.859539 32518 replica.cpp:712]
> Persisted action at 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.860041 32513 replica.cpp:691]
> Replica received learned notice for position 0 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.863092 32513 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 3.022825ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.863114 32513 replica.cpp:712]
> Persisted action at 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.863129 32513 replica.cpp:697]
> Replica learned NOP action at position 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.863597 32517 log.cpp:675] Writer
> started with ending position 0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.864405 32515 leveldb.cpp:436]
> Reading position from leveldb took 21575ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.865149 32515 registrar.cpp:340]
> Successfully fetched the registry (0B) in 15.93984ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.865234 32515 registrar.cpp:439]
> Applied 1 operations in 20551ns; attempting to update the 'registry'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.865816 32518 log.cpp:683] Attempting
> to append 206 bytes to the log
> [12:20:50]W: [Step 8/8] I0217 12:20:50.865921 32519 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.866474 32513 replica.cpp:537]
> Replica received write request for position 1 from (2095)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.873576 32513 leveldb.cpp:341]
> Persisting action (225 bytes) to leveldb took 7.073358ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.873600 32513 replica.cpp:712]
> Persisted action at 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.874136 32512 replica.cpp:691]
> Replica received learned notice for position 1 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.876266 32512 leveldb.cpp:341]
> Persisting action (227 bytes) to leveldb took 2.102934ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.876288 32512 replica.cpp:712]
> Persisted action at 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.876303 32512 replica.cpp:697]
> Replica learned APPEND action at position 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877070 32517 registrar.cpp:484]
> Successfully updated the 'registry' in 11.782912ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877202 32517 registrar.cpp:370]
> Successfully recovered registrar
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877279 32519 log.cpp:702] Attempting
> to truncate the log to 1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877374 32512 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877605 32513 master.cpp:1520]
> Recovered 0 slaves from the Registry (167B) ; allowing 10mins for slaves to
> re-register
> [12:20:50]W: [Step 8/8] I0217 12:20:50.877636 32518 hierarchical.cpp:171]
> Skipping recovery of hierarchical allocator: nothing to recover
> [12:20:50]W: [Step 8/8] I0217 12:20:50.878103 32512 replica.cpp:537]
> Replica received write request for position 2 from (2096)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.879442 32512 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.313099ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.879464 32512 replica.cpp:712]
> Persisted action at 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.879961 32513 replica.cpp:691]
> Replica received learned notice for position 2 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.881382 32513 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.393701ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.881433 32513 leveldb.cpp:399]
> Deleting ~1 keys from leveldb took 27209ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.881448 32513 replica.cpp:712]
> Persisted action at 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.881463 32513 replica.cpp:697]
> Replica learned TRUNCATE action at position 2
> [12:20:50]W: [Step 8/8] I0217 12:20:50.888675 32498 containerizer.cpp:143]
> Using isolation: posix/cpu,posix/mem,filesystem/posix
> [12:20:50]W: [Step 8/8] I0217 12:20:50.895370 32498 linux_launcher.cpp:101]
> Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
> [12:20:50]W: [Step 8/8] I0217 12:20:50.898412 32516 slave.cpp:192] Slave
> started on 52)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.898428 32516 slave.cpp:193] Flags at
> startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
> --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
> --cgroups_root="mesos" --container_disk_watch_interval="15secs"
> --containerizers="mesos"
> --credential="/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
> --docker_puller_timeout="60" --docker_registry="https://registry-1.docker.io";
> --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
> --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="true"
> --hostname_lookup="true" --image_provisioner_backend="copy"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs"
> --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false"
> --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ms" --resources="cpus:1000;mem:1000"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true" --systemd_enable_support="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY"
> [12:20:50]W: [Step 8/8] I0217 12:20:50.898826 32516 credentials.hpp:83]
> Loading credential for authentication from
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/credential'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.898960 32516 slave.cpp:323] Slave
> using credential for: test-principal
> [12:20:50]W: [Step 8/8] I0217 12:20:50.899092 32516 resources.cpp:564]
> Parsing resources as JSON failed: cpus:1000;mem:1000
> [12:20:50]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:50]W: [Step 8/8] I0217 12:20:50.899408 32516 slave.cpp:463] Slave
> resources: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.899472 32516 slave.cpp:471] Slave
> attributes: [ ]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.899482 32516 slave.cpp:476] Slave
> hostname: ip-172-30-2-21.mesosphere.io
> [12:20:50]W: [Step 8/8] I0217 12:20:50.900118 32519 state.cpp:58]
> Recovering state from
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.900372 32516
> status_update_manager.cpp:200] Recovering status update manager
> [12:20:50]W: [Step 8/8] I0217 12:20:50.900516 32516 containerizer.cpp:390]
> Recovering containerizer
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902184 32512 provisioner.cpp:245]
> Provisioner recovery complete
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902458 32514 slave.cpp:4495]
> Finished recovery
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902740 32514 slave.cpp:4667]
> Querying resource estimator for oversubscribable resources
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902928 32514 slave.cpp:795] New
> master detected at master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902943 32516
> status_update_manager.cpp:174] Pausing sending status updates
> [12:20:50]W: [Step 8/8] I0217 12:20:50.902992 32514 slave.cpp:858]
> Authenticating with master master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903007 32514 slave.cpp:863] Using
> default CRAM-MD5 authenticatee
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903121 32514 slave.cpp:831]
> Detecting new master
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903167 32517 authenticatee.cpp:121]
> Creating new client SASL connection
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903270 32514 slave.cpp:4681]
> Received oversubscribable resources from the resource estimator
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903493 32518 master.cpp:5521]
> Authenticating slave(52)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903594 32519 authenticator.cpp:413]
> Starting authentication session for
> crammd5_authenticatee(150)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.903794 32516 authenticator.cpp:98]
> Creating new server SASL connection
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904034 32517 authenticatee.cpp:212]
> Received SASL authentication mechanisms: CRAM-MD5
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904057 32517 authenticatee.cpp:238]
> Attempting to authenticate with mechanism 'CRAM-MD5'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904134 32517 authenticator.cpp:203]
> Received SASL authentication start
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904180 32517 authenticator.cpp:325]
> Authentication requires more steps
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904250 32517 authenticatee.cpp:258]
> Received SASL authentication step
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904351 32517 authenticator.cpp:231]
> Received SASL authentication step
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904376 32517 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-21.mesosphere.io' server FQDN: 'ip-172-30-2-21.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904386 32517 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904414 32517 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904433 32517 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-21.mesosphere.io' server FQDN: 'ip-172-30-2-21.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904440 32517 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904445 32517 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904456 32517 authenticator.cpp:317]
> Authentication success
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904533 32513 authenticatee.cpp:298]
> Authentication success
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904567 32516 master.cpp:5551]
> Successfully authenticated principal 'test-principal' at
> slave(52)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904624 32515 authenticator.cpp:431]
> Authentication session cleanup for
> crammd5_authenticatee(150)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904799 32512 slave.cpp:926]
> Successfully authenticated with master master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.904908 32512 slave.cpp:1320] Will
> retry registration in 14.571781ms if necessary
> [12:20:50]W: [Step 8/8] I0217 12:20:50.905035 32515 master.cpp:4235]
> Registering slave at slave(52)@172.30.2.21:33004
> (ip-172-30-2-21.mesosphere.io) with id 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.905369 32513 registrar.cpp:439]
> Applied 1 operations in 45856ns; attempting to update the 'registry'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.905974 32514 log.cpp:683] Attempting
> to append 391 bytes to the log
> [12:20:50]W: [Step 8/8] I0217 12:20:50.906070 32517 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.906674 32517 replica.cpp:537]
> Replica received write request for position 3 from (2113)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.908289 32517 leveldb.cpp:341]
> Persisting action (410 bytes) to leveldb took 1.586609ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.908313 32517 replica.cpp:712]
> Persisted action at 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.908833 32517 replica.cpp:691]
> Replica received learned notice for position 3 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.910802 32517 leveldb.cpp:341]
> Persisting action (412 bytes) to leveldb took 1.947096ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.910825 32517 replica.cpp:712]
> Persisted action at 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.910840 32517 replica.cpp:697]
> Replica learned APPEND action at position 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.911844 32516 registrar.cpp:484]
> Successfully updated the 'registry' in 6.420992ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912017 32519 log.cpp:702] Attempting
> to truncate the log to 3
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912127 32515 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 4
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912530 32512 slave.cpp:3435]
> Received ping from slave-observer(49)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912617 32518 master.cpp:4303]
> Registered slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at
> slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io) with cpus(*):1000;
> mem(*):1000; disk(*):4090; ports(*):[31000-32000]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912853 32512 slave.cpp:970]
> Registered with master master@172.30.2.21:33004; given slave ID
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912856 32519 hierarchical.cpp:473]
> Added slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> (ip-172-30-2-21.mesosphere.io) with cpus(*):1000; mem(*):1000; disk(*):4090;
> ports(*):[31000-32000] (allocated: )
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912878 32512 fetcher.cpp:81]
> Clearing fetcher cache
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912895 32515 replica.cpp:537]
> Replica received write request for position 4 from (2114)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912968 32519 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:20:50]W: [Step 8/8] I0217 12:20:50.912999 32519 hierarchical.cpp:1116]
> Performed allocation for slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 in
> 114429ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913094 32514
> status_update_manager.cpp:181] Resuming sending status updates
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913276 32512 slave.cpp:993]
> Checkpointing SlaveInfo to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/slave.info'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913524 32512 slave.cpp:1029]
> Forwarding total oversubscribed resources
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913640 32512 master.cpp:4644]
> Received update of slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at
> slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io) with total
> oversubscribed resources
> [12:20:50]W: [Step 8/8] I0217 12:20:50.913667 32498 sched.cpp:222] Version:
> 0.27.1
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914054 32516 sched.cpp:326] New
> master detected at master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914115 32516 sched.cpp:382]
> Authenticating with master master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914129 32516 sched.cpp:389] Using
> default CRAM-MD5 authenticatee
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914122 32518 hierarchical.cpp:531]
> Slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 (ip-172-30-2-21.mesosphere.io)
> updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000;
> disk(*):4090; ports(*):[31000-32000], allocated: )
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914211 32518 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914229 32518 hierarchical.cpp:1116]
> Performed allocation for slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 in
> 79633ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914273 32519 authenticatee.cpp:121]
> Creating new client SASL connection
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914374 32515 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.451028ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914397 32515 replica.cpp:712]
> Persisted action at 4
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914518 32516 master.cpp:5521]
> Authenticating
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914615 32518 authenticator.cpp:413]
> Starting authentication session for
> crammd5_authenticatee(151)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914798 32512 authenticator.cpp:98]
> Creating new server SASL connection
> [12:20:50]W: [Step 8/8] I0217 12:20:50.914968 32518 replica.cpp:691]
> Replica received learned notice for position 4 from @0.0.0.0:0
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915048 32519 authenticatee.cpp:212]
> Received SASL authentication mechanisms: CRAM-MD5
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915069 32519 authenticatee.cpp:238]
> Attempting to authenticate with mechanism 'CRAM-MD5'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915146 32519 authenticator.cpp:203]
> Received SASL authentication start
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915176 32519 authenticator.cpp:325]
> Authentication requires more steps
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915251 32519 authenticatee.cpp:258]
> Received SASL authentication step
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915354 32513 authenticator.cpp:231]
> Received SASL authentication step
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915385 32513 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-21.mesosphere.io' server FQDN: 'ip-172-30-2-21.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915402 32513 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915438 32513 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915475 32513 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-21.mesosphere.io' server FQDN: 'ip-172-30-2-21.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915490 32513 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915503 32513 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915520 32513 authenticator.cpp:317]
> Authentication success
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915606 32517 authenticatee.cpp:298]
> Authentication success
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915654 32519 master.cpp:5551]
> Successfully authenticated principal 'test-principal' at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915695 32514 authenticator.cpp:431]
> Authentication session cleanup for
> crammd5_authenticatee(151)@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915853 32512 sched.cpp:471]
> Successfully authenticated with master master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915868 32512 sched.cpp:780] Sending
> SUBSCRIBE call to master@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.915936 32512 sched.cpp:813] Will
> retry registration in 1.47153444secs if necessary
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916014 32516 master.cpp:2278]
> Received SUBSCRIBE call for framework 'default' at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] W0217 12:20:50.916038 32516 master.cpp:2285]
> Framework at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916072 32516 master.cpp:1749]
> Authorizing framework principal '' to receive offers for role '*'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916290 32519 master.cpp:2349]
> Subscribing framework default with checkpointing enabled and capabilities [ ]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916435 32518 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.438664ms
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916496 32518 leveldb.cpp:399]
> Deleting ~2 keys from leveldb took 38041ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916518 32518 replica.cpp:712]
> Persisted action at 4
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916543 32518 replica.cpp:697]
> Replica learned TRUNCATE action at position 4
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916612 32516 hierarchical.cpp:265]
> Added framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916674 32519 sched.cpp:707]
> Framework registered with 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.916707 32519 sched.cpp:721]
> Scheduler::registered took 15213ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.917186 32516 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:50]W: [Step 8/8] I0217 12:20:50.917228 32516 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 591295ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.917448 32515 master.cpp:5350]
> Sending 1 offers to framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.917795 32518 sched.cpp:877]
> Scheduler::resourceOffers took 105618ns
> [12:20:50]W: [Step 8/8] I0217 12:20:50.918026 32498 resources.cpp:564]
> Parsing resources as JSON failed: cpus:1;mem:1
> [12:20:50]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:50]W: [Step 8/8] I0217 12:20:50.918958 32518 master.cpp:3136]
> Processing ACCEPT call for offers: [ 0941887d-60f1-4ff3-85f0-5d19ffee8005-O0
> ] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at
> slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io) for framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:50]W: [Step 8/8] I0217 12:20:50.918993 32518 master.cpp:2823]
> Authorizing framework principal '' to launch task 0 as user 'root'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.919986 32516 master.hpp:176] Adding
> task 0 with resources cpus(*):1; mem(*):1 on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 (ip-172-30-2-21.mesosphere.io)
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920064 32516 master.cpp:3621]
> Launching task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> with resources cpus(*):1; mem(*):1 on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004
> (ip-172-30-2-21.mesosphere.io)
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920297 32514 slave.cpp:1360] Got
> assigned task 0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920392 32514 slave.cpp:5201]
> Checkpointing FrameworkInfo to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/framework.info'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920485 32515 hierarchical.cpp:892]
> Recovered cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000]
> (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000],
> allocated: cpus(*):1; mem(*):1) on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920526 32515 hierarchical.cpp:929]
> Framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 filtered slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for 5secs
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920642 32514 slave.cpp:5212]
> Checkpointing framework pid
> 'scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004' to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/framework.pid'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.920826 32514 resources.cpp:564]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:20:50]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:50]W: [Step 8/8] I0217 12:20:50.921176 32514 slave.cpp:1479]
> Launching task 0 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.921234 32514 resources.cpp:564]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:20:50]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:50]W: [Step 8/8] I0217 12:20:50.921684 32514 paths.cpp:472] Trying
> to chown
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e'
> to user 'root'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.925053 32514 slave.cpp:5653]
> Checkpointing ExecutorInfo to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/executor.info'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.925425 32514 slave.cpp:5281]
> Launching executor 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> with resources cpus(*):0.1; mem(*):32 in work directory
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.925781 32519 containerizer.cpp:649]
> Starting container '31b2084a-64ff-479c-af79-1ee5370efb7e' for executor '0' of
> framework '0941887d-60f1-4ff3-85f0-5d19ffee8005-0000'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.925837 32514 slave.cpp:5676]
> Checkpointing TaskInfo to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/tasks/0/task.info'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.926038 32514 slave.cpp:1697] Queuing
> task '0' for executor '0' of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:50]W: [Step 8/8] I0217 12:20:50.926115 32514 slave.cpp:748]
> Successfully attached file
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.929641 32517 linux_launcher.cpp:304]
> Cloning child process with flags =
> [12:20:50]W: [Step 8/8] I0217 12:20:50.931422 32517 containerizer.cpp:1003]
> Checkpointing executor's forked pid 3300 to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/pids/forked.pid'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.932808 32518 fetcher.cpp:304]
> Starting to fetch URIs for container: 31b2084a-64ff-479c-af79-1ee5370efb7e,
> directory:
> /tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e
> [12:20:50]W: [Step 8/8] I0217 12:20:50.935529 32518 fetcher.cpp:893]
> Created cache entry
> 'root@http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd' with file:
> c1-mesos-fetc_r-test-cmd
> [12:20:50]W: [Step 8/8] I0217 12:20:50.936242 32515 fetcher.cpp:252]
> Fetching size for URI: http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd
> [12:20:50]W: [Step 8/8] I0217 12:20:50.937364 32516 process.cpp:3141]
> Handling HTTP event for process '(2098)' with path:
> '/(2098)/mesos-fetcher-test-cmd'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.937711 32513 process.cpp:1184]
> Sending file at
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
> with length 30
> [12:20:50]W: [Step 8/8] I0217 12:20:50.938225 32516 fetcher.cpp:668]
> Claiming fetcher cache space for:
> root@http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd
> [12:20:50]W: [Step 8/8] I0217 12:20:50.938241 32516 fetcher.cpp:1113]
> Claimed cache space: 30B, now using: 30B
> [12:20:50] : [Step 8/8] HTTP/1.1 200 OK
> [12:20:50] : [Step 8/8] Date: Wed, 17 Feb 2016 12:20:50 GMT
> [12:20:50] : [Step 8/8] Content-Length: 30
> [12:20:50] : [Step 8/8]
> [12:20:50]W: [Step 8/8] I0217 12:20:50.942404 32519 fetcher.cpp:766]
> Fetching URIs using command
> '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.988598 32514 process.cpp:3141]
> Handling HTTP event for process '(2098)' with path:
> '/(2098)/mesos-fetcher-test-cmd'
> [12:20:50]W: [Step 8/8] I0217 12:20:50.988895 32517 process.cpp:1184]
> Sending file at
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
> with length 30
> [12:20:51]W: [Step 8/8] I0217 12:20:51.026612 32514 fetcher.cpp:1125]
> Released cache space: 0B, now using: 30B
> [12:20:51]W: [Step 8/8] WARNING: Logging before InitGoogleLogging() is
> written to STDERR
> [12:20:51]W: [Step 8/8] I0217 12:20:51.072054 3300 process.cpp:994]
> libprocess is initialized on 172.30.2.21:56710 for 8 cpus
> [12:20:51]W: [Step 8/8] I0217 12:20:51.072721 3300 logging.cpp:193]
> Logging to STDERR
> [12:20:51]W: [Step 8/8] I0217 12:20:51.074179 3300 exec.cpp:134] Version:
> 0.27.1
> [12:20:51]W: [Step 8/8] I0217 12:20:51.079038 3348 exec.cpp:184] Executor
> started at: executor(1)@172.30.2.21:56710 with pid 3300
> [12:20:51]W: [Step 8/8] I0217 12:20:51.080653 32512 slave.cpp:2642] Got
> registration for executor '0' of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.081066 32512 slave.cpp:2728]
> Checkpointing executor pid 'executor(1)@172.30.2.21:56710' to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/pids/libprocess.pid'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.082375 3347 exec.cpp:208] Executor
> registered on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.082581 32514 slave.cpp:1862] Sending
> queued task '0' to executor '0' of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 at executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.083726 3347 exec.cpp:220]
> Executor::registered took 223218ns
> [12:20:51] : [Step 8/8] Registered executor on ip-172-30-2-21.mesosphere.io
> [12:20:51] : [Step 8/8] Starting task 0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.083962 3347 exec.cpp:295] Executor
> asked to run task '0'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.084045 3347 exec.cpp:304]
> Executor::launchTask took 64910ns
> [12:20:51] : [Step 8/8] Forked command at 3354
> [12:20:51] : [Step 8/8] sh -c './mesos-fetcher-test-cmd 0'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.086417 3346 exec.cpp:517] Executor
> sending status update TASK_RUNNING (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.087159 32512 slave.cpp:3001]
> Handling status update TASK_RUNNING (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.087456 32512
> status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.087486 32512
> status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.087827 32512
> status_update_manager.cpp:824] Checkpointing UPDATE for status update
> TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.091712 32512
> status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to the slave
> [12:20:51]W: [Step 8/8] I0217 12:20:51.091940 32517 slave.cpp:3353]
> Forwarding the update TASK_RUNNING (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to master@172.30.2.21:33004
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092116 32517 slave.cpp:3247] Status
> update manager successfully handled status update TASK_RUNNING (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092162 32517 slave.cpp:3263] Sending
> acknowledgement for status update TASK_RUNNING (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092222 32516 master.cpp:4789] Status
> update TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0
> of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004
> (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092257 32516 master.cpp:4837]
> Forwarding status update TASK_RUNNING (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092391 32516 master.cpp:6445]
> Updating the state of task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092623 32519 sched.cpp:985]
> Scheduler::statusUpdate took 118299ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092649 3347 exec.cpp:341] Executor
> received status update acknowledgement 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078
> for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.092922 32518 master.cpp:3947]
> Processing ACKNOWLEDGE call 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078 for task 0
> of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004 on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.093154 32518
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.093262 32518
> status_update_manager.cpp:824] Checkpointing ACK for status update
> TASK_RUNNING (UUID: 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.096221 32519 slave.cpp:2411] Status
> update manager successfully handled status update acknowledgement (UUID:
> 50fcc7ae-d4e9-4ca9-a962-b33eb5fd2078) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51] : [Step 8/8] Command exited with status 0 (pid: 3354)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.187614 3350 exec.cpp:517] Executor
> sending status update TASK_FINISHED (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.188201 32513 slave.cpp:3001]
> Handling status update TASK_FINISHED (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.188304 32513 slave.cpp:5591]
> Terminating task 0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.189271 32516
> status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.189324 32516
> status_update_manager.cpp:824] Checkpointing UPDATE for status update
> TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.192682 32516
> status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to the slave
> [12:20:51]W: [Step 8/8] I0217 12:20:51.192920 32518 slave.cpp:3353]
> Forwarding the update TASK_FINISHED (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to master@172.30.2.21:33004
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193073 32518 slave.cpp:3247] Status
> update manager successfully handled status update TASK_FINISHED (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193120 32518 slave.cpp:3263] Sending
> acknowledgement for status update TASK_FINISHED (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to executor(1)@172.30.2.21:56710
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193233 32519 master.cpp:4789] Status
> update TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0
> of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004
> (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193277 32519 master.cpp:4837]
> Forwarding status update TASK_FINISHED (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193434 32519 master.cpp:6445]
> Updating the state of task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (latest state: TASK_FINISHED,
> status update state: TASK_FINISHED)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193640 3348 exec.cpp:341] Executor
> received status update acknowledgement a4298b07-b8d3-4bc3-8599-3739f6da2813
> for task 0 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193684 32514 sched.cpp:985]
> Scheduler::statusUpdate took 142687ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193855 32516 hierarchical.cpp:892]
> Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000;
> disk(*):4090; ports(*):[31000-32000], allocated: ) on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193936 32519 master.cpp:3947]
> Processing ACKNOWLEDGE call a4298b07-b8d3-4bc3-8599-3739f6da2813 for task 0
> of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004 on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.193979 32519 master.cpp:6511]
> Removing task 0 with resources cpus(*):1; mem(*):1 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004
> (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.194285 32513
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.194447 32513
> status_update_manager.cpp:824] Checkpointing ACK for status update
> TASK_FINISHED (UUID: a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.197284 32513
> status_update_manager.cpp:528] Cleaning up status update stream for task 0 of
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.197531 32518 slave.cpp:2411] Status
> update manager successfully handled status update acknowledgement (UUID:
> a4298b07-b8d3-4bc3-8599-3739f6da2813) for task 0 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.197564 32518 slave.cpp:5632]
> Completing task 0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.849397 32514 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:51]W: [Step 8/8] I0217 12:20:51.849462 32514 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 825551ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.849715 32518 master.cpp:5350]
> Sending 1 offers to framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:51]W: [Step 8/8] I0217 12:20:51.850183 32517 sched.cpp:877]
> Scheduler::resourceOffers took 109793ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.850472 32498 resources.cpp:564]
> Parsing resources as JSON failed: cpus:1;mem:1
> [12:20:51]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:51]W: [Step 8/8] I0217 12:20:51.851595 32517 master.cpp:3136]
> Processing ACCEPT call for offers: [ 0941887d-60f1-4ff3-85f0-5d19ffee8005-O1
> ] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at
> slave(52)@172.30.2.21:33004 (ip-172-30-2-21.mesosphere.io) for framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:51]W: [Step 8/8] I0217 12:20:51.851634 32517 master.cpp:2823]
> Authorizing framework principal '' to launch task 1 as user 'root'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.852676 32514 master.hpp:176] Adding
> task 1 with resources cpus(*):1; mem(*):1 on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.852761 32514 master.cpp:3621]
> Launching task 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> with resources cpus(*):1; mem(*):1 on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004
> (ip-172-30-2-21.mesosphere.io)
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853035 32519 slave.cpp:1360] Got
> assigned task 1 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853128 32519 resources.cpp:564]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:20:51]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853227 32513 hierarchical.cpp:892]
> Recovered cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000]
> (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000],
> allocated: cpus(*):1; mem(*):1) on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853272 32513 hierarchical.cpp:929]
> Framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 filtered slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for 5secs
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853509 32519 slave.cpp:1479]
> Launching task 1 for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.853567 32519 resources.cpp:564]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [12:20:51]W: [Step 8/8] Trying semicolon-delimited string format instead
> [12:20:51]W: [Step 8/8] I0217 12:20:51.854045 32519 paths.cpp:472] Trying
> to chown
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530'
> to user 'root'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.857623 32519 slave.cpp:5653]
> Checkpointing ExecutorInfo to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/executor.info'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858033 32519 slave.cpp:5281]
> Launching executor 1 of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> with resources cpus(*):0.1; mem(*):32 in work directory
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858469 32514 containerizer.cpp:649]
> Starting container 'cf539d3e-9c02-438a-b960-44bc00fb3530' for executor '1' of
> framework '0941887d-60f1-4ff3-85f0-5d19ffee8005-0000'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858515 32519 slave.cpp:5676]
> Checkpointing TaskInfo to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/tasks/1/task.info'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858726 32519 slave.cpp:1697] Queuing
> task '1' for executor '1' of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.858824 32519 slave.cpp:748]
> Successfully attached file
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.862714 32514 linux_launcher.cpp:304]
> Cloning child process with flags =
> [12:20:51]W: [Step 8/8] I0217 12:20:51.864408 32514 containerizer.cpp:1003]
> Checkpointing executor's forked pid 3357 to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/pids/forked.pid'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.866123 32516 fetcher.cpp:304]
> Starting to fetch URIs for container: cf539d3e-9c02-438a-b960-44bc00fb3530,
> directory:
> /tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530
> [12:20:51]W: [Step 8/8] I0217 12:20:51.874403 32516 fetcher.cpp:766]
> Fetching URIs using command
> '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
> [12:20:51]W: [Step 8/8] WARNING: Logging before InitGoogleLogging() is
> written to STDERR
> [12:20:51]W: [Step 8/8] I0217 12:20:51.977840 3357 process.cpp:994]
> libprocess is initialized on 172.30.2.21:58560 for 8 cpus
> [12:20:51]W: [Step 8/8] I0217 12:20:51.978535 3357 logging.cpp:193]
> Logging to STDERR
> [12:20:51]W: [Step 8/8] I0217 12:20:51.979935 3357 exec.cpp:134] Version:
> 0.27.1
> [12:20:51]W: [Step 8/8] I0217 12:20:51.984833 3402 exec.cpp:184] Executor
> started at: executor(1)@172.30.2.21:58560 with pid 3357
> [12:20:51]W: [Step 8/8] I0217 12:20:51.986431 32519 slave.cpp:2642] Got
> registration for executor '1' of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:58560
> [12:20:51]W: [Step 8/8] I0217 12:20:51.986873 32519 slave.cpp:2728]
> Checkpointing executor pid 'executor(1)@172.30.2.21:58560' to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/pids/libprocess.pid'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.988216 3405 exec.cpp:208] Executor
> registered on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:20:51]W: [Step 8/8] I0217 12:20:51.988230 32514 slave.cpp:1862] Sending
> queued task '1' to executor '1' of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 at executor(1)@172.30.2.21:58560
> [12:20:51] : [Step 8/8] Registered executor on ip-172-30-2-21.mesosphere.io
> [12:20:51] : [Step 8/8] Starting task 1
> [12:20:51]W: [Step 8/8] I0217 12:20:51.989580 3405 exec.cpp:220]
> Executor::registered took 221432ns
> [12:20:51]W: [Step 8/8] I0217 12:20:51.989831 3405 exec.cpp:295] Executor
> asked to run task '1'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.989915 3405 exec.cpp:304]
> Executor::launchTask took 65747ns
> [12:20:51] : [Step 8/8] Forked command at 3411
> [12:20:51] : [Step 8/8] sh -c './mesos-fetcher-test-cmd 1'
> [12:20:51]W: [Step 8/8] I0217 12:20:51.991230 3405 exec.cpp:517] Executor
> sending status update TASK_RUNNING (UUID:
> 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.991989 32516 slave.cpp:3001]
> Handling status update TASK_RUNNING (UUID:
> 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:58560
> [12:20:51]W: [Step 8/8] I0217 12:20:51.992316 32512
> status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
> 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.992352 32512
> status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:51]W: [Step 8/8] I0217 12:20:51.992666 32512
> status_update_manager.cpp:824] Checkpointing UPDATE for status update
> TASK_RUNNING (UUID: 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:52] : [Step 8/8] Command exited with status 0 (pid: 3411)
> [12:20:52]W: [Step 8/8] I0217 12:20:52.092772 3405 exec.cpp:517] Executor
> sending status update TASK_FINISHED (UUID:
> e4e9ef2e-83c8-4b5b-9cd9-f20c2f2ea474) for task 1 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:52]W: [Step 8/8] I0217 12:20:52.093408 32519 slave.cpp:3001]
> Handling status update TASK_FINISHED (UUID:
> e4e9ef2e-83c8-4b5b-9cd9-f20c2f2ea474) for task 1 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 from executor(1)@172.30.2.21:58560
> [12:20:52]W: [Step 8/8] I0217 12:20:52.093510 32519 slave.cpp:5591]
> Terminating task 1
> [12:20:52]W: [Step 8/8] I0217 12:20:52.189762 32514 slave.cpp:3481]
> executor(1)@172.30.2.21:56710 exited
> [12:20:52]W: [Step 8/8] I0217 12:20:52.234338 32513 containerizer.cpp:1443]
> Executor for container '31b2084a-64ff-479c-af79-1ee5370efb7e' has exited
> [12:20:52]W: [Step 8/8] I0217 12:20:52.234361 32513 containerizer.cpp:1227]
> Destroying container '31b2084a-64ff-479c-af79-1ee5370efb7e'
> [12:20:52]W: [Step 8/8] I0217 12:20:52.236660 32513 cgroups.cpp:2427]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos/31b2084a-64ff-479c-af79-1ee5370efb7e
> [12:20:52]W: [Step 8/8] I0217 12:20:52.238652 32518 cgroups.cpp:1409]
> Successfully froze cgroup
> /sys/fs/cgroup/freezer/mesos/31b2084a-64ff-479c-af79-1ee5370efb7e after
> 1.950976ms
> [12:20:52]W: [Step 8/8] I0217 12:20:52.240897 32519 cgroups.cpp:2445]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos/31b2084a-64ff-479c-af79-1ee5370efb7e
> [12:20:52]W: [Step 8/8] I0217 12:20:52.242872 32519 cgroups.cpp:1438]
> Successfullly thawed cgroup
> /sys/fs/cgroup/freezer/mesos/31b2084a-64ff-479c-af79-1ee5370efb7e after
> 1.935872ms
> [12:20:52]W: [Step 8/8] I0217 12:20:52.245499 32516 provisioner.cpp:306]
> Ignoring destroy request for unknown container
> 31b2084a-64ff-479c-af79-1ee5370efb7e
> [12:20:52]W: [Step 8/8] I0217 12:20:52.245748 32513 slave.cpp:3816]
> Executor '0' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 exited
> with status 0
> [12:20:52]W: [Step 8/8] I0217 12:20:52.245806 32513 slave.cpp:3920]
> Cleaning up executor '0' of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 at executor(1)@172.30.2.21:56710
> [12:20:52]W: [Step 8/8] I0217 12:20:52.246109 32514 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e'
> for gc 6.99999715225481days in the future
> [12:20:52]W: [Step 8/8] I0217 12:20:52.246222 32514 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0'
> for gc 6.99999715108741days in the future
> [12:20:52]W: [Step 8/8] I0217 12:20:52.246287 32514 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e'
> for gc 6.99999715049778days in the future
> [12:20:52]W: [Step 8/8] I0217 12:20:52.246345 32514 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0'
> for gc 6.9999971499763days in the future
> [12:20:52]W: [Step 8/8] I0217 12:20:52.850482 32516 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:52]W: [Step 8/8] I0217 12:20:52.850548 32516 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:20:52]W: [Step 8/8] I0217 12:20:52.850584 32516 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:52]W: [Step 8/8] I0217 12:20:52.850610 32516 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 627005ns
> [12:20:53]W: [Step 8/8] I0217 12:20:53.096267 32517 slave.cpp:3481]
> executor(1)@172.30.2.21:58560 exited
> [12:20:53]W: [Step 8/8] I0217 12:20:53.139739 32514 containerizer.cpp:1443]
> Executor for container 'cf539d3e-9c02-438a-b960-44bc00fb3530' has exited
> [12:20:53]W: [Step 8/8] I0217 12:20:53.139766 32514 containerizer.cpp:1227]
> Destroying container 'cf539d3e-9c02-438a-b960-44bc00fb3530'
> [12:20:53]W: [Step 8/8] I0217 12:20:53.142175 32515 cgroups.cpp:2427]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos/cf539d3e-9c02-438a-b960-44bc00fb3530
> [12:20:53]W: [Step 8/8] I0217 12:20:53.144177 32518 cgroups.cpp:1409]
> Successfully froze cgroup
> /sys/fs/cgroup/freezer/mesos/cf539d3e-9c02-438a-b960-44bc00fb3530 after
> 1.959168ms
> [12:20:53]W: [Step 8/8] I0217 12:20:53.146278 32517 cgroups.cpp:2445]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos/cf539d3e-9c02-438a-b960-44bc00fb3530
> [12:20:53]W: [Step 8/8] I0217 12:20:53.148144 32517 cgroups.cpp:1438]
> Successfullly thawed cgroup
> /sys/fs/cgroup/freezer/mesos/cf539d3e-9c02-438a-b960-44bc00fb3530 after
> 1.824768ms
> [12:20:53]W: [Step 8/8] I0217 12:20:53.150665 32513 provisioner.cpp:306]
> Ignoring destroy request for unknown container
> cf539d3e-9c02-438a-b960-44bc00fb3530
> [12:20:53]W: [Step 8/8] I0217 12:20:53.150898 32513 slave.cpp:3816]
> Executor '1' of framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 exited
> with status 0
> [12:20:53]W: [Step 8/8] I0217 12:20:53.851771 32515 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:53]W: [Step 8/8] I0217 12:20:53.851858 32515 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:20:53]W: [Step 8/8] I0217 12:20:53.851894 32515 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:53]W: [Step 8/8] I0217 12:20:53.851920 32515 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 661166ns
> [12:20:54]W: [Step 8/8] I0217 12:20:54.853108 32518 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:54]W: [Step 8/8] I0217 12:20:54.853176 32518 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:20:54]W: [Step 8/8] I0217 12:20:54.853212 32518 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:54]W: [Step 8/8] I0217 12:20:54.853238 32518 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 662593ns
> [12:20:55]W: [Step 8/8] I0217 12:20:55.854672 32517 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:55]W: [Step 8/8] I0217 12:20:55.854742 32517 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:20:55]W: [Step 8/8] I0217 12:20:55.854801 32517 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:55]W: [Step 8/8] I0217 12:20:55.854832 32517 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 671127ns
> [12:20:56]W: [Step 8/8] I0217 12:20:56.856071 32518 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:56]W: [Step 8/8] I0217 12:20:56.856137 32518 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 810678ns
> [12:20:56]W: [Step 8/8] I0217 12:20:56.856375 32514 master.cpp:5350]
> Sending 1 offers to framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:56]W: [Step 8/8] I0217 12:20:56.856827 32519 sched.cpp:877]
> Scheduler::resourceOffers took 115450ns
> [12:20:56]W: [Step 8/8] I0217 12:20:56.857096 32514 master.cpp:3673]
> Processing DECLINE call for offers: [ 0941887d-60f1-4ff3-85f0-5d19ffee8005-O2
> ] for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:20:56]W: [Step 8/8] I0217 12:20:56.857484 32519 hierarchical.cpp:892]
> Recovered cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000]
> (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000],
> allocated: cpus(*):1; mem(*):1) on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:56]W: [Step 8/8] I0217 12:20:56.857534 32519 hierarchical.cpp:929]
> Framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 filtered slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for 5secs
> [12:20:57]W: [Step 8/8] I0217 12:20:57.857295 32514 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:57]W: [Step 8/8] I0217 12:20:57.857364 32514 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:20:57]W: [Step 8/8] I0217 12:20:57.857400 32514 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:57]W: [Step 8/8] I0217 12:20:57.857427 32514 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 636245ns
> [12:20:58]W: [Step 8/8] I0217 12:20:58.859124 32516 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:58]W: [Step 8/8] I0217 12:20:58.859192 32516 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:20:58]W: [Step 8/8] I0217 12:20:58.859227 32516 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:58]W: [Step 8/8] I0217 12:20:58.859254 32516 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 666607ns
> [12:20:59]W: [Step 8/8] I0217 12:20:59.860666 32513 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:20:59]W: [Step 8/8] I0217 12:20:59.860735 32513 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:20:59]W: [Step 8/8] I0217 12:20:59.860771 32513 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:20:59]W: [Step 8/8] I0217 12:20:59.860816 32513 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 687846ns
> [12:21:00]W: [Step 8/8] I0217 12:21:00.862351 32516 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:00]W: [Step 8/8] I0217 12:21:00.862418 32516 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:21:00]W: [Step 8/8] I0217 12:21:00.862453 32516 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:21:00]W: [Step 8/8] I0217 12:21:00.862479 32516 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 636973ns
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864004 32514 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864064 32514 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 770250ns
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864317 32513 master.cpp:5350]
> Sending 1 offers to framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> (default) at scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864737 32515 sched.cpp:877]
> Scheduler::resourceOffers took 70746ns
> [12:21:01]W: [Step 8/8] I0217 12:21:01.864984 32513 master.cpp:3673]
> Processing DECLINE call for offers: [ 0941887d-60f1-4ff3-85f0-5d19ffee8005-O3
> ] for framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:21:01]W: [Step 8/8] I0217 12:21:01.865381 32515 hierarchical.cpp:892]
> Recovered cpus(*):999; mem(*):999; disk(*):4090; ports(*):[31000-32000]
> (total: cpus(*):1000; mem(*):1000; disk(*):4090; ports(*):[31000-32000],
> allocated: cpus(*):1; mem(*):1) on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:01]W: [Step 8/8] I0217 12:21:01.865432 32515 hierarchical.cpp:929]
> Framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 filtered slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for 5secs
> [12:21:02]W: [Step 8/8] I0217 12:21:02.865320 32514 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:02]W: [Step 8/8] I0217 12:21:02.865389 32514 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:21:02]W: [Step 8/8] I0217 12:21:02.865425 32514 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:21:02]W: [Step 8/8] I0217 12:21:02.865453 32514 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 647129ns
> [12:21:03]W: [Step 8/8] I0217 12:21:03.866272 32517 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:03]W: [Step 8/8] I0217 12:21:03.866341 32517 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:21:03]W: [Step 8/8] I0217 12:21:03.866377 32517 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:21:03]W: [Step 8/8] I0217 12:21:03.866405 32517 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 691378ns
> [12:21:04]W: [Step 8/8] I0217 12:21:04.867204 32513 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:04]W: [Step 8/8] I0217 12:21:04.867274 32513 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:21:04]W: [Step 8/8] I0217 12:21:04.867311 32513 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:21:04]W: [Step 8/8] I0217 12:21:04.867336 32513 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 663817ns
> [12:21:05]W: [Step 8/8] I0217 12:21:05.868382 32518 hierarchical.cpp:1589]
> Filtered offer with cpus(*):999; mem(*):999; disk(*):4090;
> ports(*):[31000-32000] on slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 for
> framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:05]W: [Step 8/8] I0217 12:21:05.868449 32518 hierarchical.cpp:1403]
> No resources available to allocate!
> [12:21:05]W: [Step 8/8] I0217 12:21:05.868485 32518 hierarchical.cpp:1498]
> No inverse offers to send out!
> [12:21:05]W: [Step 8/8] I0217 12:21:05.868510 32518 hierarchical.cpp:1096]
> Performed allocation for 1 slaves in 635348ns
> [12:21:05]W: [Step 8/8] I0217 12:21:05.904500 32514 slave.cpp:4667]
> Querying resource estimator for oversubscribable resources
> [12:21:05]W: [Step 8/8] I0217 12:21:05.904728 32514 slave.cpp:4681]
> Received oversubscribable resources from the resource estimator
> [12:21:05]W: [Step 8/8] I0217 12:21:05.912817 32514 slave.cpp:3435]
> Received ping from slave-observer(49)@172.30.2.21:33004
> [12:21:06] : [Step 8/8] ../../src/tests/fetcher_cache_tests.cpp:916: Failure
> [12:21:06] : [Step 8/8] Failed to wait 15secs for awaitFinished(task.get())
> [12:21:06] : [Step 8/8] Begin listing sandboxes
> [12:21:06] : [Step 8/8] Begin listing sandbox
> `/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/latest`:
> [12:21:06] : [Step 8/8] Begin file contents of `stdout`:
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] Begin file contents of `stderr`:
> [12:21:06] : [Step 8/8] I0217 12:20:50.982002 3316 logging.cpp:193]
> Logging to STDERR
> [12:21:06] : [Step 8/8] I0217 12:20:50.982161 3316 fetcher.cpp:424]
> Fetcher Info:
> {"cache_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY\/fetch\/slaves\/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0\/root","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-mesos-fetc_r-test-cmd","uri":{"cache":true,"executable":true,"extract":true,"value":"http:\/\/172.30.2.21:33004\/(2098)\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY\/slaves\/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0\/frameworks\/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000\/executors\/0\/runs\/31b2084a-64ff-479c-af79-1ee5370efb7e","user":"root"}
> [12:21:06] : [Step 8/8] I0217 12:20:50.987099 3316 fetcher.cpp:379]
> Fetching URI 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8] I0217 12:20:50.987119 3316 fetcher.cpp:349]
> Downloading into cache
> [12:21:06] : [Step 8/8] I0217 12:20:50.987370 3316 fetcher.cpp:187]
> Fetching URI 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd'
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853065 32498 sched.cpp:1907] Asked
> to stop the driver
> [12:21:06] : [Step 8/8] I0217 12:20:50.987406 3316 fetcher.cpp:134]
> Downloading resource from
> 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd' to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/fetch/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/root/c1-mesos-fetc_r-test-cmd'
> [12:21:06] : [Step 8/8] I0217 12:20:50.989434 3316 fetcher.cpp:289]
> Fetching from cache
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853193 32519 sched.cpp:1147]
> Stopping framework '0941887d-60f1-4ff3-85f0-5d19ffee8005-0000'
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853457 32513 master.cpp:5921]
> Processing TEARDOWN call for framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:21:06] : [Step 8/8] I0217 12:20:50.989460 3316 fetcher.cpp:167]
> Copying resource with command:cp
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/fetch/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/root/c1-mesos-fetc_r-test-cmd'
>
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/mesos-fetcher-test-cmd'
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853485 32513 master.cpp:5933]
> Removing framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (default) at
> scheduler-1c91fcbd-6ee7-48a7-80d6-7ad9536b21ec@172.30.2.21:33004
> [12:21:06] : [Step 8/8] I0217 12:20:50.992434 3316 fetcher.cpp:456]
> Fetched 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd' to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/0/runs/31b2084a-64ff-479c-af79-1ee5370efb7e/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8]
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853677 32518 hierarchical.cpp:375]
> Deactivated framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06] : [Step 8/8] End file
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853739 32517 slave.cpp:2078] Asked
> to shut down framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 by
> master@172.30.2.21:33004
> [12:21:06] : [Step 8/8] Begin file contents of `mesos-fetcher-test-cmd`:
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853782 32517 slave.cpp:2103]
> Shutting down framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06] : [Step 8/8] touch mesos-fetcher-test-cmd$1
> [12:21:06] : [Step 8/8] End file
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853806 32513 master.cpp:6445]
> Updating the state of task 1 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 (latest state: TASK_KILLED, status
> update state: TASK_KILLED)
> [12:21:06] : [Step 8/8] Begin file contents of `mesos-fetcher-test-cmd0`:
> [12:21:06]W: [Step 8/8] I0217 12:21:06.853873 32517 slave.cpp:3920]
> Cleaning up executor '1' of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 at executor(1)@172.30.2.21:58560
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] End sandbox
> [12:21:06] : [Step 8/8] Begin listing sandbox
> `/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/latest`:
> [12:21:06] : [Step 8/8] Begin file contents of `stdout`:
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] Begin file contents of `stderr`:
> [12:21:06] : [Step 8/8] I0217 12:20:51.914311 3373 logging.cpp:193]
> Logging to STDERR
> [12:21:06] : [Step 8/8] I0217 12:20:51.914465 3373 fetcher.cpp:424]
> Fetcher Info:
> {"cache_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY\/fetch\/slaves\/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0\/root","items":[{"action":"RETRIEVE_FROM_CACHE","cache_filename":"c1-mesos-fetc_r-test-cmd","uri":{"cache":true,"executable":true,"extract":true,"value":"http:\/\/172.30.2.21:33004\/(2098)\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY\/slaves\/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0\/frameworks\/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000\/executors\/1\/runs\/cf539d3e-9c02-438a-b960-44bc00fb3530","user":"root"}
> [12:21:06] : [Step 8/8] I0217 12:20:51.919170 3373 fetcher.cpp:379]
> Fetching URI 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8] I0217 12:20:51.919193 3373 fetcher.cpp:289]
> Fetching from cache
> [12:21:06] : [Step 8/8] I0217 12:20:51.919214 3373 fetcher.cpp:167]
> Copying resource with command:cp
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/fetch/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/root/c1-mesos-fetc_r-test-cmd'
>
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8] I0217 12:20:51.922278 3373 fetcher.cpp:456]
> Fetched 'http://172.30.2.21:33004/(2098)/mesos-fetcher-test-cmd' to
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530/mesos-fetcher-test-cmd'
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] Begin file contents of `mesos-fetcher-test-cmd`:
> [12:21:06] : [Step 8/8] touch mesos-fetcher-test-cmd$1
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] Begin file contents of `mesos-fetcher-test-cmd1`:
> [12:21:06] : [Step 8/8]
> [12:21:06] : [Step 8/8] End file
> [12:21:06] : [Step 8/8] End sandbox
> [12:21:06] : [Step 8/8] End sandboxes
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854249 32518 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530'
> for gc 6.99999011384296days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854306 32519 hierarchical.cpp:892]
> Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000;
> disk(*):4090; ports(*):[31000-32000], allocated: ) on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 from framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854307 32513 master.cpp:6511]
> Removing task 1 with resources cpus(*):1; mem(*):1 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 on slave
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0 at slave(52)@172.30.2.21:33004
> (ip-172-30-2-21.mesosphere.io)
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854398 32514 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1'
> for gc 6.99999011203556days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854470 32514 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1/runs/cf539d3e-9c02-438a-b960-44bc00fb3530'
> for gc 6.9999901109037days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854552 32517 slave.cpp:4008]
> Cleaning up framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854557 32514 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000/executors/1'
> for gc 6.99999011days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854769 32516 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000'
> for gc 6.99999010776889days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854815 32513 master.cpp:1025] Master
> terminating
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854843 32516 gc.cpp:54] Scheduling
> '/tmp/FetcherCacheHttpTest_HttpCachedSerialized_gHQIlY/meta/slaves/0941887d-60f1-4ff3-85f0-5d19ffee8005-S0/frameworks/0941887d-60f1-4ff3-85f0-5d19ffee8005-0000'
> for gc 6.99999010661926days in the future
> [12:21:06]W: [Step 8/8] I0217 12:21:06.854859 32518 hierarchical.cpp:326]
> Removed framework 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000
> [12:21:06]W: [Step 8/8] I0217 12:21:06.855139 32518 hierarchical.cpp:505]
> Removed slave 0941887d-60f1-4ff3-85f0-5d19ffee8005-S0
> [12:21:06]W: [Step 8/8] I0217 12:21:06.855335 32519 slave.cpp:3481]
> master@172.30.2.21:33004 exited
> [12:21:06]W: [Step 8/8] W0217 12:21:06.855355 32519 slave.cpp:3484] Master
> disconnected! Waiting for a new master to be elected
> [12:21:06]W: [Step 8/8] I0217 12:21:06.859239 32515 slave.cpp:667] Slave
> terminating
> [12:21:06]W: [Step 8/8] I0217 12:21:06.881626 32512
> status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
> 5cdf0928-0611-4614-ba85-a4e5ec6facfd) for task 1 of framework
> 0941887d-60f1-4ff3-85f0-5d19ffee8005-0000 to the slave
> [12:21:06] : [Step 8/8] [ FAILED ]
> FetcherCacheHttpTest.HttpCachedSerialized (16052 ms)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
