You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Jie Yu (JIRA)" <ji...@apache.org> on 2015/06/16 00:59:00 UTC
[jira] [Created] (MESOS-2871)
FetcherCacheHttpTest.HttpCachedRecovery is flaky
Jie Yu created MESOS-2871:
-----------------------------
Summary: FetcherCacheHttpTest.HttpCachedRecovery is flaky
Key: MESOS-2871
URL: https://issues.apache.org/jira/browse/MESOS-2871
Project: Mesos
Issue Type: Bug
Reporter: Jie Yu
https://builds.apache.org/job/Mesos/COMPILER=clang,LABEL=docker%7C%7CHadoop,OS=ubuntu:14.10/375/consoleFull
{noformat}
[ RUN ] FetcherCacheHttpTest.HttpCachedRecovery
Using temporary directory '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_T1CYbF'
I0615 22:48:21.997678 24680 leveldb.cpp:176] Opened db in 155.514067ms
I0615 22:48:22.032702 24680 leveldb.cpp:183] Compacted db in 34.972268ms
I0615 22:48:22.032788 24680 leveldb.cpp:198] Created db iterator in 35354ns
I0615 22:48:22.032811 24680 leveldb.cpp:204] Seeked to beginning of db in 11429ns
I0615 22:48:22.032825 24680 leveldb.cpp:273] Iterated through 0 keys in the db in 7898ns
I0615 22:48:22.032879 24680 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0615 22:48:22.033618 24711 recover.cpp:449] Starting replica recovery
I0615 22:48:22.034335 24711 recover.cpp:475] Replica is in EMPTY status
I0615 22:48:22.035841 24711 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
I0615 22:48:22.036453 24711 recover.cpp:195] Received a recover response from a replica in EMPTY status
I0615 22:48:22.037179 24707 recover.cpp:566] Updating replica status to STARTING
I0615 22:48:22.039435 24699 master.cpp:361] Master 20150615-224822-2231374252-55005-24680 (266bbfb8797f) started on 172.17.0.133:55005
I0615 22:48:22.039468 24699 master.cpp:363] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --credentials="/tmp/FetcherCacheHttpTest_HttpCachedRecovery_T1CYbF/credentials" --framework_sorter="drf" --help="false" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --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_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.23.0/_inst/share/mesos/webui" --work_dir="/tmp/FetcherCacheHttpTest_HttpCachedRecovery_T1CYbF/master" --zk_session_timeout="10secs"
I0615 22:48:22.039881 24699 master.cpp:408] Master only allowing authenticated frameworks to register
I0615 22:48:22.039897 24699 master.cpp:413] Master only allowing authenticated slaves to register
I0615 22:48:22.039909 24699 credentials.hpp:37] Loading credentials for authentication from '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_T1CYbF/credentials'
I0615 22:48:22.040138 24699 master.cpp:452] Using default 'crammd5' authenticator
I0615 22:48:22.040256 24699 master.cpp:489] Authorization enabled
I0615 22:48:22.040477 24709 hierarchical.hpp:309] Initialized hierarchical allocator process
I0615 22:48:22.040602 24713 whitelist_watcher.cpp:79] No whitelist given
I0615 22:48:22.041679 24711 master.cpp:1474] The newly elected leader is master@172.17.0.133:55005 with id 20150615-224822-2231374252-55005-24680
I0615 22:48:22.041795 24711 master.cpp:1487] Elected as the leading master!
I0615 22:48:22.041813 24711 master.cpp:1257] Recovering from registrar
I0615 22:48:22.041975 24709 registrar.cpp:313] Recovering registrar
I0615 22:48:22.073132 24706 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 35.563275ms
I0615 22:48:22.073336 24706 replica.cpp:323] Persisted replica status to STARTING
I0615 22:48:22.073932 24706 recover.cpp:475] Replica is in STARTING status
I0615 22:48:22.075609 24710 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
I0615 22:48:22.075856 24703 recover.cpp:195] Received a recover response from a replica in STARTING status
I0615 22:48:22.076344 24705 recover.cpp:566] Updating replica status to VOTING
I0615 22:48:22.113186 24702 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 36.734438ms
I0615 22:48:22.113261 24702 replica.cpp:323] Persisted replica status to VOTING
I0615 22:48:22.113440 24711 recover.cpp:580] Successfully joined the Paxos group
I0615 22:48:22.113667 24711 recover.cpp:464] Recover process terminated
I0615 22:48:22.114145 24702 log.cpp:661] Attempting to start the writer
I0615 22:48:22.115365 24713 replica.cpp:477] Replica received implicit promise request with proposal 1
I0615 22:48:22.142144 24713 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 26.776243ms
I0615 22:48:22.142225 24713 replica.cpp:345] Persisted promised to 1
I0615 22:48:22.143024 24698 coordinator.cpp:230] Coordinator attemping to fill missing position
I0615 22:48:22.144114 24703 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
I0615 22:48:22.167280 24703 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 23.152818ms
I0615 22:48:22.167354 24703 replica.cpp:679] Persisted action at 0
I0615 22:48:22.168876 24712 replica.cpp:511] Replica received write request for position 0
I0615 22:48:22.169039 24712 leveldb.cpp:438] Reading position from leveldb took 59881ns
I0615 22:48:22.192410 24712 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 23.251513ms
I0615 22:48:22.192644 24712 replica.cpp:679] Persisted action at 0
I0615 22:48:22.193847 24698 replica.cpp:658] Replica received learned notice for position 0
I0615 22:48:22.217589 24698 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 23.737384ms
I0615 22:48:22.217670 24698 replica.cpp:679] Persisted action at 0
I0615 22:48:22.217707 24698 replica.cpp:664] Replica learned NOP action at position 0
I0615 22:48:22.218678 24702 log.cpp:677] Writer started with ending position 0
I0615 22:48:22.219712 24705 leveldb.cpp:438] Reading position from leveldb took 67074ns
I0615 22:48:22.222612 24699 registrar.cpp:346] Successfully fetched the registry (0B) in 180.507136ms
I0615 22:48:22.222736 24699 registrar.cpp:445] Applied 1 operations in 42606ns; attempting to update the 'registry'
I0615 22:48:22.225186 24699 log.cpp:685] Attempting to append 131 bytes to the log
I0615 22:48:22.225450 24708 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0615 22:48:22.226702 24711 replica.cpp:511] Replica received write request for position 1
I0615 22:48:22.251610 24711 leveldb.cpp:343] Persisting action (150 bytes) to leveldb took 24.896766ms
I0615 22:48:22.251701 24711 replica.cpp:679] Persisted action at 1
I0615 22:48:22.252807 24703 replica.cpp:658] Replica received learned notice for position 1
I0615 22:48:22.281626 24703 leveldb.cpp:343] Persisting action (152 bytes) to leveldb took 28.814352ms
I0615 22:48:22.281716 24703 replica.cpp:679] Persisted action at 1
I0615 22:48:22.281755 24703 replica.cpp:664] Replica learned APPEND action at position 1
I0615 22:48:22.283448 24703 registrar.cpp:490] Successfully updated the 'registry' in 60.638208ms
I0615 22:48:22.283586 24708 log.cpp:704] Attempting to truncate the log to 1
I0615 22:48:22.283802 24703 registrar.cpp:376] Successfully recovered registrar
I0615 22:48:22.284077 24701 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0615 22:48:22.284649 24708 master.cpp:1284] Recovered 0 slaves from the Registry (95B) ; allowing 10mins for slaves to re-register
I0615 22:48:22.285790 24708 replica.cpp:511] Replica received write request for position 2
I0615 22:48:22.311146 24708 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 25.029085ms
I0615 22:48:22.311775 24708 replica.cpp:679] Persisted action at 2
I0615 22:48:22.312764 24708 replica.cpp:658] Replica received learned notice for position 2
I0615 22:48:22.340273 24708 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 27.506455ms
I0615 22:48:22.340431 24708 leveldb.cpp:401] Deleting ~1 keys from leveldb took 90595ns
I0615 22:48:22.340739 24708 replica.cpp:679] Persisted action at 2
I0615 22:48:22.341016 24708 replica.cpp:664] Replica learned TRUNCATE action at position 2
I0615 22:48:22.349275 24680 containerizer.cpp:111] Using isolation: posix/cpu,posix/mem
I0615 22:48:22.356341 24705 slave.cpp:187] Slave started on 48)@172.17.0.133:55005
I0615 22:48:22.356396 24705 slave.cpp:188] Flags at startup: --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_HttpCachedRecovery_eTAiVx/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_remove_delay="6hrs" --docker_sandbox_directory="/mnt/mesos/sandbox" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.23.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_monitoring_interval="1secs" --resources="cpus(*):1000; mem(*):1000" --revocable_cpu_low_priority="true" --strict="true" --switch_user="true" --version="false" --work_dir="/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx"
I0615 22:48:22.357002 24705 credentials.hpp:85] Loading credential for authentication from '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/credential'
I0615 22:48:22.357224 24705 slave.cpp:318] Slave using credential for: test-principal
I0615 22:48:22.357834 24705 slave.cpp:352] Slave resources: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
I0615 22:48:22.357949 24705 slave.cpp:382] Slave hostname: 266bbfb8797f
I0615 22:48:22.357972 24705 slave.cpp:387] Slave checkpoint: true
I0615 22:48:22.359107 24705 state.cpp:35] Recovering state from '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta'
I0615 22:48:22.360563 24705 status_update_manager.cpp:201] Recovering status update manager
I0615 22:48:22.360754 24712 containerizer.cpp:312] Recovering containerizer
I0615 22:48:22.361608 24702 slave.cpp:3918] Finished recovery
I0615 22:48:22.362193 24702 slave.cpp:4072] Querying resource estimator for oversubscribable resources
I0615 22:48:22.362418 24702 slave.cpp:678] New master detected at master@172.17.0.133:55005
I0615 22:48:22.362464 24703 status_update_manager.cpp:175] Pausing sending status updates
I0615 22:48:22.362507 24702 slave.cpp:741] Authenticating with master master@172.17.0.133:55005
I0615 22:48:22.362542 24702 slave.cpp:746] Using default CRAM-MD5 authenticatee
I0615 22:48:22.362678 24702 slave.cpp:714] Detecting new master
I0615 22:48:22.362699 24703 authenticatee.hpp:139] Creating new client SASL connection
I0615 22:48:22.362844 24702 slave.cpp:4086] Received oversubscribable resources from the resource estimator
I0615 22:48:22.362993 24700 master.cpp:4187] Authenticating slave(48)@172.17.0.133:55005
I0615 22:48:22.363101 24703 authenticator.cpp:406] Starting authentication session for crammd5_authenticatee(142)@172.17.0.133:55005
I0615 22:48:22.363324 24700 authenticator.cpp:92] Creating new server SASL connection
I0615 22:48:22.363512 24702 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
I0615 22:48:22.363560 24702 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
I0615 22:48:22.363653 24702 authenticator.cpp:197] Received SASL authentication start
I0615 22:48:22.363714 24702 authenticator.cpp:319] Authentication requires more steps
I0615 22:48:22.363801 24702 authenticatee.hpp:276] Received SASL authentication step
I0615 22:48:22.363942 24709 authenticator.cpp:225] Received SASL authentication step
I0615 22:48:22.363981 24709 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '266bbfb8797f' server FQDN: '266bbfb8797f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0615 22:48:22.363999 24709 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I0615 22:48:22.364051 24709 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0615 22:48:22.364089 24709 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '266bbfb8797f' server FQDN: '266bbfb8797f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0615 22:48:22.364104 24709 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0615 22:48:22.364114 24709 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0615 22:48:22.364136 24709 authenticator.cpp:311] Authentication success
I0615 22:48:22.364297 24709 authenticatee.hpp:316] Authentication success
I0615 22:48:22.364382 24709 master.cpp:4217] Successfully authenticated principal 'test-principal' at slave(48)@172.17.0.133:55005
I0615 22:48:22.364475 24709 authenticator.cpp:424] Authentication session cleanup for crammd5_authenticatee(142)@172.17.0.133:55005
I0615 22:48:22.364752 24713 slave.cpp:812] Successfully authenticated with master master@172.17.0.133:55005
I0615 22:48:22.364893 24713 slave.cpp:1171] Will retry registration in 12.128474ms if necessary
I0615 22:48:22.365262 24713 master.cpp:3166] Registering slave at slave(48)@172.17.0.133:55005 (266bbfb8797f) with id 20150615-224822-2231374252-55005-24680-S0
I0615 22:48:22.365797 24713 registrar.cpp:445] Applied 1 operations in 81726ns; attempting to update the 'registry'
I0615 22:48:22.369240 24713 log.cpp:685] Attempting to append 305 bytes to the log
I0615 22:48:22.369360 24705 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0615 22:48:22.370169 24700 replica.cpp:511] Replica received write request for position 3
I0615 22:48:22.377470 24705 slave.cpp:1171] Will retry registration in 21.384821ms if necessary
I0615 22:48:22.377724 24701 master.cpp:3154] Ignoring register slave message from slave(48)@172.17.0.133:55005 (266bbfb8797f) as admission is already in progress
I0615 22:48:22.398974 24700 leveldb.cpp:343] Persisting action (324 bytes) to leveldb took 28.7905ms
I0615 22:48:22.399438 24700 replica.cpp:679] Persisted action at 3
I0615 22:48:22.400745 24705 replica.cpp:658] Replica received learned notice for position 3
I0615 22:48:22.401090 24703 slave.cpp:1171] Will retry registration in 70.363717ms if necessary
I0615 22:48:22.401401 24704 master.cpp:3154] Ignoring register slave message from slave(48)@172.17.0.133:55005 (266bbfb8797f) as admission is already in progress
I0615 22:48:22.432654 24705 leveldb.cpp:343] Persisting action (326 bytes) to leveldb took 31.906699ms
I0615 22:48:22.432739 24705 replica.cpp:679] Persisted action at 3
I0615 22:48:22.432771 24705 replica.cpp:664] Replica learned APPEND action at position 3
I0615 22:48:22.434578 24703 log.cpp:704] Attempting to truncate the log to 3
I0615 22:48:22.434839 24707 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0615 22:48:22.434921 24705 registrar.cpp:490] Successfully updated the 'registry' in 68.67584ms
I0615 22:48:22.435932 24712 replica.cpp:511] Replica received write request for position 4
I0615 22:48:22.436249 24701 master.cpp:3223] Registered slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
I0615 22:48:22.436592 24701 hierarchical.hpp:496] Added slave 20150615-224822-2231374252-55005-24680-S0 (266bbfb8797f) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (and cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] available)
I0615 22:48:22.436801 24701 hierarchical.hpp:933] No resources available to allocate!
I0615 22:48:22.436821 24701 hierarchical.hpp:852] Performed allocation for slave 20150615-224822-2231374252-55005-24680-S0 in 194134ns
I0615 22:48:22.437000 24701 slave.cpp:847] Registered with master master@172.17.0.133:55005; given slave ID 20150615-224822-2231374252-55005-24680-S0
I0615 22:48:22.437028 24701 fetcher.cpp:77] Clearing fetcher cache
I0615 22:48:22.437415 24701 slave.cpp:870] Checkpointing SlaveInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/slave.info'
I0615 22:48:22.437608 24702 status_update_manager.cpp:182] Resuming sending status updates
I0615 22:48:22.437947 24701 slave.cpp:905] Forwarding total oversubscribed resources
I0615 22:48:22.438057 24701 slave.cpp:2893] Received ping from slave-observer(46)@172.17.0.133:55005
I0615 22:48:22.438247 24701 master.cpp:3509] Received update of slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f) with total oversubscribed resources
I0615 22:48:22.438482 24701 hierarchical.hpp:570] Slave 20150615-224822-2231374252-55005-24680-S0 (266bbfb8797f) updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], available: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000])
I0615 22:48:22.438743 24701 hierarchical.hpp:933] No resources available to allocate!
I0615 22:48:22.438820 24701 hierarchical.hpp:852] Performed allocation for slave 20150615-224822-2231374252-55005-24680-S0 in 275272ns
I0615 22:48:22.441763 24680 sched.cpp:155] Version: 0.23.0
I0615 22:48:22.443343 24707 sched.cpp:252] New master detected at master@172.17.0.133:55005
I0615 22:48:22.443840 24707 sched.cpp:308] Authenticating with master master@172.17.0.133:55005
I0615 22:48:22.444073 24707 sched.cpp:315] Using default CRAM-MD5 authenticatee
I0615 22:48:22.444553 24706 authenticatee.hpp:139] Creating new client SASL connection
I0615 22:48:22.445039 24699 master.cpp:4187] Authenticating scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:22.445188 24706 authenticator.cpp:406] Starting authentication session for crammd5_authenticatee(143)@172.17.0.133:55005
I0615 22:48:22.445668 24706 authenticator.cpp:92] Creating new server SASL connection
I0615 22:48:22.445907 24707 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
I0615 22:48:22.445945 24707 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
I0615 22:48:22.446135 24698 authenticator.cpp:197] Received SASL authentication start
I0615 22:48:22.446194 24698 authenticator.cpp:319] Authentication requires more steps
I0615 22:48:22.446277 24698 authenticatee.hpp:276] Received SASL authentication step
I0615 22:48:22.446408 24706 authenticator.cpp:225] Received SASL authentication step
I0615 22:48:22.446475 24706 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '266bbfb8797f' server FQDN: '266bbfb8797f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0615 22:48:22.446491 24706 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I0615 22:48:22.446557 24706 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0615 22:48:22.446619 24706 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '266bbfb8797f' server FQDN: '266bbfb8797f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0615 22:48:22.446640 24706 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0615 22:48:22.446651 24706 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0615 22:48:22.446673 24706 authenticator.cpp:311] Authentication success
I0615 22:48:22.446856 24709 authenticatee.hpp:316] Authentication success
I0615 22:48:22.446924 24710 master.cpp:4217] Successfully authenticated principal 'test-principal' at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:22.447195 24709 sched.cpp:396] Successfully authenticated with master master@172.17.0.133:55005
I0615 22:48:22.447223 24709 sched.cpp:519] Sending registration request to master@172.17.0.133:55005
I0615 22:48:22.447247 24707 authenticator.cpp:424] Authentication session cleanup for crammd5_authenticatee(143)@172.17.0.133:55005
I0615 22:48:22.447330 24709 sched.cpp:552] Will retry registration in 752.925799ms if necessary
I0615 22:48:22.447688 24704 master.cpp:1714] Received registration request for framework 'default' at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
W0615 22:48:22.447721 24704 master.cpp:1537] Framework at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 (authenticated as 'test-principal') does not specify principal in its FrameworkInfo
I0615 22:48:22.447747 24704 master.cpp:1553] Authorizing framework principal '' to receive offers for role '*'
I0615 22:48:22.448335 24709 master.cpp:1781] Registering framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 with checkpointing enabled and capabilities [ ]
I0615 22:48:22.449314 24709 hierarchical.hpp:354] Added framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.449769 24700 sched.cpp:446] Framework registered with 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.450391 24700 sched.cpp:460] Scheduler::registered took 77015ns
I0615 22:48:22.451206 24709 hierarchical.hpp:834] Performed allocation for 1 slaves in 1.256382ms
I0615 22:48:22.451725 24709 master.cpp:4106] Sending 1 offers to framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:22.452217 24707 sched.cpp:609] Scheduler::resourceOffers took 116064ns
I0615 22:48:22.454144 24707 master.cpp:2422] Processing ACCEPT call for offers: [ 20150615-224822-2231374252-55005-24680-O0 ] on slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f) for framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:22.454368 24707 master.cpp:2266] Authorizing framework principal '' to launch task 0 as user 'mesos'
I0615 22:48:22.456940 24707 master.hpp:159] Adding task 0 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 (266bbfb8797f)
I0615 22:48:22.457072 24707 master.cpp:2749] Launching task 0 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:22.457783 24706 slave.cpp:1211] Got assigned task 0 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.458000 24698 hierarchical.hpp:741] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.458282 24698 hierarchical.hpp:777] Framework 20150615-224822-2231374252-55005-24680-0000 filtered slave 20150615-224822-2231374252-55005-24680-S0 for 5secs
I0615 22:48:22.458205 24706 slave.cpp:4437] Checkpointing FrameworkInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/framework.info'
I0615 22:48:22.460281 24706 slave.cpp:4444] Checkpointing framework pid 'scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005' to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/framework.pid'
I0615 22:48:22.461844 24706 slave.cpp:1325] Launching task 0 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.468386 24706 slave.cpp:4873] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/executor.info'
I0615 22:48:22.469035 24712 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 32.963716ms
I0615 22:48:22.469116 24712 replica.cpp:679] Persisted action at 4
I0615 22:48:22.469259 24706 slave.cpp:4510] Launching executor 0 of framework 20150615-224822-2231374252-55005-24680-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab'
I0615 22:48:22.469751 24709 containerizer.cpp:530] Starting container '794071a8-cc49-4ca6-a6bf-78d134bc44ab' for executor '0' of framework '20150615-224822-2231374252-55005-24680-0000'
I0615 22:48:22.469954 24706 slave.cpp:4896] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab/tasks/0/task.info'
I0615 22:48:22.470461 24706 slave.cpp:1471] Queuing task '0' for executor 0 of framework '20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.470628 24706 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab'
I0615 22:48:22.471504 24703 replica.cpp:658] Replica received learned notice for position 4
I0615 22:48:22.473235 24702 launcher.cpp:131] Forked child with pid '29448' for container '794071a8-cc49-4ca6-a6bf-78d134bc44ab'
I0615 22:48:22.473412 24702 containerizer.cpp:766] Checkpointing executor's forked pid 29448 to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab/pids/forked.pid'
I0615 22:48:22.475262 24710 fetcher.cpp:299] Starting to fetch URIs for container: 794071a8-cc49-4ca6-a6bf-78d134bc44ab, directory: /tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab
I0615 22:48:22.480964 24710 fetcher.cpp:873] Created cache entry 'mesos@http://172.17.0.133:55005/(1432)/mesos-fetcher-test-cmd' with file: c1-mesos-fetc_r-test-cmd
I0615 22:48:22.482498 24709 fetcher.cpp:248] Fetching size for URI: http://172.17.0.133:55005/(1432)/mesos-fetcher-test-cmd
I0615 22:48:22.483933 24700 process.cpp:2749] Handling HTTP event for process '(1432)' with path: '/(1432)/mesos-fetcher-test-cmd'
I0615 22:48:22.484416 24700 process.cpp:1082] Sending file at '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
HTTP/1.1 200 OK
Date: Mon, 15 Jun 2015 22:48:22 GMT
Content-Length: 30
E0615 22:48:22.485293 24714 socket.hpp:103] Shutdown failed on fd=15: Transport endpoint is not connected [107]
I0615 22:48:22.485430 24698 fetcher.cpp:663] Claiming fetcher cache space for: mesos@http://172.17.0.133:55005/(1432)/mesos-fetcher-test-cmd
I0615 22:48:22.485465 24698 fetcher.cpp:1086] Claimed cache space: 30B, now using: 30B
I0615 22:48:22.506139 24705 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.23.0/_build/src/mesos-fetcher'
I0615 22:48:22.507644 24703 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 36.114953ms
I0615 22:48:22.507907 24703 leveldb.cpp:401] Deleting ~2 keys from leveldb took 109221ns
I0615 22:48:22.508044 24703 replica.cpp:679] Persisted action at 4
I0615 22:48:22.508195 24703 replica.cpp:664] Replica learned TRUNCATE action at position 4
I0615 22:48:22.589593 24699 process.cpp:2749] Handling HTTP event for process '(1432)' with path: '/(1432)/mesos-fetcher-test-cmd'
I0615 22:48:22.590754 24703 process.cpp:1082] Sending file at '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
I0615 22:48:22.651819 24709 fetcher.cpp:1098] Released cache space: 0B, now using: 30B
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0615 22:48:22.722298 29485 process.cpp:926] libprocess is initialized on 172.17.0.133:40060 for 16 cpus
I0615 22:48:22.723960 29485 logging.cpp:177] Logging to STDERR
I0615 22:48:22.726011 29485 exec.cpp:132] Version: 0.23.0
I0615 22:48:22.736563 29502 exec.cpp:182] Executor started at: executor(1)@172.17.0.133:40060 with pid 29485
I0615 22:48:22.740270 24707 slave.cpp:2223] Got registration for executor '0' of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:40060
I0615 22:48:22.740425 24707 slave.cpp:2309] Checkpointing executor pid 'executor(1)@172.17.0.133:40060' to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab/pids/libprocess.pid'
I0615 22:48:22.743175 24701 slave.cpp:1623] Sending queued task '0' to executor '0' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.744606 29500 exec.cpp:206] Executor registered on slave 20150615-224822-2231374252-55005-24680-S0
I0615 22:48:22.747032 29500 exec.cpp:218] Executor::registered took 483060ns
Registered executor on 266bbfb8797f
I0615 22:48:22.747864 29500 exec.cpp:293] Executor asked to run task '0'
I0615 22:48:22.748044 29500 exec.cpp:302] Executor::launchTask took 157258ns
Starting task 0
sh -c './mesos-fetcher-test-cmd 0'
Forked command at 29516
I0615 22:48:22.752012 29508 exec.cpp:509] Executor sending status update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.753779 24710 slave.cpp:2562] Handling status update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:40060
I0615 22:48:22.754109 24708 status_update_manager.cpp:321] Received status update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.754169 24708 status_update_manager.cpp:498] Creating StatusUpdate stream for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.754890 24708 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.817183 24708 status_update_manager.cpp:375] Forwarding update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:22.817704 24704 slave.cpp:2817] Forwarding the update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:22.817940 24704 slave.cpp:2744] Status update manager successfully handled status update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.817971 24704 slave.cpp:2750] Sending acknowledgement for status update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:40060
I0615 22:48:22.818073 24699 master.cpp:3580] Status update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:22.818295 24699 master.cpp:3619] Forwarding status update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.818711 24699 master.cpp:4973] Updating the latest state of task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_RUNNING
I0615 22:48:22.819130 24702 sched.cpp:715] Scheduler::statusUpdate took 159490ns
II0615 22:48:22.819718 29509 exec.cpp:339] Executor received status update acknowledgement 0e105ba4-dd44-4035-8d05-dd67c0cc219e for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
0615 22:48:22.819666 24702 master.cpp:3013] Forwarding status update acknowledgement 0e105ba4-dd44-4035-8d05-dd67c0cc219e for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:22.820165 24704 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.820307 24704 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_RUNNING (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
Command exited with status 0 (pid: 29516)
I0615 22:48:22.853608 29504 exec.cpp:509] Executor sending status update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.854382 24701 slave.cpp:2562] Handling status update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:40060
I0615 22:48:22.854547 24701 slave.cpp:4811] Terminating task 0
I0615 22:48:22.878589 24707 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: 0e105ba4-dd44-4035-8d05-dd67c0cc219e) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.878607 24704 status_update_manager.cpp:321] Received status update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.878659 24704 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.925876 24704 status_update_manager.cpp:375] Forwarding update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:22.926204 24706 slave.cpp:2817] Forwarding the update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:22.926566 24706 slave.cpp:2744] Status update manager successfully handled status update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.926592 24706 slave.cpp:2750] Sending acknowledgement for status update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:40060
I0615 22:48:22.927001 24704 master.cpp:3580] Status update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:22.927042 24704 master.cpp:3619] Forwarding status update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.927176 24704 master.cpp:4973] Updating the latest state of task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_FINISHED
I0615 22:48:22.927623 24704 sched.cpp:715] Scheduler::statusUpdate took 120341ns
I0615 22:48:22.927664 24707 hierarchical.hpp:741] Recovered cpus(*):1; mem(*):1 (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
II0615 22:48:22.928231 29502 exec.cpp:339] Executor received status update acknowledgement e08bb2e7-da4f-4109-8585-7c34737d7161 for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
0615 22:48:22.927851 24707 master.cpp:5041] Removing task 0 with resources cpus(*):1; mem(*):1 of framework 20150615-224822-2231374252-55005-24680-0000 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:22.929206 24707 master.cpp:3013] Forwarding status update acknowledgement e08bb2e7-da4f-4109-8585-7c34737d7161 for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:22.929925 24707 status_update_manager.cpp:393] Received status update acknowledgement (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.930691 24707 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_FINISHED (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.976119 24707 status_update_manager.cpp:529] Cleaning up status update stream for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.977192 24707 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: e08bb2e7-da4f-4109-8585-7c34737d7161) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:22.977839 24707 slave.cpp:4852] Completing task 0
I0615 22:48:23.041960 24702 hierarchical.hpp:834] Performed allocation for 1 slaves in 852927ns
I0615 22:48:23.042853 24703 master.cpp:4106] Sending 1 offers to framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:23.043453 24702 sched.cpp:609] Scheduler::resourceOffers took 106636ns
I0615 22:48:23.044909 24712 master.cpp:2422] Processing ACCEPT call for offers: [ 20150615-224822-2231374252-55005-24680-O1 ] on slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f) for framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:23.044960 24712 master.cpp:2266] Authorizing framework principal '' to launch task 1 as user 'mesos'
I0615 22:48:23.046041 24712 master.hpp:159] Adding task 1 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 (266bbfb8797f)
I0615 22:48:23.046138 24712 master.cpp:2749] Launching task 1 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:23.046447 24698 slave.cpp:1211] Got assigned task 1 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.046512 24712 hierarchical.hpp:741] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.046679 24712 hierarchical.hpp:777] Framework 20150615-224822-2231374252-55005-24680-0000 filtered slave 20150615-224822-2231374252-55005-24680-S0 for 5secs
I0615 22:48:23.047173 24698 slave.cpp:1325] Launching task 1 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.052340 24698 slave.cpp:4873] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/executor.info'
I0615 22:48:23.053014 24698 slave.cpp:4510] Launching executor 1 of framework 20150615-224822-2231374252-55005-24680-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b'
I0615 22:48:23.053432 24702 containerizer.cpp:530] Starting container 'b3b4f1f9-c172-4c43-b129-99230b0b1a0b' for executor '1' of framework '20150615-224822-2231374252-55005-24680-0000'
I0615 22:48:23.053601 24698 slave.cpp:4896] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b/tasks/1/task.info'
I0615 22:48:23.054136 24698 slave.cpp:1471] Queuing task '1' for executor 1 of framework '20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.054265 24698 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b'
I0615 22:48:23.056098 24702 launcher.cpp:131] Forked child with pid '29521' for container 'b3b4f1f9-c172-4c43-b129-99230b0b1a0b'
I0615 22:48:23.056392 24702 containerizer.cpp:766] Checkpointing executor's forked pid 29521 to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b/pids/forked.pid'
I0615 22:48:23.058200 24704 fetcher.cpp:299] Starting to fetch URIs for container: b3b4f1f9-c172-4c43-b129-99230b0b1a0b, directory: /tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b
I0615 22:48:23.068907 24702 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.23.0/_build/src/mesos-fetcher'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0615 22:48:23.230368 29558 process.cpp:926] libprocess is initialized on 172.17.0.133:44872 for 16 cpus
I0615 22:48:23.232218 29558 logging.cpp:177] Logging to STDERR
I0615 22:48:23.234447 29558 exec.cpp:132] Version: 0.23.0
I0615 22:48:23.247771 29581 exec.cpp:182] Executor started at: executor(1)@172.17.0.133:44872 with pid 29558
I0615 22:48:23.253686 24698 slave.cpp:2223] Got registration for executor '1' of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:44872
I0615 22:48:23.253865 24698 slave.cpp:2309] Checkpointing executor pid 'executor(1)@172.17.0.133:44872' to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b/pids/libprocess.pid'
I0615 22:48:23.256191 24706 slave.cpp:1623] Sending queued task '1' to executor '1' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.257499 29582 exec.cpp:206] Executor registered on slave 20150615-224822-2231374252-55005-24680-S0
I0615 22:48:23.259575 29582 exec.cpp:218] Executor::registered took 344606ns
Registered executor on 266bbfb8797f
I0615 22:48:23.260124 29582 exec.cpp:293] Executor asked to run task '1'
Starting task 1
I0615 22:48:23.260272 29582 exec.cpp:302] Executor::launchTask took 134001ns
sh -c './mesos-fetcher-test-cmd 1'
Forked command at 29589
I0615 22:48:23.263803 29586 exec.cpp:509] Executor sending status update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.264967 24707 slave.cpp:2562] Handling status update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:44872
I0615 22:48:23.265245 24708 status_update_manager.cpp:321] Received status update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.265331 24708 status_update_manager.cpp:498] Creating StatusUpdate stream for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.265781 24708 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.321219 24708 status_update_manager.cpp:375] Forwarding update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:23.321508 24699 slave.cpp:2817] Forwarding the update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:23.321703 24699 slave.cpp:2744] Status update manager successfully handled status update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.321733 24699 slave.cpp:2750] Sending acknowledgement for status update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:44872
I0615 22:48:23.321831 24707 master.cpp:3580] Status update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:23.322082 24707 master.cpp:3619] Forwarding status update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.322438 24707 master.cpp:4973] Updating the latest state of task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_RUNNING
I0615 22:48:23.322818 24713 sched.cpp:715] Scheduler::statusUpdate took 162452ns
I0615 22:48:23.323274 24711 master.cpp:3013] Forwarding status update acknowledgement 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6 for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:23.323493 24713 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.323748 24713 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_RUNNING (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.323740 29576 exec.cpp:339] Executor received status update acknowledgement 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6 for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
Command exited with status 0 (pid: 29589)
I0615 22:48:23.364934 29584 exec.cpp:509] Executor sending status update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.365722 24698 slave.cpp:2562] Handling status update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:44872
I0615 22:48:23.365818 24698 slave.cpp:4811] Terminating task 1
I0615 22:48:23.384138 24713 status_update_manager.cpp:321] Received status update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.384182 24701 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: 835dbc23-85fe-49ae-a7b2-c2aef3f57fc6) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.384212 24713 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.451077 24713 status_update_manager.cpp:375] Forwarding update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:23.451571 24713 slave.cpp:2817] Forwarding the update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:23.451741 24713 slave.cpp:2744] Status update manager successfully handled status update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.451956 24713 slave.cpp:2750] Sending acknowledgement for status update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:44872
I0615 22:48:23.452005 24700 master.cpp:3580] Status update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:23.452227 24700 master.cpp:3619] Forwarding status update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.452450 24700 master.cpp:4973] Updating the latest state of task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_FINISHED
I0615 22:48:23.452739 24712 sched.cpp:715] Scheduler::statusUpdate took 125815ns
I0615 22:48:23.452965 24711 hierarchical.hpp:741] Recovered cpus(*):1; mem(*):1 (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.453434 24700 master.cpp:5041] Removing task 1 with resources cpus(*):1; mem(*):1 of framework 20150615-224822-2231374252-55005-24680-0000 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:23.453673 24700 master.cpp:3013] Forwarding status update acknowledgement eef5197e-78ec-4a6e-b55c-e98b03819ea8 for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:23.454031 24713 status_update_manager.cpp:393] Received status update acknowledgement (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.454210 24713 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_FINISHED (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.454414 29580 exec.cpp:339] Executor received status update acknowledgement eef5197e-78ec-4a6e-b55c-e98b03819ea8 for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.517969 24713 status_update_manager.cpp:529] Cleaning up status update stream for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.518391 24712 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: eef5197e-78ec-4a6e-b55c-e98b03819ea8) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.518501 24712 slave.cpp:4852] Completing task 1
I0615 22:48:23.863066 24707 containerizer.cpp:1184] Executor for container '794071a8-cc49-4ca6-a6bf-78d134bc44ab' has exited
I0615 22:48:23.863118 24707 containerizer.cpp:997] Destroying container '794071a8-cc49-4ca6-a6bf-78d134bc44ab'
I0615 22:48:23.866014 24705 slave.cpp:3248] Executor '0' of framework 20150615-224822-2231374252-55005-24680-0000 exited with status 0
I0615 22:48:23.866101 24705 slave.cpp:3354] Cleaning up executor '0' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:23.866408 24712 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab' for gc 6.9999899729037days in the future
I0615 22:48:23.866847 24712 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0' for gc 6.99998997123852days in the future
I0615 22:48:23.866960 24712 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab' for gc 6.99998996984889days in the future
I0615 22:48:23.867066 24712 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0' for gc 6.99998996882074days in the future
I0615 22:48:24.044549 24702 hierarchical.hpp:834] Performed allocation for 1 slaves in 560278ns
I0615 22:48:24.044885 24698 master.cpp:4106] Sending 1 offers to framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:24.045385 24704 sched.cpp:609] Scheduler::resourceOffers took 162418ns
I0615 22:48:24.046632 24708 master.cpp:2422] Processing ACCEPT call for offers: [ 20150615-224822-2231374252-55005-24680-O2 ] on slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f) for framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:24.046684 24708 master.cpp:2266] Authorizing framework principal '' to launch task 2 as user 'mesos'
I0615 22:48:24.047765 24708 master.hpp:159] Adding task 2 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 (266bbfb8797f)
I0615 22:48:24.047873 24708 master.cpp:2749] Launching task 2 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:24.048192 24710 slave.cpp:1211] Got assigned task 2 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.048285 24708 hierarchical.hpp:741] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.048334 24708 hierarchical.hpp:777] Framework 20150615-224822-2231374252-55005-24680-0000 filtered slave 20150615-224822-2231374252-55005-24680-S0 for 5secs
I0615 22:48:24.048854 24710 slave.cpp:1325] Launching task 2 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.054090 24710 slave.cpp:4873] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/executor.info'
I0615 22:48:24.054831 24710 slave.cpp:4510] Launching executor 2 of framework 20150615-224822-2231374252-55005-24680-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/c9b13cc7-54d1-41ed-b895-672fc2275d16'
I0615 22:48:24.055274 24700 containerizer.cpp:530] Starting container 'c9b13cc7-54d1-41ed-b895-672fc2275d16' for executor '2' of framework '20150615-224822-2231374252-55005-24680-0000'
I0615 22:48:24.055444 24710 slave.cpp:4896] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/c9b13cc7-54d1-41ed-b895-672fc2275d16/tasks/2/task.info'
I0615 22:48:24.055922 24710 slave.cpp:1471] Queuing task '2' for executor 2 of framework '20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.056046 24710 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/c9b13cc7-54d1-41ed-b895-672fc2275d16'
I0615 22:48:24.057868 24700 launcher.cpp:131] Forked child with pid '29594' for container 'c9b13cc7-54d1-41ed-b895-672fc2275d16'
I0615 22:48:24.058058 24700 containerizer.cpp:766] Checkpointing executor's forked pid 29594 to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/c9b13cc7-54d1-41ed-b895-672fc2275d16/pids/forked.pid'
I0615 22:48:24.060298 24705 fetcher.cpp:299] Starting to fetch URIs for container: c9b13cc7-54d1-41ed-b895-672fc2275d16, directory: /tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/c9b13cc7-54d1-41ed-b895-672fc2275d16
I0615 22:48:24.070935 24712 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.23.0/_build/src/mesos-fetcher'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0615 22:48:24.341466 29631 process.cpp:926] libprocess is initialized on 172.17.0.133:34155 for 16 cpus
I0615 22:48:24.343353 29631 logging.cpp:177] Logging to STDERR
I0615 22:48:24.346472 29631 exec.cpp:132] Version: 0.23.0
I0615 22:48:24.351649 29659 exec.cpp:182] Executor started at: executor(1)@172.17.0.133:34155 with pid 29631
I0615 22:48:24.355754 24712 slave.cpp:2223] Got registration for executor '2' of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:34155
I0615 22:48:24.356001 24712 slave.cpp:2309] Checkpointing executor pid 'executor(1)@172.17.0.133:34155' to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/c9b13cc7-54d1-41ed-b895-672fc2275d16/pids/libprocess.pid'
I0615 22:48:24.357667 24712 slave.cpp:1623] Sending queued task '2' to executor '2' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.359133 29651 exec.cpp:206] Executor registered on slave 20150615-224822-2231374252-55005-24680-S0
IRegistered executor on 266bbfb8797f
0615 22:48:24.361985 29651 exec.cpp:218] Executor::registered took 593848ns
I0615 22:48:24.362882 29651 exec.cpp:293] Executor asked to run task '2'
Starting task 2
I0615 22:48:24.363051 29651 exec.cpp:302] Executor::launchTask took 150952ns
sh -c './mesos-fetcher-test-cmd 2'
Forked command at 29662
I0615 22:48:24.367565 29655 exec.cpp:509] Executor sending status update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.369005 24700 slave.cpp:2562] Handling status update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:34155
I0615 22:48:24.369295 24703 status_update_manager.cpp:321] Received status update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.369336 24703 status_update_manager.cpp:498] Creating StatusUpdate stream for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.369793 24703 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.421576 24703 status_update_manager.cpp:375] Forwarding update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:24.421917 24698 slave.cpp:2817] Forwarding the update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:24.422165 24698 slave.cpp:2744] Status update manager successfully handled status update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.422194 24698 slave.cpp:2750] Sending acknowledgement for status update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:34155
I0615 22:48:24.422297 24703 master.cpp:3580] Status update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:24.422329 24703 master.cpp:3619] Forwarding status update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.422452 24703 master.cpp:4973] Updating the latest state of task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_RUNNING
I0615 22:48:24.422705 24703 sched.cpp:715] Scheduler::statusUpdate took 106144ns
I0615 22:48:24.422901 24703 master.cpp:3013] Forwarding status update acknowledgement c238bc57-db0b-4d58-9ee2-fb8130a1b64e for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:24.423146 24703 status_update_manager.cpp:393] Received status update acknowledgement (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.423229 24703 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_RUNNING (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.424090 29652 exec.cpp:339] Executor received status update acknowledgement c238bc57-db0b-4d58-9ee2-fb8130a1b64e for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
Command exited with status 0 (pid: 29662)
I0615 22:48:24.467972 24710 containerizer.cpp:1184] Executor for container 'b3b4f1f9-c172-4c43-b129-99230b0b1a0b' has exited
I0615 22:48:24.468021 24710 containerizer.cpp:997] Destroying container 'b3b4f1f9-c172-4c43-b129-99230b0b1a0b'
I0615 22:48:24.469097 29649 exec.cpp:509] Executor sending status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.470098 24710 slave.cpp:2562] Handling status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:34155
I0615 22:48:24.470196 24710 slave.cpp:4811] Terminating task 2
I0615 22:48:24.471344 24698 slave.cpp:3248] Executor '1' of framework 20150615-224822-2231374252-55005-24680-0000 exited with status 0
I0615 22:48:24.471417 24698 slave.cpp:3354] Cleaning up executor '1' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.471740 24703 status_update_manager.cpp:321] Received status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.471868 24708 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b' for gc 6.99999453986074days in the future
I0615 22:48:24.471997 24708 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1' for gc 6.99999453824296days in the future
I0615 22:48:24.472153 24698 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: c238bc57-db0b-4d58-9ee2-fb8130a1b64e) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.472185 24708 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b' for gc 6.99999453708148days in the future
I0615 22:48:24.472275 24708 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1' for gc 6.99999453610074days in the future
I0615 22:48:24.471794 24703 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.522269 24703 status_update_manager.cpp:375] Forwarding update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:24.522579 24699 slave.cpp:2817] Forwarding the update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:24.522814 24699 slave.cpp:2744] Status update manager successfully handled status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.522913 24699 slave.cpp:2750] Sending acknowledgement for status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:34155
I0615 22:48:24.522913 24703 master.cpp:3580] Status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:24.523624 24703 master.cpp:3619] Forwarding status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.523993 24703 master.cpp:4973] Updating the latest state of task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_FINISHED
I0615 22:48:24.524289 29650 exec.cpp:339] Executor received status update acknowledgement 08099f40-2437-4173-90f5-9dc7c94c7603 for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.524207 24702 sched.cpp:715] Scheduler::statusUpdate took 126126ns
I0615 22:48:24.524883 24703 master.cpp:5041] Removing task 2 with resources cpus(*):1; mem(*):1 of framework 20150615-224822-2231374252-55005-24680-0000 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:24.525044 24703 master.cpp:3013] Forwarding status update acknowledgement 08099f40-2437-4173-90f5-9dc7c94c7603 for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:24.525204 24680 slave.cpp:560] Slave terminating
I0615 22:48:24.525277 24710 hierarchical.hpp:741] Recovered cpus(*):1; mem(*):1 (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.525460 24703 master.cpp:999] Slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f) disconnected
I0615 22:48:24.525492 24703 master.cpp:2134] Disconnecting slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:24.525578 24703 master.cpp:2153] Deactivating slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:24.525852 24705 hierarchical.hpp:603] Slave 20150615-224822-2231374252-55005-24680-S0 deactivated
I0615 22:48:24.528178 24680 containerizer.cpp:111] Using isolation: posix/cpu,posix/mem
I0615 22:48:24.532331 24706 slave.cpp:187] Slave started on 49)@172.17.0.133:55005
I0615 22:48:24.532467 24706 slave.cpp:188] Flags at startup: --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_HttpCachedRecovery_eTAiVx/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_remove_delay="6hrs" --docker_sandbox_directory="/mnt/mesos/sandbox" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.23.0/_build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resource_monitoring_interval="1secs" --resources="cpus(*):1000; mem(*):1000" --revocable_cpu_low_priority="true" --strict="true" --switch_user="true" --version="false" --work_dir="/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx"
I0615 22:48:24.533128 24706 credentials.hpp:85] Loading credential for authentication from '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/credential'
I0615 22:48:24.533390 24706 slave.cpp:318] Slave using credential for: test-principal
I0615 22:48:24.534016 24706 slave.cpp:352] Slave resources: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
I0615 22:48:24.534116 24706 slave.cpp:382] Slave hostname: 266bbfb8797f
I0615 22:48:24.534133 24706 slave.cpp:387] Slave checkpoint: true
I0615 22:48:24.534883 24699 state.cpp:35] Recovering state from '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta'
I0615 22:48:24.535001 24699 state.cpp:671] Failed to find resources file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/resources/resources.info'
I0615 22:48:24.542053 24703 fetcher.cpp:77] Clearing fetcher cache
I0615 22:48:24.542477 24703 slave.cpp:4007] Recovering framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.542609 24703 slave.cpp:4622] Recovering executor '2' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.542948 24703 slave.cpp:4811] Terminating task 2
I0615 22:48:24.543180 24703 slave.cpp:4622] Recovering executor '1' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.543459 24703 slave.cpp:4811] Terminating task 1
I0615 22:48:24.543555 24703 slave.cpp:4852] Completing task 1
I0615 22:48:24.543812 24698 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b' for gc 6.99999370683852days in the future
I0615 22:48:24.543967 24698 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b' for gc 6.99999370486222days in the future
I0615 22:48:24.544077 24703 slave.cpp:4622] Recovering executor '0' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.544101 24698 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1' for gc 6.99999370415407days in the future
I0615 22:48:24.544184 24698 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1' for gc 6.99999370356444days in the future
I0615 22:48:24.544404 24703 slave.cpp:4811] Terminating task 0
I0615 22:48:24.544483 24703 slave.cpp:4852] Completing task 0
I0615 22:48:24.544761 24708 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab' for gc 6.99998212180444days in the future
I0615 22:48:24.544878 24708 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab' for gc 6.99998212047407days in the future
I0615 22:48:24.544984 24708 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0' for gc 6.99998211978963days in the future
I0615 22:48:24.545060 24708 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0' for gc 6.9999821191437days in the future
I0615 22:48:24.545574 24702 status_update_manager.cpp:201] Recovering status update manager
I0615 22:48:24.545608 24702 status_update_manager.cpp:209] Recovering executor '2' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.545769 24702 status_update_manager.cpp:498] Creating StatusUpdate stream for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.546144 24702 status_update_manager.cpp:797] Replaying status update stream for task 2
I0615 22:48:24.546249 24702 status_update_manager.cpp:209] Recovering executor '0' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.546340 24702 status_update_manager.cpp:234] Skipping recovering updates of executor '0' of framework 20150615-224822-2231374252-55005-24680-0000 because its latest run 794071a8-cc49-4ca6-a6bf-78d134bc44ab is completed
I0615 22:48:24.546381 24702 status_update_manager.cpp:209] Recovering executor '1' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.546485 24702 status_update_manager.cpp:234] Skipping recovering updates of executor '1' of framework 20150615-224822-2231374252-55005-24680-0000 because its latest run b3b4f1f9-c172-4c43-b129-99230b0b1a0b is completed
I0615 22:48:24.546771 24703 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/c9b13cc7-54d1-41ed-b895-672fc2275d16'
I0615 22:48:24.546823 24703 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/b3b4f1f9-c172-4c43-b129-99230b0b1a0b'
I0615 22:48:24.546866 24703 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/794071a8-cc49-4ca6-a6bf-78d134bc44ab'
I0615 22:48:24.547605 24710 containerizer.cpp:312] Recovering containerizer
I0615 22:48:24.547695 24710 containerizer.cpp:367] Recovering container 'c9b13cc7-54d1-41ed-b895-672fc2275d16' for executor '2' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.547842 24710 containerizer.cpp:348] Skipping recovery of executor '0' of framework 20150615-224822-2231374252-55005-24680-0000 because its latest run 794071a8-cc49-4ca6-a6bf-78d134bc44ab is completed
I0615 22:48:24.547919 24710 containerizer.cpp:348] Skipping recovery of executor '1' of framework 20150615-224822-2231374252-55005-24680-0000 because its latest run b3b4f1f9-c172-4c43-b129-99230b0b1a0b is completed
I0615 22:48:24.548948 24707 slave.cpp:3859] Sending reconnect request to executor 2 of framework 20150615-224822-2231374252-55005-24680-0000 at executor(1)@172.17.0.133:34155
I0615 22:48:24.549924 29655 exec.cpp:252] Received reconnect request from slave 20150615-224822-2231374252-55005-24680-S0
I0615 22:48:24.551198 24704 slave.cpp:2374] Re-registering executor 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:24.552144 29660 exec.cpp:229] Executor re-registered on slave 20150615-224822-2231374252-55005-24680-S0
I0615 22:48:24.553678 29660 exec.cpp:241] Executor::reregistered took 84337ns
I0615 22:48:25.045651 24701 hierarchical.hpp:933] No resources available to allocate!
I0615 22:48:25.045706 24701 hierarchical.hpp:834] Performed allocation for 1 slaves in 117291ns
Re-registered executor on 266bbfb8797f
I0615 22:48:25.475556 24708 containerizer.cpp:1184] Executor for container 'c9b13cc7-54d1-41ed-b895-672fc2275d16' has exited
I0615 22:48:25.475618 24708 containerizer.cpp:997] Destroying container 'c9b13cc7-54d1-41ed-b895-672fc2275d16'
I0615 22:48:25.478549 24709 slave.cpp:3248] Executor '2' of framework 20150615-224822-2231374252-55005-24680-0000 exited with status 0
I0615 22:48:26.046739 24698 hierarchical.hpp:933] No resources available to allocate!
I0615 22:48:26.046794 24698 hierarchical.hpp:834] Performed allocation for 1 slaves in 102603ns
I0615 22:48:26.550570 24709 slave.cpp:2511] Cleaning up un-reregistered executors
I0615 22:48:26.550696 24709 slave.cpp:3918] Finished recovery
I0615 22:48:26.551288 24709 slave.cpp:4072] Querying resource estimator for oversubscribable resources
I0615 22:48:26.551621 24704 status_update_manager.cpp:175] Pausing sending status updates
I0615 22:48:26.551622 24709 slave.cpp:678] New master detected at master@172.17.0.133:55005
I0615 22:48:26.551769 24709 slave.cpp:741] Authenticating with master master@172.17.0.133:55005
I0615 22:48:26.551887 24709 slave.cpp:746] Using default CRAM-MD5 authenticatee
I0615 22:48:26.552062 24709 slave.cpp:714] Detecting new master
I0615 22:48:26.552111 24707 authenticatee.hpp:139] Creating new client SASL connection
I0615 22:48:26.552180 24709 slave.cpp:4086] Received oversubscribable resources from the resource estimator
I0615 22:48:26.552404 24707 master.cpp:4187] Authenticating slave(49)@172.17.0.133:55005
I0615 22:48:26.552562 24709 authenticator.cpp:406] Starting authentication session for crammd5_authenticatee(144)@172.17.0.133:55005
I0615 22:48:26.552783 24702 authenticator.cpp:92] Creating new server SASL connection
I0615 22:48:26.552949 24709 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
I0615 22:48:26.552989 24709 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
I0615 22:48:26.553099 24712 authenticator.cpp:197] Received SASL authentication start
I0615 22:48:26.553159 24712 authenticator.cpp:319] Authentication requires more steps
I0615 22:48:26.553243 24712 authenticatee.hpp:276] Received SASL authentication step
I0615 22:48:26.553335 24712 authenticator.cpp:225] Received SASL authentication step
I0615 22:48:26.553366 24712 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '266bbfb8797f' server FQDN: '266bbfb8797f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0615 22:48:26.553385 24712 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I0615 22:48:26.553441 24712 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0615 22:48:26.553479 24712 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '266bbfb8797f' server FQDN: '266bbfb8797f' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0615 22:48:26.553498 24712 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0615 22:48:26.553508 24712 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0615 22:48:26.553587 24712 authenticator.cpp:311] Authentication success
I0615 22:48:26.553728 24712 authenticatee.hpp:316] Authentication success
I0615 22:48:26.553807 24712 master.cpp:4217] Successfully authenticated principal 'test-principal' at slave(49)@172.17.0.133:55005
I0615 22:48:26.553894 24712 authenticator.cpp:424] Authentication session cleanup for crammd5_authenticatee(144)@172.17.0.133:55005
I0615 22:48:26.554157 24712 slave.cpp:812] Successfully authenticated with master master@172.17.0.133:55005
I0615 22:48:26.554421 24712 slave.cpp:1171] Will retry registration in 3.394201ms if necessary
I0615 22:48:26.554769 24709 master.cpp:3297] Re-registering slave 20150615-224822-2231374252-55005-24680-S0 at slave(48)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.555047 24704 slave.cpp:939] Re-registered with master master@172.17.0.133:55005
I0615 22:48:26.555093 24704 slave.cpp:963] Forwarding total oversubscribed resources
I0615 22:48:26.555088 24709 master.cpp:3447] Sending updated checkpointed resources to slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.555229 24704 slave.cpp:2006] Updating framework 20150615-224822-2231374252-55005-24680-0000 pid to scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:26.555258 24709 master.cpp:3509] Received update of slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f) with total oversubscribed resources
I0615 22:48:26.555294 24704 slave.cpp:2014] Checkpointing framework pid 'scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005' to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/framework.pid'
I0615 22:48:26.555387 24709 hierarchical.hpp:589] Slave 20150615-224822-2231374252-55005-24680-S0 reactivated
I0615 22:48:26.555541 24709 hierarchical.hpp:570] Slave 20150615-224822-2231374252-55005-24680-S0 (266bbfb8797f) updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], available: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000])
I0615 22:48:26.555969 24709 hierarchical.hpp:852] Performed allocation for slave 20150615-224822-2231374252-55005-24680-S0 in 393487ns
I0615 22:48:26.556004 24704 slave.cpp:2092] Updated checkpointed resources from to
I0615 22:48:26.556022 24709 status_update_manager.cpp:182] Resuming sending status updates
W0615 22:48:26.556064 24709 status_update_manager.cpp:189] Resending status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.556103 24709 status_update_manager.cpp:375] Forwarding update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:26.556274 24709 status_update_manager.cpp:182] Resuming sending status updates
W0615 22:48:26.556304 24709 status_update_manager.cpp:189] Resending status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.556331 24709 status_update_manager.cpp:375] Forwarding update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:26.556471 24704 slave.cpp:2817] Forwarding the update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:26.556751 24704 slave.cpp:2817] Forwarding the update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:26.556897 24707 master.cpp:4106] Sending 1 offers to framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:26.557135 24707 master.cpp:3580] Status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.557165 24707 master.cpp:3619] Forwarding status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
W0615 22:48:26.557238 24707 master.cpp:3588] Could not lookup task for status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.557374 24707 master.cpp:3580] Status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.557412 24709 sched.cpp:609] Scheduler::resourceOffers took 243129ns
I0615 22:48:26.557411 24707 master.cpp:3619] Forwarding status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
W0615 22:48:26.557626 24707 master.cpp:3588] Could not lookup task for status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.557677 24709 sched.cpp:715] Scheduler::statusUpdate took 33975ns
I0615 22:48:26.558060 24709 sched.cpp:715] Scheduler::statusUpdate took 34311ns
I0615 22:48:26.558277 24708 master.cpp:3013] Forwarding status update acknowledgement 08099f40-2437-4173-90f5-9dc7c94c7603 for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.558676 24708 master.cpp:3013] Forwarding status update acknowledgement 08099f40-2437-4173-90f5-9dc7c94c7603 for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.558794 24710 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
../../src/tests/fetcher_cache_tests.cpp:1145: Failure
Value of: fetcherProcess->cacheFiles(slaveId, flags).get().size()
Actual: 0
Expected: 1u
Which is: 1
../../src/tests/fetcher_cache_tests.cpp:1149: Failure
Value of: httpServer->countCommandRequests
Actual: 0
Expected: 2u
Which is: 2
I0615 22:48:26.559114 24710 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_FINISHED (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.559407 24708 master.cpp:2422] Processing ACCEPT call for offers: [ 20150615-224822-2231374252-55005-24680-O3 ] on slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f) for framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:26.559447 24708 master.cpp:2266] Authorizing framework principal '' to launch task 0 as user 'mesos'
I0615 22:48:26.560467 24708 master.hpp:159] Adding task 0 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 (266bbfb8797f)
I0615 22:48:26.560600 24708 master.cpp:2749] Launching task 0 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.560915 24712 slave.cpp:1211] Got assigned task 0 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.561036 24708 hierarchical.hpp:741] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.561087 24708 hierarchical.hpp:777] Framework 20150615-224822-2231374252-55005-24680-0000 filtered slave 20150615-224822-2231374252-55005-24680-S0 for 5secs
I0615 22:48:26.561647 24709 gc.cpp:84] Unscheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0' from gc
I0615 22:48:26.561936 24709 gc.cpp:84] Unscheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0' from gc
I0615 22:48:26.562176 24708 slave.cpp:1325] Launching task 0 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.567335 24708 slave.cpp:4873] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/executor.info'
I0615 22:48:26.567984 24708 slave.cpp:4510] Launching executor 0 of framework 20150615-224822-2231374252-55005-24680-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/30cbc14c-e934-46b5-ae86-ff83ba9c3aa9'
I0615 22:48:26.568459 24703 containerizer.cpp:530] Starting container '30cbc14c-e934-46b5-ae86-ff83ba9c3aa9' for executor '0' of framework '20150615-224822-2231374252-55005-24680-0000'
I0615 22:48:26.568519 24708 slave.cpp:4896] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/30cbc14c-e934-46b5-ae86-ff83ba9c3aa9/tasks/0/task.info'
I0615 22:48:26.569089 24708 slave.cpp:1471] Queuing task '0' for executor 0 of framework '20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.569212 24708 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/30cbc14c-e934-46b5-ae86-ff83ba9c3aa9'
I0615 22:48:26.570787 24703 launcher.cpp:131] Forked child with pid '29667' for container '30cbc14c-e934-46b5-ae86-ff83ba9c3aa9'
I0615 22:48:26.570951 24703 containerizer.cpp:766] Checkpointing executor's forked pid 29667 to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/30cbc14c-e934-46b5-ae86-ff83ba9c3aa9/pids/forked.pid'
I0615 22:48:26.572517 24713 fetcher.cpp:299] Starting to fetch URIs for container: 30cbc14c-e934-46b5-ae86-ff83ba9c3aa9, directory: /tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/30cbc14c-e934-46b5-ae86-ff83ba9c3aa9
I0615 22:48:26.599771 24713 fetcher.cpp:873] Created cache entry 'mesos@http://172.17.0.133:55005/(1432)/mesos-fetcher-test-cmd' with file: c1-mesos-fetc_r-test-cmd
I0615 22:48:26.600739 24712 fetcher.cpp:248] Fetching size for URI: http://172.17.0.133:55005/(1432)/mesos-fetcher-test-cmd
I0615 22:48:26.601469 24707 process.cpp:2749] Handling HTTP event for process '(1432)' with path: '/(1432)/mesos-fetcher-test-cmd'
I0615 22:48:26.601914 24707 process.cpp:1082] Sending file at '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
HTTP/1.1 200 OK
Date: Mon, 15 Jun 2015 22:48:26 GMT
Content-Length: 30
I0615 22:48:26.602509 24707 fetcher.cpp:663] Claiming fetcher cache space for: mesos@http://172.17.0.133:55005/(1432)/mesos-fetcher-test-cmd
I0615 22:48:26.602742 24707 fetcher.cpp:1086] Claimed cache space: 30B, now using: 30B
I0615 22:48:26.607974 24699 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.23.0/_build/src/mesos-fetcher'
I0615 22:48:26.641422 24710 status_update_manager.cpp:529] Cleaning up status update stream for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.641885 24705 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.641990 24705 slave.cpp:4852] Completing task 2
I0615 22:48:26.642101 24705 slave.cpp:3354] Cleaning up executor '2' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.642557 24710 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.642562 24704 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/c9b13cc7-54d1-41ed-b895-672fc2275d16' for gc 6.99999256444444days in the future
I0615 22:48:26.642791 24703 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2' for gc 6.99999256133333days in the future
I0615 22:48:26.642901 24703 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/c9b13cc7-54d1-41ed-b895-672fc2275d16' for gc 6.99999256034667days in the future
E0615 22:48:26.642917 24705 slave.cpp:2156] Failed to handle status update acknowledgement (UUID: 08099f40-2437-4173-90f5-9dc7c94c7603) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000: Cannot find the status update stream for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.643090 24703 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2' for gc 6.99999255964148days in the future
I0615 22:48:26.681280 24698 process.cpp:2749] Handling HTTP event for process '(1432)' with path: '/(1432)/mesos-fetcher-test-cmd'
I0615 22:48:26.681721 24698 process.cpp:1082] Sending file at '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
I0615 22:48:26.784791 24713 fetcher.cpp:1098] Released cache space: 0B, now using: 30B
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0615 22:48:26.856441 29704 process.cpp:926] libprocess is initialized on 172.17.0.133:36520 for 16 cpus
I0615 22:48:26.857831 29704 logging.cpp:177] Logging to STDERR
I0615 22:48:26.859894 29704 exec.cpp:132] Version: 0.23.0
I0615 22:48:26.866421 29729 exec.cpp:182] Executor started at: executor(1)@172.17.0.133:36520 with pid 29704
I0615 22:48:26.869421 24702 slave.cpp:2223] Got registration for executor '0' of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:36520
I0615 22:48:26.869716 24702 slave.cpp:2309] Checkpointing executor pid 'executor(1)@172.17.0.133:36520' to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/30cbc14c-e934-46b5-ae86-ff83ba9c3aa9/pids/libprocess.pid'
I0615 22:48:26.871796 24700 slave.cpp:1623] Sending queued task '0' to executor '0' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.872609 29728 exec.cpp:206] Executor registered on slave 20150615-224822-2231374252-55005-24680-S0
I0615 22:48:26.874627 29728 exec.cpp:218] Executor::registered took 404201ns
Registered executor on 266bbfb8797f
I0615 22:48:26.875223 29728 exec.cpp:293] Executor asked to run task '0'
Starting task 0
I0615 22:48:26.875341 29728 exec.cpp:302] Executor::launchTask took 105362ns
Forked command at 29735
sh -c './mesos-fetcher-test-cmd 0'
I0615 22:48:26.878888 29724 exec.cpp:509] Executor sending status update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.880107 24705 slave.cpp:2562] Handling status update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:36520
I0615 22:48:26.880303 24710 status_update_manager.cpp:321] Received status update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.880455 24710 status_update_manager.cpp:498] Creating StatusUpdate stream for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.880926 24710 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.942164 24710 status_update_manager.cpp:375] Forwarding update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:26.942456 24698 slave.cpp:2817] Forwarding the update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:26.942692 24698 slave.cpp:2744] Status update manager successfully handled status update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.942720 24698 slave.cpp:2750] Sending acknowledgement for status update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:36520
I0615 22:48:26.943280 24711 master.cpp:3580] Status update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.943315 24711 master.cpp:3619] Forwarding status update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.943469 24711 master.cpp:4973] Updating the latest state of task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_RUNNING
I0615 22:48:26.943745 24707 sched.cpp:715] Scheduler::statusUpdate took 64393ns
I0615 22:48:26.944013 24708 master.cpp:3013] Forwarding status update acknowledgement 04ee8b56-e310-4f38-be4d-4b796058a404 for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:26.944020 29731 exec.cpp:339] Executor received status update acknowledgement 04ee8b56-e310-4f38-be4d-4b796058a404 for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.944228 24708 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.944383 24708 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_RUNNING (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
Command exited with status 0 (pid: 29735)
I0615 22:48:26.979601 29728 exec.cpp:509] Executor sending status update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.980365 24702 slave.cpp:2562] Handling status update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:36520
I0615 22:48:26.980455 24702 slave.cpp:4811] Terminating task 0
I0615 22:48:26.996456 24708 status_update_manager.cpp:321] Received status update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.996479 24704 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: 04ee8b56-e310-4f38-be4d-4b796058a404) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:26.996515 24708 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.046675 24708 status_update_manager.cpp:375] Forwarding update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:27.046979 24698 slave.cpp:2817] Forwarding the update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:27.047127 24698 slave.cpp:2744] Status update manager successfully handled status update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.047150 24698 slave.cpp:2750] Sending acknowledgement for status update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:36520
I0615 22:48:27.047307 24703 master.cpp:3580] Status update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:27.047351 24703 master.cpp:3619] Forwarding status update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.047497 24703 master.cpp:4973] Updating the latest state of task 0 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_FINISHED
I0615 22:48:27.047708 24713 sched.cpp:715] Scheduler::statusUpdate took 57342ns
I0615 22:48:27.048089 24703 master.cpp:5041] Removing task 0 with resources cpus(*):1; mem(*):1 of framework 20150615-224822-2231374252-55005-24680-0000 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:27.048159 24700 hierarchical.hpp:997] Filtered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150615-224822-2231374252-55005-24680-S0 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.048254 24703 master.cpp:3013] Forwarding status update acknowledgement 8676ee99-0928-4cbb-bec8-e501109c43ee for task 0 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
II0615 22:48:27.048416 29727 exec.cpp:339] Executor received status update acknowledgement 8676ee99-0928-4cbb-bec8-e501109c43ee for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
0615 22:48:27.048285 24700 hierarchical.hpp:933] No resources available to allocate!
I0615 22:48:27.048604 24700 hierarchical.hpp:834] Performed allocation for 1 slaves in 760875ns
I0615 22:48:27.048661 24703 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.048866 24703 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_FINISHED (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.048969 24700 hierarchical.hpp:741] Recovered cpus(*):1; mem(*):1 (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.096776 24703 status_update_manager.cpp:529] Cleaning up status update stream for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.097096 24703 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: 8676ee99-0928-4cbb-bec8-e501109c43ee) for task 0 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.097151 24703 slave.cpp:4852] Completing task 0
I0615 22:48:27.995479 24705 containerizer.cpp:1184] Executor for container '30cbc14c-e934-46b5-ae86-ff83ba9c3aa9' has exited
I0615 22:48:27.995543 24705 containerizer.cpp:997] Destroying container '30cbc14c-e934-46b5-ae86-ff83ba9c3aa9'
I0615 22:48:27.998263 24713 slave.cpp:3248] Executor '0' of framework 20150615-224822-2231374252-55005-24680-0000 exited with status 0
I0615 22:48:27.998343 24713 slave.cpp:3354] Cleaning up executor '0' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.998687 24701 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/30cbc14c-e934-46b5-ae86-ff83ba9c3aa9' for gc 6.99998844190815days in the future
I0615 22:48:27.998852 24701 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0' for gc 6.99998844015111days in the future
I0615 22:48:27.998951 24701 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0/runs/30cbc14c-e934-46b5-ae86-ff83ba9c3aa9' for gc 6.99998843902815days in the future
I0615 22:48:27.999006 24713 slave.cpp:3441] Cleaning up framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.999048 24701 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/0' for gc 6.99998843798519days in the future
I0615 22:48:27.999117 24704 status_update_manager.cpp:283] Closing status update streams for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:27.999150 24701 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000' for gc 6.99998843624889days in the future
I0615 22:48:27.999244 24701 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000' for gc 6.99998843537185days in the future
I0615 22:48:28.050231 24705 hierarchical.hpp:834] Performed allocation for 1 slaves in 525348ns
I0615 22:48:28.050597 24709 master.cpp:4106] Sending 1 offers to framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:28.050981 24709 sched.cpp:609] Scheduler::resourceOffers took 79701ns
I0615 22:48:28.052213 24703 master.cpp:2422] Processing ACCEPT call for offers: [ 20150615-224822-2231374252-55005-24680-O4 ] on slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f) for framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:28.052258 24703 master.cpp:2266] Authorizing framework principal '' to launch task 1 as user 'mesos'
I0615 22:48:28.053272 24703 master.hpp:159] Adding task 1 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 (266bbfb8797f)
I0615 22:48:28.053356 24703 master.cpp:2749] Launching task 1 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:28.053654 24702 slave.cpp:1211] Got assigned task 1 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.053787 24707 hierarchical.hpp:741] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.053836 24707 hierarchical.hpp:777] Framework 20150615-224822-2231374252-55005-24680-0000 filtered slave 20150615-224822-2231374252-55005-24680-S0 for 5secs
I0615 22:48:28.053922 24702 slave.cpp:4437] Checkpointing FrameworkInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/framework.info'
I0615 22:48:28.054311 24702 slave.cpp:4444] Checkpointing framework pid 'scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005' to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/framework.pid'
I0615 22:48:28.055109 24712 gc.cpp:84] Unscheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000' from gc
I0615 22:48:28.055395 24702 gc.cpp:84] Unscheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000' from gc
I0615 22:48:28.055644 24709 gc.cpp:84] Unscheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1' from gc
I0615 22:48:28.055930 24704 gc.cpp:84] Unscheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1' from gc
I0615 22:48:28.056236 24705 slave.cpp:1325] Launching task 1 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.061911 24705 slave.cpp:4873] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/executor.info'
I0615 22:48:28.062561 24705 slave.cpp:4510] Launching executor 1 of framework 20150615-224822-2231374252-55005-24680-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/4552dff9-5b03-4cf6-a2b9-7ffed59a9246'
I0615 22:48:28.062975 24710 containerizer.cpp:530] Starting container '4552dff9-5b03-4cf6-a2b9-7ffed59a9246' for executor '1' of framework '20150615-224822-2231374252-55005-24680-0000'
I0615 22:48:28.063024 24705 slave.cpp:4896] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/4552dff9-5b03-4cf6-a2b9-7ffed59a9246/tasks/1/task.info'
I0615 22:48:28.063421 24705 slave.cpp:1471] Queuing task '1' for executor 1 of framework '20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.063673 24705 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/4552dff9-5b03-4cf6-a2b9-7ffed59a9246'
I0615 22:48:28.065145 24710 launcher.cpp:131] Forked child with pid '29740' for container '4552dff9-5b03-4cf6-a2b9-7ffed59a9246'
I0615 22:48:28.065286 24710 containerizer.cpp:766] Checkpointing executor's forked pid 29740 to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/4552dff9-5b03-4cf6-a2b9-7ffed59a9246/pids/forked.pid'
I0615 22:48:28.066944 24704 fetcher.cpp:299] Starting to fetch URIs for container: 4552dff9-5b03-4cf6-a2b9-7ffed59a9246, directory: /tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/4552dff9-5b03-4cf6-a2b9-7ffed59a9246
I0615 22:48:28.076223 24704 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.23.0/_build/src/mesos-fetcher'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0615 22:48:28.266820 29777 process.cpp:926] libprocess is initialized on 172.17.0.133:50428 for 16 cpus
I0615 22:48:28.268152 29777 logging.cpp:177] Logging to STDERR
I0615 22:48:28.270114 29777 exec.cpp:132] Version: 0.23.0
I0615 22:48:28.276978 29794 exec.cpp:182] Executor started at: executor(1)@172.17.0.133:50428 with pid 29777
I0615 22:48:28.280062 24700 slave.cpp:2223] Got registration for executor '1' of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:50428
I0615 22:48:28.280272 24700 slave.cpp:2309] Checkpointing executor pid 'executor(1)@172.17.0.133:50428' to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/4552dff9-5b03-4cf6-a2b9-7ffed59a9246/pids/libprocess.pid'
I0615 22:48:28.281993 24703 slave.cpp:1623] Sending queued task '1' to executor '1' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.282822 29792 exec.cpp:206] Executor registered on slave 20150615-224822-2231374252-55005-24680-S0
Registered executor on 266bbfb8797f
I0615 22:48:28.284723 29792 exec.cpp:218] Executor::registered took 414095ns
I0615 22:48:28.285305 29792 exec.cpp:293] Executor asked to run task '1'
Starting task 1
I0615 22:48:28.285424 29792 exec.cpp:302] Executor::launchTask took 105953ns
sh -c './mesos-fetcher-test-cmd 1'
Forked command at 29808
I0615 22:48:28.288988 29795 exec.cpp:509] Executor sending status update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.290118 24711 slave.cpp:2562] Handling status update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:50428
I0615 22:48:28.290380 24701 status_update_manager.cpp:321] Received status update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.290418 24701 status_update_manager.cpp:498] Creating StatusUpdate stream for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.290894 24701 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.349802 24701 status_update_manager.cpp:375] Forwarding update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:28.350034 24699 slave.cpp:2817] Forwarding the update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:28.350306 24701 master.cpp:3580] Status update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:28.350337 24701 master.cpp:3619] Forwarding status update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.350450 24701 master.cpp:4973] Updating the latest state of task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_RUNNING
I0615 22:48:28.350606 24699 slave.cpp:2744] Status update manager successfully handled status update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.350661 24712 sched.cpp:715] Scheduler::statusUpdate took 161685ns
I0615 22:48:28.350659 24699 slave.cpp:2750] Sending acknowledgement for status update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:50428
I0615 22:48:28.350880 24708 master.cpp:3013] Forwarding status update acknowledgement 5642b224-96a6-48d9-8e0a-fcdeaa049f91 for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:28.351157 24712 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.351248 24712 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_RUNNING (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.351789 29791 exec.cpp:339] Executor received status update acknowledgement 5642b224-96a6-48d9-8e0a-fcdeaa049f91 for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
Command exited with status 0 (pid: 29808)
I0615 22:48:28.390475 29806 exec.cpp:509] Executor sending status update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.391285 24706 slave.cpp:2562] Handling status update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:50428
I0615 22:48:28.391391 24706 slave.cpp:4811] Terminating task 1
I0615 22:48:28.416780 24712 status_update_manager.cpp:321] Received status update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.416815 24705 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: 5642b224-96a6-48d9-8e0a-fcdeaa049f91) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.416851 24712 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.480381 24712 status_update_manager.cpp:375] Forwarding update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:28.480762 24702 slave.cpp:2817] Forwarding the update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:28.480926 24702 slave.cpp:2744] Status update manager successfully handled status update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.481031 24702 slave.cpp:2750] Sending acknowledgement for status update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:50428
I0615 22:48:28.481109 24713 master.cpp:3580] Status update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:28.481233 24713 master.cpp:3619] Forwarding status update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.481384 24713 master.cpp:4973] Updating the latest state of task 1 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_FINISHED
I0615 22:48:28.481616 24704 sched.cpp:715] Scheduler::statusUpdate took 174900ns
I0615 22:48:28.481793 24713 hierarchical.hpp:741] Recovered cpus(*):1; mem(*):1 (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.481863 24704 master.cpp:5041] Removing task 1 with resources cpus(*):1; mem(*):1 of framework 20150615-224822-2231374252-55005-24680-0000 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:28.482027 24704 master.cpp:3013] Forwarding status update acknowledgement 8c8e0760-aa21-423d-bdf8-25158c7a5c5e for task 1 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:28.482318 24703 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.482435 24703 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_FINISHED (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.482697 29801 exec.cpp:339] Executor received status update acknowledgement 8c8e0760-aa21-423d-bdf8-25158c7a5c5e for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.534196 24703 status_update_manager.cpp:529] Cleaning up status update stream for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.534595 24698 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: 8c8e0760-aa21-423d-bdf8-25158c7a5c5e) for task 1 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:28.534657 24698 slave.cpp:4852] Completing task 1
I0615 22:48:29.051512 24706 hierarchical.hpp:834] Performed allocation for 1 slaves in 538343ns
I0615 22:48:29.051836 24698 master.cpp:4106] Sending 1 offers to framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:29.052218 24709 sched.cpp:609] Scheduler::resourceOffers took 83997ns
I0615 22:48:29.053474 24709 master.cpp:2422] Processing ACCEPT call for offers: [ 20150615-224822-2231374252-55005-24680-O5 ] on slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f) for framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:29.053534 24709 master.cpp:2266] Authorizing framework principal '' to launch task 2 as user 'mesos'
I0615 22:48:29.054563 24709 master.hpp:159] Adding task 2 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 (266bbfb8797f)
I0615 22:48:29.054649 24709 master.cpp:2749] Launching task 2 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 with resources cpus(*):1; mem(*):1 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:29.054970 24699 slave.cpp:1211] Got assigned task 2 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.055114 24704 hierarchical.hpp:741] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.055171 24704 hierarchical.hpp:777] Framework 20150615-224822-2231374252-55005-24680-0000 filtered slave 20150615-224822-2231374252-55005-24680-S0 for 5secs
I0615 22:48:29.055727 24706 gc.cpp:84] Unscheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2' from gc
I0615 22:48:29.055964 24699 gc.cpp:84] Unscheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2' from gc
I0615 22:48:29.056150 24709 slave.cpp:1325] Launching task 2 for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.061352 24709 slave.cpp:4873] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/executor.info'
I0615 22:48:29.062011 24709 slave.cpp:4510] Launching executor 2 of framework 20150615-224822-2231374252-55005-24680-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/a2a47186-ac2b-4c14-8a72-db6e3f4e0769'
I0615 22:48:29.062366 24705 containerizer.cpp:530] Starting container 'a2a47186-ac2b-4c14-8a72-db6e3f4e0769' for executor '2' of framework '20150615-224822-2231374252-55005-24680-0000'
I0615 22:48:29.062479 24709 slave.cpp:4896] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/a2a47186-ac2b-4c14-8a72-db6e3f4e0769/tasks/2/task.info'
I0615 22:48:29.062960 24709 slave.cpp:1471] Queuing task '2' for executor 2 of framework '20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.063086 24709 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/a2a47186-ac2b-4c14-8a72-db6e3f4e0769'
I0615 22:48:29.064702 24705 launcher.cpp:131] Forked child with pid '29813' for container 'a2a47186-ac2b-4c14-8a72-db6e3f4e0769'
I0615 22:48:29.064903 24705 containerizer.cpp:766] Checkpointing executor's forked pid 29813 to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/a2a47186-ac2b-4c14-8a72-db6e3f4e0769/pids/forked.pid'
I0615 22:48:29.066596 24711 fetcher.cpp:299] Starting to fetch URIs for container: a2a47186-ac2b-4c14-8a72-db6e3f4e0769, directory: /tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/a2a47186-ac2b-4c14-8a72-db6e3f4e0769
I0615 22:48:29.076148 24700 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.23.0/_build/src/mesos-fetcher'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0615 22:48:29.274803 29850 process.cpp:926] libprocess is initialized on 172.17.0.133:34032 for 16 cpus
I0615 22:48:29.276015 29850 logging.cpp:177] Logging to STDERR
I0615 22:48:29.277884 29850 exec.cpp:132] Version: 0.23.0
I0615 22:48:29.283953 29876 exec.cpp:182] Executor started at: executor(1)@172.17.0.133:34032 with pid 29850
I0615 22:48:29.286483 24704 slave.cpp:2223] Got registration for executor '2' of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:34032
I0615 22:48:29.286607 24704 slave.cpp:2309] Checkpointing executor pid 'executor(1)@172.17.0.133:34032' to '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/a2a47186-ac2b-4c14-8a72-db6e3f4e0769/pids/libprocess.pid'
I0615 22:48:29.288462 24705 slave.cpp:1623] Sending queued task '2' to executor '2' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.288866 29868 exec.cpp:206] Executor registered on slave 20150615-224822-2231374252-55005-24680-S0
I0615 22:48:29.290666 29868 exec.cpp:218] Executor::registered took 332582ns
Registered executor on 266bbfb8797f
I0615 22:48:29.291173 29868 exec.cpp:293] Executor asked to run task '2'
Starting task 2
I0615 22:48:29.291301 29868 exec.cpp:302] Executor::launchTask took 115171ns
sh -c './mesos-fetcher-test-cmd 2'
Forked command at 29881
I0615 22:48:29.294538 29871 exec.cpp:509] Executor sending status update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.295816 24711 slave.cpp:2562] Handling status update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:34032
I0615 22:48:29.296133 24711 status_update_manager.cpp:321] Received status update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.296165 24711 status_update_manager.cpp:498] Creating StatusUpdate stream for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.296679 24711 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.348251 24711 status_update_manager.cpp:375] Forwarding update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:29.348695 24701 slave.cpp:2817] Forwarding the update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:29.348902 24701 slave.cpp:2744] Status update manager successfully handled status update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.348937 24701 slave.cpp:2750] Sending acknowledgement for status update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:34032
I0615 22:48:29.349686 24701 master.cpp:3580] Status update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:29.349889 24701 master.cpp:3619] Forwarding status update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.350155 24701 master.cpp:4973] Updating the latest state of task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_RUNNING
I0615 22:48:29.350400 24702 sched.cpp:715] Scheduler::statusUpdate took 118233ns
I0615 22:48:29.350518 29866 exec.cpp:339] Executor received status update acknowledgement 8445151c-cda1-4e94-931a-825c99ec81f7 for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.350807 24710 master.cpp:3013] Forwarding status update acknowledgement 8445151c-cda1-4e94-931a-825c99ec81f7 for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:29.351016 24710 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.351128 24710 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_RUNNING (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
Command exited with status 0 (pid: 29881)
I0615 22:48:29.395364 29872 exec.cpp:509] Executor sending status update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.396250 24701 slave.cpp:2562] Handling status update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from executor(1)@172.17.0.133:34032
I0615 22:48:29.396390 24701 slave.cpp:4811] Terminating task 2
I0615 22:48:29.398447 24710 status_update_manager.cpp:321] Received status update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.398483 24705 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: 8445151c-cda1-4e94-931a-825c99ec81f7) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.398514 24710 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.405921 24708 containerizer.cpp:1184] Executor for container '4552dff9-5b03-4cf6-a2b9-7ffed59a9246' has exited
I0615 22:48:29.405966 24708 containerizer.cpp:997] Destroying container '4552dff9-5b03-4cf6-a2b9-7ffed59a9246'
I0615 22:48:29.408975 24709 slave.cpp:3248] Executor '1' of framework 20150615-224822-2231374252-55005-24680-0000 exited with status 0
I0615 22:48:29.409056 24709 slave.cpp:3354] Cleaning up executor '1' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.415179 24703 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/4552dff9-5b03-4cf6-a2b9-7ffed59a9246' for gc 6.99999519561482days in the future
I0615 22:48:29.415391 24703 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1' for gc 6.99999519391111days in the future
I0615 22:48:29.415480 24703 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1/runs/4552dff9-5b03-4cf6-a2b9-7ffed59a9246' for gc 6.99999519289481days in the future
I0615 22:48:29.415598 24703 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/1' for gc 6.99999519205926days in the future
I0615 22:48:29.448796 24710 status_update_manager.cpp:375] Forwarding update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to the slave
I0615 22:48:29.449093 24699 slave.cpp:2817] Forwarding the update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to master@172.17.0.133:55005
I0615 22:48:29.449386 24699 slave.cpp:2744] Status update manager successfully handled status update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.449468 24699 slave.cpp:2750] Sending acknowledgement for status update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to executor(1)@172.17.0.133:34032
I0615 22:48:29.449517 24707 master.cpp:3580] Status update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 from slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:29.449568 24707 master.cpp:3619] Forwarding status update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.449702 24707 master.cpp:4973] Updating the latest state of task 2 of framework 20150615-224822-2231374252-55005-24680-0000 to TASK_FINISHED
I0615 22:48:29.450031 24704 sched.cpp:715] Scheduler::statusUpdate took 284140ns
I0615 22:48:29.450008 24712 hierarchical.hpp:741] Recovered cpus(*):1; mem(*):1 (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150615-224822-2231374252-55005-24680-S0 from framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.450299 24704 master.cpp:5041] Removing task 2 with resources cpus(*):1; mem(*):1 of framework 20150615-224822-2231374252-55005-24680-0000 on slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:29.450459 24704 master.cpp:3013] Forwarding status update acknowledgement 35e19c63-c69d-491f-a6aa-807bddb8e0d9 for task 2 of framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 to slave 20150615-224822-2231374252-55005-24680-S0 at slave(49)@172.17.0.133:55005 (266bbfb8797f)
I0615 22:48:29.450723 24704 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.450829 24704 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_FINISHED (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.451023 24680 sched.cpp:1590] Asked to stop the driver
I0615 22:48:29.451236 24707 master.cpp:945] Framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 disconnected
I0615 22:48:29.451280 24707 master.cpp:2097] Disconnecting framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:29.451314 24707 master.cpp:2113] Deactivating framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005
I0615 22:48:29.451321 29871 exec.cpp:339] Executor received status update acknowledgement 35e19c63-c69d-491f-a6aa-807bddb8e0d9 for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.451378 24707 master.cpp:967] Giving framework 20150615-224822-2231374252-55005-24680-0000 (default) at scheduler-91b436dc-0e7e-4cac-84b3-952d387d327c@172.17.0.133:55005 0ns to failover
I0615 22:48:29.451686 24703 hierarchical.hpp:437] Deactivated framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.452110 24709 master.cpp:837] Master terminating
I0615 22:48:29.452333 24710 hierarchical.hpp:527] Removed slave 20150615-224822-2231374252-55005-24680-S0
I0615 22:48:29.452410 24710 hierarchical.hpp:391] Removed framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.452862 24699 slave.cpp:2978] master@172.17.0.133:55005 exited
W0615 22:48:29.452980 24699 slave.cpp:2981] Master disconnected! Waiting for a new master to be elected
I0615 22:48:29.456091 24710 containerizer.cpp:997] Destroying container 'a2a47186-ac2b-4c14-8a72-db6e3f4e0769'
I0615 22:48:29.507190 24700 containerizer.cpp:1184] Executor for container 'a2a47186-ac2b-4c14-8a72-db6e3f4e0769' has exited
I0615 22:48:29.508425 24703 slave.cpp:3248] Executor '2' of framework 20150615-224822-2231374252-55005-24680-0000 terminated with signal Killed
I0615 22:48:29.509145 24704 status_update_manager.cpp:529] Cleaning up status update stream for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.509567 24700 slave.cpp:2163] Status update manager successfully handled status update acknowledgement (UUID: 35e19c63-c69d-491f-a6aa-807bddb8e0d9) for task 2 of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.509625 24700 slave.cpp:4852] Completing task 2
I0615 22:48:29.509666 24700 slave.cpp:3354] Cleaning up executor '2' of framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.510087 24711 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/a2a47186-ac2b-4c14-8a72-db6e3f4e0769' for gc 6.99999409775407days in the future
I0615 22:48:29.510208 24711 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2' for gc 6.99999409599407days in the future
I0615 22:48:29.510280 24711 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2/runs/a2a47186-ac2b-4c14-8a72-db6e3f4e0769' for gc 6.99999409493037days in the future
I0615 22:48:29.510360 24711 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000/executors/2' for gc 6.9999940937037days in the future
I0615 22:48:29.510372 24700 slave.cpp:3441] Cleaning up framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.510454 24711 status_update_manager.cpp:283] Closing status update streams for framework 20150615-224822-2231374252-55005-24680-0000
I0615 22:48:29.510610 24713 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000' for gc 6.99999409123852days in the future
I0615 22:48:29.510689 24700 slave.cpp:560] Slave terminating
I0615 22:48:29.510712 24713 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpCachedRecovery_eTAiVx/meta/slaves/20150615-224822-2231374252-55005-24680-S0/frameworks/20150615-224822-2231374252-55005-24680-0000' for gc 6.99999408987259days in the future
[ FAILED ] FetcherCacheHttpTest.HttpCachedRecovery (7681 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)