You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Joseph Wu (JIRA)" <ji...@apache.org> on 2016/02/29 20:31:18 UTC
[jira] [Commented] (MESOS-2858) FetcherCacheHttpTest.HttpMixed is
flaky.
[ https://issues.apache.org/jira/browse/MESOS-2858?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15172447#comment-15172447 ]
Joseph Wu commented on MESOS-2858:
----------------------------------
Here's a verbose failure seen on CentOS 6 + SSL. This includes the sandbox dump:
{noformat}
[ RUN ] FetcherCacheHttpTest.HttpMixed
I0227 05:12:00.206799 27818 leveldb.cpp:174] Opened db in 50.017509ms
I0227 05:12:00.209074 27818 leveldb.cpp:181] Compacted db in 2.241024ms
I0227 05:12:00.209115 27818 leveldb.cpp:196] Created db iterator in 17227ns
I0227 05:12:00.209125 27818 leveldb.cpp:202] Seeked to beginning of db in 1295ns
I0227 05:12:00.209132 27818 leveldb.cpp:271] Iterated through 0 keys in the db in 355ns
I0227 05:12:00.209172 27818 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0227 05:12:00.209712 27835 recover.cpp:447] Starting replica recovery
I0227 05:12:00.209913 27835 recover.cpp:473] Replica is in EMPTY status
I0227 05:12:00.210860 27838 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (2365)@172.30.2.80:52121
I0227 05:12:00.211302 27837 recover.cpp:193] Received a recover response from a replica in EMPTY status
I0227 05:12:00.211701 27836 recover.cpp:564] Updating replica status to STARTING
I0227 05:12:00.212213 27839 master.cpp:376] Master e1cdf701-b040-46a3-ba69-3389093cbc35 (ip-172-30-2-80.mesosphere.io) started on 172.30.2.80:52121
I0227 05:12:00.212227 27839 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/RxdlQL/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --http_authenticators="basic" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50" --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/RxdlQL/master" --zk_session_timeout="10secs"
I0227 05:12:00.212440 27839 master.cpp:423] Master only allowing authenticated frameworks to register
I0227 05:12:00.212448 27839 master.cpp:428] Master only allowing authenticated slaves to register
I0227 05:12:00.212453 27839 credentials.hpp:35] Loading credentials for authentication from '/tmp/RxdlQL/credentials'
I0227 05:12:00.212694 27839 master.cpp:468] Using default 'crammd5' authenticator
I0227 05:12:00.212826 27839 master.cpp:537] Using default 'basic' HTTP authenticator
I0227 05:12:00.212955 27839 master.cpp:571] Authorization enabled
I0227 05:12:00.213081 27837 whitelist_watcher.cpp:77] No whitelist given
I0227 05:12:00.213081 27838 hierarchical.cpp:144] Initialized hierarchical allocator process
I0227 05:12:00.213927 27840 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 2.10648ms
I0227 05:12:00.213948 27840 replica.cpp:320] Persisted replica status to STARTING
I0227 05:12:00.214175 27835 recover.cpp:473] Replica is in STARTING status
I0227 05:12:00.214956 27837 master.cpp:1712] The newly elected leader is master@172.30.2.80:52121 with id e1cdf701-b040-46a3-ba69-3389093cbc35
I0227 05:12:00.214987 27837 master.cpp:1725] Elected as the leading master!
I0227 05:12:00.215008 27837 master.cpp:1470] Recovering from registrar
I0227 05:12:00.215050 27833 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (2367)@172.30.2.80:52121
I0227 05:12:00.215157 27839 registrar.cpp:307] Recovering registrar
I0227 05:12:00.215530 27838 recover.cpp:193] Received a recover response from a replica in STARTING status
I0227 05:12:00.215914 27840 recover.cpp:564] Updating replica status to VOTING
I0227 05:12:00.224273 27839 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 8.142528ms
I0227 05:12:00.224293 27839 replica.cpp:320] Persisted replica status to VOTING
I0227 05:12:00.224377 27833 recover.cpp:578] Successfully joined the Paxos group
I0227 05:12:00.224503 27833 recover.cpp:462] Recover process terminated
I0227 05:12:00.224874 27836 log.cpp:659] Attempting to start the writer
I0227 05:12:00.225875 27836 replica.cpp:493] Replica received implicit promise request from (2368)@172.30.2.80:52121 with proposal 1
I0227 05:12:00.227829 27836 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 1.925832ms
I0227 05:12:00.227849 27836 replica.cpp:342] Persisted promised to 1
I0227 05:12:00.228365 27835 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0227 05:12:00.229394 27835 replica.cpp:388] Replica received explicit promise request from (2369)@172.30.2.80:52121 for position 0 with proposal 2
I0227 05:12:00.231195 27835 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 1.769232ms
I0227 05:12:00.231220 27835 replica.cpp:712] Persisted action at 0
I0227 05:12:00.232059 27840 replica.cpp:537] Replica received write request for position 0 from (2370)@172.30.2.80:52121
I0227 05:12:00.232107 27840 leveldb.cpp:436] Reading position from leveldb took 21014ns
I0227 05:12:00.234089 27840 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 1.952069ms
I0227 05:12:00.234110 27840 replica.cpp:712] Persisted action at 0
I0227 05:12:00.234604 27837 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0227 05:12:00.236526 27837 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.893714ms
I0227 05:12:00.236546 27837 replica.cpp:712] Persisted action at 0
I0227 05:12:00.236560 27837 replica.cpp:697] Replica learned NOP action at position 0
I0227 05:12:00.236968 27834 log.cpp:675] Writer started with ending position 0
I0227 05:12:00.237845 27840 leveldb.cpp:436] Reading position from leveldb took 21732ns
I0227 05:12:00.238523 27837 registrar.cpp:340] Successfully fetched the registry (0B) in 23.33184ms
I0227 05:12:00.238602 27837 registrar.cpp:439] Applied 1 operations in 20533ns; attempting to update the 'registry'
I0227 05:12:00.239223 27839 log.cpp:683] Attempting to append 206 bytes to the log
I0227 05:12:00.239329 27840 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0227 05:12:00.239919 27839 replica.cpp:537] Replica received write request for position 1 from (2371)@172.30.2.80:52121
I0227 05:12:00.241914 27839 leveldb.cpp:341] Persisting action (225 bytes) to leveldb took 1.961001ms
I0227 05:12:00.241935 27839 replica.cpp:712] Persisted action at 1
I0227 05:12:00.242513 27836 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0227 05:12:00.244505 27836 leveldb.cpp:341] Persisting action (227 bytes) to leveldb took 1.968916ms
I0227 05:12:00.244526 27836 replica.cpp:712] Persisted action at 1
I0227 05:12:00.244540 27836 replica.cpp:697] Replica learned APPEND action at position 1
I0227 05:12:00.245319 27834 registrar.cpp:484] Successfully updated the 'registry' in 6.662912ms
I0227 05:12:00.245476 27834 registrar.cpp:370] Successfully recovered registrar
I0227 05:12:00.245542 27840 log.cpp:702] Attempting to truncate the log to 1
I0227 05:12:00.245640 27837 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0227 05:12:00.246036 27840 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
I0227 05:12:00.246033 27835 master.cpp:1522] Recovered 0 slaves from the Registry (167B) ; allowing 10mins for slaves to re-register
I0227 05:12:00.246414 27838 replica.cpp:537] Replica received write request for position 2 from (2372)@172.30.2.80:52121
I0227 05:12:00.248299 27838 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 1.849989ms
I0227 05:12:00.248320 27838 replica.cpp:712] Persisted action at 2
I0227 05:12:00.248878 27833 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0227 05:12:00.250821 27833 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 1.918391ms
I0227 05:12:00.250870 27833 leveldb.cpp:399] Deleting ~1 keys from leveldb took 26609ns
I0227 05:12:00.250885 27833 replica.cpp:712] Persisted action at 2
I0227 05:12:00.250900 27833 replica.cpp:697] Replica learned TRUNCATE action at position 2
I0227 05:12:00.257117 27818 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
I0227 05:12:00.261559 27818 linux_launcher.cpp:101] Using /cgroup/freezer as the freezer hierarchy for the Linux launcher
I0227 05:12:00.265316 27838 slave.cpp:193] Slave started on 56)@172.30.2.80:52121
I0227 05:12:00.265336 27838 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:1000;mem:1000" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr"
I0227 05:12:00.265583 27838 credentials.hpp:83] Loading credential for authentication from '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/credential'
I0227 05:12:00.265708 27838 slave.cpp:324] Slave using credential for: test-principal
I0227 05:12:00.265877 27838 resources.cpp:572] Parsing resources as JSON failed: cpus:1000;mem:1000
Trying semicolon-delimited string format instead
I0227 05:12:00.266201 27838 slave.cpp:464] Slave resources: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000]
I0227 05:12:00.266270 27838 slave.cpp:472] Slave attributes: [ ]
I0227 05:12:00.266279 27838 slave.cpp:477] Slave hostname: ip-172-30-2-80.mesosphere.io
I0227 05:12:00.267164 27840 state.cpp:58] Recovering state from '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta'
I0227 05:12:00.267343 27833 status_update_manager.cpp:200] Recovering status update manager
I0227 05:12:00.267501 27835 containerizer.cpp:407] Recovering containerizer
I0227 05:12:00.268838 27838 provisioner.cpp:245] Provisioner recovery complete
I0227 05:12:00.269093 27835 slave.cpp:4565] Finished recovery
I0227 05:12:00.269383 27835 slave.cpp:4737] Querying resource estimator for oversubscribable resources
I0227 05:12:00.269608 27837 status_update_manager.cpp:174] Pausing sending status updates
I0227 05:12:00.269654 27835 slave.cpp:796] New master detected at master@172.30.2.80:52121
I0227 05:12:00.269714 27835 slave.cpp:859] Authenticating with master master@172.30.2.80:52121
I0227 05:12:00.269728 27835 slave.cpp:864] Using default CRAM-MD5 authenticatee
I0227 05:12:00.269843 27835 slave.cpp:832] Detecting new master
I0227 05:12:00.269873 27833 authenticatee.cpp:121] Creating new client SASL connection
I0227 05:12:00.269949 27835 slave.cpp:4751] Received oversubscribable resources from the resource estimator
I0227 05:12:00.270082 27840 master.cpp:5541] Authenticating slave(56)@172.30.2.80:52121
I0227 05:12:00.270169 27839 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(158)@172.30.2.80:52121
I0227 05:12:00.270359 27834 authenticator.cpp:98] Creating new server SASL connection
I0227 05:12:00.270478 27836 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0227 05:12:00.270496 27836 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0227 05:12:00.270572 27836 authenticator.cpp:203] Received SASL authentication start
I0227 05:12:00.270625 27836 authenticator.cpp:325] Authentication requires more steps
I0227 05:12:00.270694 27836 authenticatee.cpp:258] Received SASL authentication step
I0227 05:12:00.270795 27839 authenticator.cpp:231] Received SASL authentication step
I0227 05:12:00.270817 27839 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-80' server FQDN: 'ip-172-30-2-80' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0227 05:12:00.270825 27839 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0227 05:12:00.270851 27839 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0227 05:12:00.270869 27839 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-80' server FQDN: 'ip-172-30-2-80' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0227 05:12:00.270876 27839 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0227 05:12:00.270881 27839 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0227 05:12:00.270892 27839 authenticator.cpp:317] Authentication success
I0227 05:12:00.270961 27837 authenticatee.cpp:298] Authentication success
I0227 05:12:00.271020 27838 master.cpp:5571] Successfully authenticated principal 'test-principal' at slave(56)@172.30.2.80:52121
I0227 05:12:00.271060 27834 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(158)@172.30.2.80:52121
I0227 05:12:00.271292 27836 slave.cpp:927] Successfully authenticated with master master@172.30.2.80:52121
I0227 05:12:00.271411 27836 slave.cpp:1321] Will retry registration in 11.988513ms if necessary
I0227 05:12:00.271558 27839 master.cpp:4255] Registering slave at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io) with id e1cdf701-b040-46a3-ba69-3389093cbc35-S0
I0227 05:12:00.271873 27834 registrar.cpp:439] Applied 1 operations in 44173ns; attempting to update the 'registry'
I0227 05:12:00.272459 27839 log.cpp:683] Attempting to append 391 bytes to the log
I0227 05:12:00.272590 27840 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0227 05:12:00.273108 27833 replica.cpp:537] Replica received write request for position 3 from (2389)@172.30.2.80:52121
I0227 05:12:00.275226 27833 leveldb.cpp:341] Persisting action (410 bytes) to leveldb took 2.091265ms
I0227 05:12:00.275249 27833 replica.cpp:712] Persisted action at 3
I0227 05:12:00.275794 27837 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0227 05:12:00.277685 27837 leveldb.cpp:341] Persisting action (412 bytes) to leveldb took 1.865615ms
I0227 05:12:00.277707 27837 replica.cpp:712] Persisted action at 3
I0227 05:12:00.277721 27837 replica.cpp:697] Replica learned APPEND action at position 3
I0227 05:12:00.278857 27839 registrar.cpp:484] Successfully updated the 'registry' in 6.93504ms
I0227 05:12:00.279016 27837 log.cpp:702] Attempting to truncate the log to 3
I0227 05:12:00.279119 27834 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0227 05:12:00.279523 27834 slave.cpp:3482] Received ping from slave-observer(53)@172.30.2.80:52121
I0227 05:12:00.279583 27838 master.cpp:4323] Registered slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io) with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000]
I0227 05:12:00.279747 27837 hierarchical.cpp:473] Added slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 (ip-172-30-2-80.mesosphere.io) with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] (allocated: )
I0227 05:12:00.279783 27834 slave.cpp:971] Registered with master master@172.30.2.80:52121; given slave ID e1cdf701-b040-46a3-ba69-3389093cbc35-S0
I0227 05:12:00.279808 27834 fetcher.cpp:81] Clearing fetcher cache
I0227 05:12:00.279867 27838 replica.cpp:537] Replica received write request for position 4 from (2390)@172.30.2.80:52121
I0227 05:12:00.279886 27837 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:00.279917 27837 hierarchical.cpp:1145] Performed allocation for slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 in 131303ns
I0227 05:12:00.279983 27835 status_update_manager.cpp:181] Resuming sending status updates
I0227 05:12:00.280139 27834 slave.cpp:994] Checkpointing SlaveInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/slave.info'
I0227 05:12:00.280366 27834 slave.cpp:1030] Forwarding total oversubscribed resources
I0227 05:12:00.280479 27834 master.cpp:4664] Received update of slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io) with total oversubscribed resources
I0227 05:12:00.280622 27818 sched.cpp:222] Version: 0.28.0
I0227 05:12:00.280853 27834 hierarchical.cpp:531] Slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 (ip-172-30-2-80.mesosphere.io) updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: )
I0227 05:12:00.280942 27834 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:00.280961 27834 hierarchical.cpp:1145] Performed allocation for slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 in 83318ns
I0227 05:12:00.281059 27833 sched.cpp:326] New master detected at master@172.30.2.80:52121
I0227 05:12:00.281172 27833 sched.cpp:382] Authenticating with master master@172.30.2.80:52121
I0227 05:12:00.281185 27833 sched.cpp:389] Using default CRAM-MD5 authenticatee
I0227 05:12:00.281391 27835 authenticatee.cpp:121] Creating new client SASL connection
I0227 05:12:00.281558 27840 master.cpp:5541] Authenticating scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:00.281643 27839 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(159)@172.30.2.80:52121
I0227 05:12:00.281839 27836 authenticator.cpp:98] Creating new server SASL connection
I0227 05:12:00.281945 27833 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
I0227 05:12:00.281970 27833 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
I0227 05:12:00.282038 27833 authenticator.cpp:203] Received SASL authentication start
I0227 05:12:00.282080 27833 authenticator.cpp:325] Authentication requires more steps
I0227 05:12:00.282145 27833 authenticatee.cpp:258] Received SASL authentication step
I0227 05:12:00.282240 27839 authenticator.cpp:231] Received SASL authentication step
I0227 05:12:00.282264 27839 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-80' server FQDN: 'ip-172-30-2-80' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0227 05:12:00.282272 27839 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
I0227 05:12:00.282294 27839 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0227 05:12:00.282311 27839 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ip-172-30-2-80' server FQDN: 'ip-172-30-2-80' SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0227 05:12:00.282318 27839 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0227 05:12:00.282323 27839 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0227 05:12:00.282333 27839 authenticator.cpp:317] Authentication success
I0227 05:12:00.282397 27834 authenticatee.cpp:298] Authentication success
I0227 05:12:00.282429 27833 master.cpp:5571] Successfully authenticated principal 'test-principal' at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:00.282482 27836 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(159)@172.30.2.80:52121
I0227 05:12:00.282672 27840 sched.cpp:471] Successfully authenticated with master master@172.30.2.80:52121
I0227 05:12:00.282693 27840 sched.cpp:776] Sending SUBSCRIBE call to master@172.30.2.80:52121
I0227 05:12:00.282802 27840 sched.cpp:809] Will retry registration in 71.862862ms if necessary
I0227 05:12:00.282879 27833 master.cpp:2280] Received SUBSCRIBE call for framework 'default' at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
W0227 05:12:00.282907 27833 master.cpp:2287] Framework at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121 (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
I0227 05:12:00.282943 27833 master.cpp:1751] Authorizing framework principal '' to receive offers for role '*'
I0227 05:12:00.283118 27836 master.cpp:2351] Subscribing framework default with checkpointing enabled and capabilities [ ]
I0227 05:12:00.283474 27839 hierarchical.cpp:265] Added framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.283601 27834 sched.cpp:703] Framework registered with e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.283643 27834 sched.cpp:717] Scheduler::registered took 18945ns
I0227 05:12:00.284061 27839 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:00.284097 27839 hierarchical.cpp:1125] Performed allocation for 1 slaves in 597322ns
I0227 05:12:00.284324 27833 master.cpp:5370] Sending 1 offers to framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:00.284713 27840 sched.cpp:873] Scheduler::resourceOffers took 92528ns
I0227 05:12:00.285007 27818 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:1
Trying semicolon-delimited string format instead
I0227 05:12:00.285190 27818 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:1
Trying semicolon-delimited string format instead
I0227 05:12:00.285400 27818 resources.cpp:572] Parsing resources as JSON failed: cpus:1;mem:1
Trying semicolon-delimited string format instead
I0227 05:12:00.286617 27840 master.cpp:3153] Processing ACCEPT call for offers: [ e1cdf701-b040-46a3-ba69-3389093cbc35-O0 ] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io) for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:00.286650 27840 master.cpp:2825] Authorizing framework principal '' to launch task 0 as user 'root'
I0227 05:12:00.286684 27838 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 6.785173ms
I0227 05:12:00.286710 27838 replica.cpp:712] Persisted action at 4
I0227 05:12:00.286736 27840 master.cpp:2825] Authorizing framework principal '' to launch task 1 as user 'root'
I0227 05:12:00.286811 27840 master.cpp:2825] Authorizing framework principal '' to launch task 2 as user 'root'
I0227 05:12:00.287377 27837 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0227 05:12:00.288409 27834 master.hpp:176] Adding task 0 with resources cpus(*):1; mem(*):1 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:00.288491 27834 master.cpp:3638] Launching task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121 with resources cpus(*):1; mem(*):1 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:00.288766 27840 slave.cpp:1361] Got assigned task 0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.288862 27840 slave.cpp:5287] Checkpointing FrameworkInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/framework.info'
I0227 05:12:00.288966 27834 master.hpp:176] Adding task 1 with resources cpus(*):1; mem(*):1 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:00.289038 27834 master.cpp:3638] Launching task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121 with resources cpus(*):1; mem(*):1 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:00.289311 27840 slave.cpp:5298] Checkpointing framework pid 'scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/framework.pid'
I0227 05:12:00.289474 27840 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0227 05:12:00.289698 27837 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 2.294345ms
I0227 05:12:00.289751 27837 leveldb.cpp:399] Deleting ~2 keys from leveldb took 29425ns
I0227 05:12:00.289765 27837 replica.cpp:712] Persisted action at 4
I0227 05:12:00.289780 27837 replica.cpp:697] Replica learned TRUNCATE action at position 4
I0227 05:12:00.289834 27834 master.hpp:176] Adding task 2 with resources cpus(*):1; mem(*):1 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:00.289909 27840 slave.cpp:1361] Got assigned task 1 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.289971 27840 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0227 05:12:00.289963 27834 master.cpp:3638] Launching task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121 with resources cpus(*):1; mem(*):1 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:00.290364 27840 slave.cpp:1480] Launching task 0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.290421 27840 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0227 05:12:00.290535 27837 hierarchical.cpp:890] Recovered cpus(*):997; mem(*):997; disk(*):3967; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):3; mem(*):3) on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 from framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.290576 27837 hierarchical.cpp:927] Framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 filtered slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for 5secs
I0227 05:12:00.290859 27840 paths.cpp:474] Trying to chown '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2' to user 'root'
I0227 05:12:00.294186 27840 slave.cpp:5739] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/executor.info'
I0227 05:12:00.294584 27840 slave.cpp:5367] Launching executor 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2'
I0227 05:12:00.294945 27838 containerizer.cpp:666] Starting container '1b0dec2b-723a-4f74-a994-36e7181de6f2' for executor '0' of framework 'e1cdf701-b040-46a3-ba69-3389093cbc35-0000'
I0227 05:12:00.294992 27840 slave.cpp:5762] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2/tasks/0/task.info'
I0227 05:12:00.295241 27840 slave.cpp:1698] Queuing task '0' for executor '0' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.295423 27840 slave.cpp:1361] Got assigned task 2 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.295486 27840 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0227 05:12:00.295840 27840 slave.cpp:1480] Launching task 1 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.295897 27840 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0227 05:12:00.296246 27840 paths.cpp:474] Trying to chown '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512' to user 'root'
I0227 05:12:00.299010 27840 slave.cpp:5739] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/executor.info'
I0227 05:12:00.299409 27840 slave.cpp:5367] Launching executor 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512'
I0227 05:12:00.299760 27840 slave.cpp:5762] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512/tasks/1/task.info'
I0227 05:12:00.299774 27838 linux_launcher.cpp:304] Cloning child process with flags =
I0227 05:12:00.299978 27840 slave.cpp:1698] Queuing task '1' for executor '1' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.300618 27840 slave.cpp:749] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2'
I0227 05:12:00.300839 27840 slave.cpp:1480] Launching task 2 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.300983 27840 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0227 05:12:00.301470 27840 paths.cpp:474] Trying to chown '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812' to user 'root'
I0227 05:12:00.302314 27838 containerizer.cpp:1104] Checkpointing executor's forked pid 31462 to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2/pids/forked.pid'
I0227 05:12:00.303287 27838 containerizer.cpp:666] Starting container '3b5cecd7-a72d-4a2d-bb7a-3fe92c487512' for executor '1' of framework 'e1cdf701-b040-46a3-ba69-3389093cbc35-0000'
I0227 05:12:00.304836 27840 slave.cpp:5739] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/executor.info'
I0227 05:12:00.305073 27837 fetcher.cpp:304] Starting to fetch URIs for container: 1b0dec2b-723a-4f74-a994-36e7181de6f2, directory: /tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2
I0227 05:12:00.305923 27840 slave.cpp:5367] Launching executor 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812'
I0227 05:12:00.306337 27840 slave.cpp:5762] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812/tasks/2/task.info'
I0227 05:12:00.306570 27840 slave.cpp:1698] Queuing task '2' for executor '2' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.306646 27840 slave.cpp:749] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512'
I0227 05:12:00.306674 27840 slave.cpp:749] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812'
I0227 05:12:00.306684 27838 containerizer.cpp:666] Starting container '3a0795e3-60f4-4c81-9839-57c57125f812' for executor '2' of framework 'e1cdf701-b040-46a3-ba69-3389093cbc35-0000'
I0227 05:12:00.308063 27837 fetcher.cpp:893] Created cache entry 'root@http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz' with file: c1-mesos-fetc_rchive.tgz
I0227 05:12:00.308784 27836 fetcher.cpp:252] Fetching size for URI: http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz
I0227 05:12:00.310348 27838 linux_launcher.cpp:304] Cloning child process with flags =
I0227 05:12:00.312027 27838 containerizer.cpp:1104] Checkpointing executor's forked pid 31479 to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512/pids/forked.pid'
I0227 05:12:00.314021 27835 fetcher.cpp:304] Starting to fetch URIs for container: 3b5cecd7-a72d-4a2d-bb7a-3fe92c487512, directory: /tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512
I0227 05:12:00.315760 27838 linux_launcher.cpp:304] Cloning child process with flags =
I0227 05:12:00.317659 27838 containerizer.cpp:1104] Checkpointing executor's forked pid 31486 to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812/pids/forked.pid'
I0227 05:12:00.321234 27835 fetcher.cpp:304] Starting to fetch URIs for container: 3a0795e3-60f4-4c81-9839-57c57125f812, directory: /tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812
I0227 05:12:00.325058 27839 process.cpp:3141] Handling HTTP event for process '(2374)' with path: '/(2374)/mesos-fetcher-test-archive.tgz'
I0227 05:12:00.325390 27839 process.cpp:1181] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz' with length 10240
HTTP/1.1 200 OK
Date: Sat, 27 Feb 2016 05:12:00 GMT
Content-Length: 10240
I0227 05:12:00.329351 27835 fetcher.cpp:766] Fetching URIs using command '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
I0227 05:12:00.330900 27835 fetcher.cpp:668] Claiming fetcher cache space for: root@http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz
I0227 05:12:00.330925 27835 fetcher.cpp:1113] Claimed cache space: 10KB, now using: 10KB
I0227 05:12:00.336823 27836 fetcher.cpp:766] Fetching URIs using command '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
I0227 05:12:00.387264 27840 process.cpp:3141] Handling HTTP event for process '(2374)' with path: '/(2374)/mesos-fetcher-test-archive.tgz'
I0227 05:12:00.387539 27836 process.cpp:1181] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz' with length 10240
I0227 05:12:00.388584 27838 process.cpp:3141] Handling HTTP event for process '(2374)' with path: '/(2374)/mesos-fetcher-test-archive.tgz'
I0227 05:12:00.388779 27833 process.cpp:1181] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz' with length 10240
I0227 05:12:00.392030 27836 process.cpp:3141] Handling HTTP event for process '(2374)' with path: '/(2374)/mesos-fetcher-test-cmd'
I0227 05:12:00.392217 27839 process.cpp:1181] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
I0227 05:12:00.392540 27838 process.cpp:3141] Handling HTTP event for process '(2374)' with path: '/(2374)/mesos-fetcher-test-cmd'
I0227 05:12:00.392715 27833 process.cpp:1181] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
I0227 05:12:00.446514 27833 fetcher.cpp:1125] Released cache space: 0B, now using: 10KB
I0227 05:12:00.451242 27833 fetcher.cpp:766] Fetching URIs using command '/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0227 05:12:00.494453 31462 process.cpp:991] libprocess is initialized on 172.30.2.80:33478 for 8 cpus
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0227 05:12:00.494820 31479 process.cpp:991] libprocess is initialized on 172.30.2.80:44339 for 8 cpus
I0227 05:12:00.495173 31462 logging.cpp:193] Logging to STDERR
I0227 05:12:00.495375 31479 logging.cpp:193] Logging to STDERR
I0227 05:12:00.497396 31462 exec.cpp:143] Version: 0.28.0
I0227 05:12:00.497740 31479 exec.cpp:143] Version: 0.28.0
I0227 05:12:00.505581 31602 exec.cpp:193] Executor started at: executor(1)@172.30.2.80:33478 with pid 31462
I0227 05:12:00.507900 27837 slave.cpp:2643] Got registration for executor '0' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from executor(1)@172.30.2.80:33478
I0227 05:12:00.508093 31603 exec.cpp:193] Executor started at: executor(1)@172.30.2.80:44339 with pid 31479
I0227 05:12:00.508368 27837 slave.cpp:2729] Checkpointing executor pid 'executor(1)@172.30.2.80:33478' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2/pids/libprocess.pid'
I0227 05:12:00.508718 27835 process.cpp:3141] Handling HTTP event for process '(2374)' with path: '/(2374)/mesos-fetcher-test-cmd'
I0227 05:12:00.508922 27835 process.cpp:1181] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
I0227 05:12:00.510185 27839 slave.cpp:1863] Sending queued task '0' to executor '0' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 at executor(1)@172.30.2.80:33478
I0227 05:12:00.510339 31604 exec.cpp:217] Executor registered on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0
I0227 05:12:00.510612 27839 slave.cpp:2643] Got registration for executor '1' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from executor(1)@172.30.2.80:44339
I0227 05:12:00.510975 27839 slave.cpp:2729] Checkpointing executor pid 'executor(1)@172.30.2.80:44339' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512/pids/libprocess.pid'
I0227 05:12:00.511910 31604 exec.cpp:229] Executor::registered took 231459ns
Registered executor on ip-172-30-2-80.mesosphere.io
Starting task 0
I0227 05:12:00.512151 31604 exec.cpp:304] Executor asked to run task '0'
I0227 05:12:00.512258 31604 exec.cpp:313] Executor::launchTask took 87403ns
Forked command at 31611
sh -c './mesos-fetcher-test-cmd 0'
I0227 05:12:00.514798 31606 exec.cpp:526] Executor sending status update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0227 05:12:00.593705 31486 process.cpp:991] libprocess is initialized on 172.30.2.80:41448 for 8 cpus
I0227 05:12:00.594342 31486 logging.cpp:193] Logging to STDERR
I0227 05:12:00.596139 31486 exec.cpp:143] Version: 0.28.0
I0227 05:12:00.602715 31628 exec.cpp:193] Executor started at: executor(1)@172.30.2.80:41448 with pid 31486
Command exited with status 0 (pid: 31611)
I0227 05:12:00.616340 31600 exec.cpp:526] Executor sending status update TASK_FINISHED (UUID: 4bdc0dca-119b-4bdc-b437-d33ce177fed0) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.935595 27839 slave.cpp:3002] Handling status update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from executor(1)@172.30.2.80:33478
I0227 05:12:00.936070 31605 exec.cpp:217] Executor registered on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0
I0227 05:12:00.936179 27839 slave.cpp:2643] Got registration for executor '2' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from executor(1)@172.30.2.80:41448
I0227 05:12:00.936812 27839 slave.cpp:2729] Checkpointing executor pid 'executor(1)@172.30.2.80:41448' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812/pids/libprocess.pid'
I0227 05:12:00.937636 27839 slave.cpp:3002] Handling status update TASK_FINISHED (UUID: 4bdc0dca-119b-4bdc-b437-d33ce177fed0) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from executor(1)@172.30.2.80:33478
I0227 05:12:00.937983 27839 slave.cpp:1863] Sending queued task '1' to executor '1' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 at executor(1)@172.30.2.80:44339
I0227 05:12:00.938190 31605 exec.cpp:229] Executor::registered took 378290ns
Registered executor on ip-172-30-2-80.mesosphere.io
Starting task 1
I0227 05:12:00.938680 31627 exec.cpp:217] Executor registered on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0
I0227 05:12:00.938670 27840 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.938745 27840 status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.938840 27839 slave.cpp:1863] Sending queued task '2' to executor '2' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 at executor(1)@172.30.2.80:41448
I0227 05:12:00.938944 31603 exec.cpp:304] Executor asked to run task '1'
sh -c './mesos-fetcher-test-acmd 1'
I0227 05:12:00.939088 31603 exec.cpp:313] Executor::launchTask took 113787ns
Forked command at 31636
I0227 05:12:00.939159 27839 slave.cpp:5677] Terminating task 0
Registered executor on ip-172-30-2-80.mesosphere.io
I0227 05:12:00.939198 27840 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.940435 31627 exec.cpp:229] Executor::registered took 225373ns
I0227 05:12:00.940634 31627 exec.cpp:304] Executor asked to run task '2'
I0227 05:12:00.940723 31627 exec.cpp:313] Executor::launchTask took 70877ns
Starting task 2
sh -c './mesos-fetcher-test-acmd 2'
Forked command at 31637
I0227 05:12:00.942621 31592 exec.cpp:526] Executor sending status update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.943197 31633 exec.cpp:526] Executor sending status update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.943640 27837 slave.cpp:3002] Handling status update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from executor(1)@172.30.2.80:44339
I0227 05:12:00.943985 27837 slave.cpp:3002] Handling status update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from executor(1)@172.30.2.80:41448
Command exited with status 0 (pid: 31636)
I0227 05:12:01.042111 31605 exec.cpp:526] Executor sending status update TASK_FINISHED (UUID: f9d44cbf-bba9-4870-9ada-fadfc554f11f) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:01.043159 27833 slave.cpp:3002] Handling status update TASK_FINISHED (UUID: f9d44cbf-bba9-4870-9ada-fadfc554f11f) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from executor(1)@172.30.2.80:44339
Command exited with status 0 (pid: 31637)
I0227 05:12:01.043388 31633 exec.cpp:526] Executor sending status update TASK_FINISHED (UUID: 41aa0b3e-97a4-45f4-8395-6af63d98d21b) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:01.044050 27838 slave.cpp:3002] Handling status update TASK_FINISHED (UUID: 41aa0b3e-97a4-45f4-8395-6af63d98d21b) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from executor(1)@172.30.2.80:41448
I0227 05:12:01.044363 27838 slave.cpp:5677] Terminating task 1
I0227 05:12:01.045023 27835 slave.cpp:5677] Terminating task 2
I0227 05:12:01.214388 27836 hierarchical.cpp:1618] Filtered offer with cpus(*):997; mem(*):997; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:01.214453 27836 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:01.214501 27836 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:01.214540 27836 hierarchical.cpp:1125] Performed allocation for 1 slaves in 681443ns
I0227 05:12:01.618629 27839 slave.cpp:3528] executor(1)@172.30.2.80:33478 exited
I0227 05:12:01.654125 27833 containerizer.cpp:1594] Executor for container '1b0dec2b-723a-4f74-a994-36e7181de6f2' has exited
I0227 05:12:01.654155 27833 containerizer.cpp:1378] Destroying container '1b0dec2b-723a-4f74-a994-36e7181de6f2'
I0227 05:12:01.655766 27834 cgroups.cpp:2427] Freezing cgroup /cgroup/freezer/mesos/1b0dec2b-723a-4f74-a994-36e7181de6f2
I0227 05:12:01.657085 27838 cgroups.cpp:1409] Successfully froze cgroup /cgroup/freezer/mesos/1b0dec2b-723a-4f74-a994-36e7181de6f2 after 1.27104ms
I0227 05:12:01.658505 27835 cgroups.cpp:2445] Thawing cgroup /cgroup/freezer/mesos/1b0dec2b-723a-4f74-a994-36e7181de6f2
I0227 05:12:01.659716 27835 cgroups.cpp:1438] Successfullly thawed cgroup /cgroup/freezer/mesos/1b0dec2b-723a-4f74-a994-36e7181de6f2 after 1.171968ms
I0227 05:12:01.661983 27839 provisioner.cpp:306] Ignoring destroy request for unknown container 1b0dec2b-723a-4f74-a994-36e7181de6f2
I0227 05:12:01.662214 27838 slave.cpp:3886] Executor '0' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 exited with status 0
I0227 05:12:02.045439 27838 slave.cpp:3528] executor(1)@172.30.2.80:44339 exited
I0227 05:12:02.046310 27841 process.cpp:636] Decode failure: Connection reset by peer
E0227 05:12:02.046349 27841 process.cpp:1963] Failed to shutdown socket with fd 17: Transport endpoint is not connected
I0227 05:12:02.046668 27835 slave.cpp:3528] executor(1)@172.30.2.80:41448 exited
I0227 05:12:02.056164 27833 containerizer.cpp:1594] Executor for container '3b5cecd7-a72d-4a2d-bb7a-3fe92c487512' has exited
I0227 05:12:02.056190 27833 containerizer.cpp:1378] Destroying container '3b5cecd7-a72d-4a2d-bb7a-3fe92c487512'
I0227 05:12:02.057773 27838 cgroups.cpp:2427] Freezing cgroup /cgroup/freezer/mesos/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512
I0227 05:12:02.057811 27833 containerizer.cpp:1594] Executor for container '3a0795e3-60f4-4c81-9839-57c57125f812' has exited
I0227 05:12:02.057839 27833 containerizer.cpp:1378] Destroying container '3a0795e3-60f4-4c81-9839-57c57125f812'
I0227 05:12:02.059196 27837 cgroups.cpp:1409] Successfully froze cgroup /cgroup/freezer/mesos/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512 after 1.380864ms
I0227 05:12:02.059427 27833 cgroups.cpp:2427] Freezing cgroup /cgroup/freezer/mesos/3a0795e3-60f4-4c81-9839-57c57125f812
I0227 05:12:02.060874 27838 cgroups.cpp:2445] Thawing cgroup /cgroup/freezer/mesos/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512
I0227 05:12:02.060991 27835 cgroups.cpp:1409] Successfully froze cgroup /cgroup/freezer/mesos/3a0795e3-60f4-4c81-9839-57c57125f812 after 1.509888ms
I0227 05:12:02.062371 27838 cgroups.cpp:1438] Successfullly thawed cgroup /cgroup/freezer/mesos/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512 after 1.45792ms
I0227 05:12:02.062489 27834 cgroups.cpp:2445] Thawing cgroup /cgroup/freezer/mesos/3a0795e3-60f4-4c81-9839-57c57125f812
I0227 05:12:02.064141 27833 cgroups.cpp:1438] Successfullly thawed cgroup /cgroup/freezer/mesos/3a0795e3-60f4-4c81-9839-57c57125f812 after 1.609984ms
I0227 05:12:02.064878 27839 provisioner.cpp:306] Ignoring destroy request for unknown container 3b5cecd7-a72d-4a2d-bb7a-3fe92c487512
I0227 05:12:02.065140 27836 slave.cpp:3886] Executor '1' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 exited with status 0
I0227 05:12:02.066639 27834 provisioner.cpp:306] Ignoring destroy request for unknown container 3a0795e3-60f4-4c81-9839-57c57125f812
I0227 05:12:02.066841 27837 slave.cpp:3886] Executor '2' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 exited with status 0
I0227 05:12:02.216058 27834 hierarchical.cpp:1618] Filtered offer with cpus(*):997; mem(*):997; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:02.216094 27834 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:02.216130 27834 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:02.216155 27834 hierarchical.cpp:1125] Performed allocation for 1 slaves in 549426ns
I0227 05:12:03.217429 27833 hierarchical.cpp:1618] Filtered offer with cpus(*):997; mem(*):997; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:03.217495 27833 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:03.217533 27833 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:03.217560 27833 hierarchical.cpp:1125] Performed allocation for 1 slaves in 674598ns
I0227 05:12:03.971442 27840 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to the slave
I0227 05:12:03.971730 27838 slave.cpp:3400] Forwarding the update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to master@172.30.2.80:52121
I0227 05:12:03.971843 27840 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 4bdc0dca-119b-4bdc-b437-d33ce177fed0) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:03.971909 27840 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 4bdc0dca-119b-4bdc-b437-d33ce177fed0) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:03.971976 27838 slave.cpp:3294] Status update manager successfully handled status update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:03.972024 27838 slave.cpp:3310] Sending acknowledgement for status update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to executor(1)@172.30.2.80:33478
I0227 05:12:03.972256 27839 master.cpp:4809] Status update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:03.972295 27839 master.cpp:4857] Forwarding status update TASK_RUNNING (UUID: a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:03.972425 27838 poll_socket.cpp:110] Socket error while connecting
I0227 05:12:03.972447 27839 master.cpp:6465] Updating the state of task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (latest state: TASK_FINISHED, status update state: TASK_RUNNING)
I0227 05:12:03.972484 27838 process.cpp:1655] Failed to send 'mesos.internal.StatusUpdateAcknowledgementMessage' to '172.30.2.80:33478', connect: Socket error while connecting
E0227 05:12:03.972569 27838 process.cpp:1963] Failed to shutdown socket with fd 12: Transport endpoint is not connected
I0227 05:12:03.972738 27837 sched.cpp:981] Scheduler::statusUpdate took 128292ns
I0227 05:12:03.972748 27835 hierarchical.cpp:890] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):2) on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 from framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:03.972975 27837 master.cpp:3967] Processing ACKNOWLEDGE call a32ce1dd-a1ef-4c3d-a888-385dc9c2edbb for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0
I0227 05:12:04.218521 27836 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:04.218555 27836 hierarchical.cpp:1125] Performed allocation for 1 slaves in 646965ns
I0227 05:12:04.218809 27838 master.cpp:5370] Sending 1 offers to framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:04.219267 27839 sched.cpp:873] Scheduler::resourceOffers took 114100ns
I0227 05:12:04.219555 27838 master.cpp:3690] Processing DECLINE call for offers: [ e1cdf701-b040-46a3-ba69-3389093cbc35-O1 ] for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:04.219995 27839 hierarchical.cpp:890] Recovered cpus(*):998; mem(*):998; disk(*):3967; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):2) on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 from framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:04.220037 27839 hierarchical.cpp:927] Framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 filtered slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for 5secs
I0227 05:12:05.220468 27836 hierarchical.cpp:1618] Filtered offer with cpus(*):998; mem(*):998; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:05.220530 27836 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:05.220567 27836 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:05.220594 27836 hierarchical.cpp:1125] Performed allocation for 1 slaves in 826577ns
I0227 05:12:06.221446 27838 hierarchical.cpp:1618] Filtered offer with cpus(*):998; mem(*):998; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:06.221487 27838 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:06.221518 27838 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:06.221539 27838 hierarchical.cpp:1125] Performed allocation for 1 slaves in 469560ns
I0227 05:12:06.484894 27839 slave.cpp:3294] Status update manager successfully handled status update TASK_FINISHED (UUID: 4bdc0dca-119b-4bdc-b437-d33ce177fed0) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:06.484915 27840 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:06.484978 27840 status_update_manager.cpp:497] Creating StatusUpdate stream for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:06.484961 27839 slave.cpp:3310] Sending acknowledgement for status update TASK_FINISHED (UUID: 4bdc0dca-119b-4bdc-b437-d33ce177fed0) for task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to executor(1)@172.30.2.80:33478
I0227 05:12:06.485363 27840 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:06.485519 27839 poll_socket.cpp:110] Socket error while connecting
I0227 05:12:06.485597 27839 process.cpp:1655] Failed to send 'mesos.internal.StatusUpdateAcknowledgementMessage' to '172.30.2.80:33478', connect: Socket error while connecting
E0227 05:12:06.485693 27839 process.cpp:1963] Failed to shutdown socket with fd 9: Transport endpoint is not connected
I0227 05:12:07.222488 27835 hierarchical.cpp:1618] Filtered offer with cpus(*):998; mem(*):998; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:07.222527 27835 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:07.222558 27835 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:07.222581 27835 hierarchical.cpp:1125] Performed allocation for 1 slaves in 527915ns
I0227 05:12:08.223923 27834 hierarchical.cpp:1618] Filtered offer with cpus(*):998; mem(*):998; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:08.223958 27834 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:08.223986 27834 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:08.224006 27834 hierarchical.cpp:1125] Performed allocation for 1 slaves in 423712ns
I0227 05:12:09.225059 27835 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:09.225095 27835 hierarchical.cpp:1125] Performed allocation for 1 slaves in 579716ns
I0227 05:12:09.225471 27839 master.cpp:5370] Sending 1 offers to framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:09.225986 27833 sched.cpp:873] Scheduler::resourceOffers took 73199ns
I0227 05:12:09.226308 27833 master.cpp:3690] Processing DECLINE call for offers: [ e1cdf701-b040-46a3-ba69-3389093cbc35-O2 ] for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:09.226747 27839 hierarchical.cpp:890] Recovered cpus(*):998; mem(*):998; disk(*):3967; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):2) on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 from framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:09.226788 27839 hierarchical.cpp:927] Framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 filtered slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for 5secs
I0227 05:12:10.001430 27840 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to the slave
I0227 05:12:10.001721 27838 slave.cpp:3400] Forwarding the update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to master@172.30.2.80:52121
I0227 05:12:10.001819 27840 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:10.001871 27840 status_update_manager.cpp:497] Creating StatusUpdate stream for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:10.001960 27838 slave.cpp:3294] Status update manager successfully handled status update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:10.002005 27838 slave.cpp:3310] Sending acknowledgement for status update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to executor(1)@172.30.2.80:44339
I0227 05:12:10.002149 27835 master.cpp:4809] Status update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:10.002185 27835 master.cpp:4857] Forwarding status update TASK_RUNNING (UUID: 799b4516-36f2-45bc-8dc2-507db6215c80) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:10.002354 27835 master.cpp:6465] Updating the state of task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (latest state: TASK_FINISHED, status update state: TASK_RUNNING)
I0227 05:12:10.002370 27840 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:10.002444 27838 poll_socket.cpp:110] Socket error while connecting
I0227 05:12:10.002522 27838 process.cpp:1655] Failed to send 'mesos.internal.StatusUpdateAcknowledgementMessage' to '172.30.2.80:44339', connect: Socket error while connecting
E0227 05:12:10.002601 27838 process.cpp:1963] Failed to shutdown socket with fd 9: Transport endpoint is not connected
I0227 05:12:10.002660 27834 hierarchical.cpp:890] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 from framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:10.002719 27833 sched.cpp:981] Scheduler::statusUpdate took 173437ns
I0227 05:12:10.002945 27833 master.cpp:3967] Processing ACKNOWLEDGE call 799b4516-36f2-45bc-8dc2-507db6215c80 for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0
I0227 05:12:10.226840 27839 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:10.226879 27839 hierarchical.cpp:1125] Performed allocation for 1 slaves in 700058ns
I0227 05:12:10.227104 27835 master.cpp:5370] Sending 1 offers to framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:10.227529 27838 sched.cpp:873] Scheduler::resourceOffers took 65587ns
I0227 05:12:10.227748 27838 master.cpp:3690] Processing DECLINE call for offers: [ e1cdf701-b040-46a3-ba69-3389093cbc35-O3 ] for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:10.228202 27835 hierarchical.cpp:890] Recovered cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 from framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:10.228263 27835 hierarchical.cpp:927] Framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 filtered slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for 5secs
I0227 05:12:11.228196 27836 hierarchical.cpp:1618] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:11.228274 27836 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:11.228315 27836 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:11.228340 27836 hierarchical.cpp:1125] Performed allocation for 1 slaves in 515590ns
I0227 05:12:12.229576 27835 hierarchical.cpp:1618] Filtered offer with cpus(*):999; mem(*):999; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:12.229634 27835 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:12.229670 27835 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:12.229694 27835 hierarchical.cpp:1125] Performed allocation for 1 slaves in 614855ns
I0227 05:12:12.526252 27840 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to the slave
I0227 05:12:12.526511 27833 slave.cpp:3400] Forwarding the update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to master@172.30.2.80:52121
I0227 05:12:12.526587 27840 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: f9d44cbf-bba9-4870-9ada-fadfc554f11f) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:12.526638 27840 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FINISHED (UUID: f9d44cbf-bba9-4870-9ada-fadfc554f11f) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:12.526693 27833 slave.cpp:3294] Status update manager successfully handled status update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:12.526733 27833 slave.cpp:3310] Sending acknowledgement for status update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to executor(1)@172.30.2.80:41448
I0227 05:12:12.526967 27836 master.cpp:4809] Status update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 from slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:12.527001 27836 master.cpp:4857] Forwarding status update TASK_RUNNING (UUID: 361af4ea-a1e5-47e4-83ef-97de34b6ccd8) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:12.527097 27833 poll_socket.cpp:110] Socket error while connecting
I0227 05:12:12.527148 27836 master.cpp:6465] Updating the state of task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (latest state: TASK_FINISHED, status update state: TASK_RUNNING)
I0227 05:12:12.527161 27833 process.cpp:1655] Failed to send 'mesos.internal.StatusUpdateAcknowledgementMessage' to '172.30.2.80:41448', connect: Socket error while connecting
E0227 05:12:12.527274 27833 process.cpp:1963] Failed to shutdown socket with fd 9: Transport endpoint is not connected
I0227 05:12:12.527477 27837 sched.cpp:981] Scheduler::statusUpdate took 157651ns
I0227 05:12:12.527511 27834 hierarchical.cpp:890] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: ) on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 from framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:12.527722 27833 master.cpp:3967] Processing ACKNOWLEDGE call 361af4ea-a1e5-47e4-83ef-97de34b6ccd8 for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0
I0227 05:12:13.231052 27839 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:13.231096 27839 hierarchical.cpp:1125] Performed allocation for 1 slaves in 599669ns
I0227 05:12:13.231359 27834 master.cpp:5370] Sending 1 offers to framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:13.231771 27836 sched.cpp:873] Scheduler::resourceOffers took 67010ns
I0227 05:12:13.231993 27836 master.cpp:3690] Processing DECLINE call for offers: [ e1cdf701-b040-46a3-ba69-3389093cbc35-O4 ] for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:13.232478 27834 hierarchical.cpp:890] Recovered cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000], allocated: ) on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 from framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:13.232518 27834 hierarchical.cpp:927] Framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 filtered slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for 5secs
I0227 05:12:14.232123 27838 hierarchical.cpp:1618] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:14.232157 27838 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:14.232185 27838 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:14.232206 27838 hierarchical.cpp:1125] Performed allocation for 1 slaves in 374741ns
../../src/tests/fetcher_cache_tests.cpp:1093: Failure
I0227 05:12:15.232889 27839 hierarchical.cpp:1618] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
Failed to wait 15secs for awaitFinished(tasks.get())
I0227 05:12:15.232923 27839 hierarchical.cpp:1432] No resources available to allocate!
Begin listing sandboxes
I0227 05:12:15.232950 27839 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:15.232969 27839 hierarchical.cpp:1125] Performed allocation for 1 slaves in 360569ns
Begin listing sandbox `/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/latest`:
Begin file contents of `stderr`:
I0227 05:12:15.270974 27837 slave.cpp:4737] Querying resource estimator for oversubscribable resources
I0227 05:12:00.380938 31518 logging.cpp:193] Logging to STDERR
I0227 05:12:15.271191 27836 slave.cpp:4751] Received oversubscribable resources from the resource estimator
I0227 05:12:15.280226 27838 slave.cpp:3482] Received ping from slave-observer(53)@172.30.2.80:52121
I0227 05:12:16.233609 27835 hierarchical.cpp:1618] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3967; ports(*):[31000-32000] on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.381036 31518 fetcher.cpp:424] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheHttpTest_HttpMixed_6Zjmqr\/fetch\/slaves\/e1cdf701-b040-46a3-ba69-3389093cbc35-S0\/root","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-mesos-fetc_rchive.tgz","uri":{"cache":true,"executable":false,"extract":false,"value":"http:\/\/172.30.2.80:52121\/(2374)\/mesos-fetcher-test-archive.tgz"}},{"action":"BYPASS_CACHE","uri":{"executable":true,"extract":false,"value":"http:\/\/172.30.2.80:52121\/(2374)\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheHttpTest_HttpMixed_6Zjmqr\/slaves\/e1cdf701-b040-46a3-ba69-3389093cbc35-S0\/frameworks\/e1cdf701-b040-46a3-ba69-3389093cbc35-0000\/executors\/0\/runs\/1b0dec2b-723a-4f74-a994-36e7181de6f2","user":"root"}
I0227 05:12:16.233642 27835 hierarchical.cpp:1432] No resources available to allocate!
I0227 05:12:00.387310 31518 fetcher.cpp:379] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz'
I0227 05:12:16.233669 27835 hierarchical.cpp:1527] No inverse offers to send out!
I0227 05:12:00.387337 31518 fetcher.cpp:349] Downloading into cache
I0227 05:12:16.233690 27835 hierarchical.cpp:1125] Performed allocation for 1 slaves in 386863ns
I0227 05:12:00.387565 31518 fetcher.cpp:187] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz'
I0227 05:12:00.387601 31518 fetcher.cpp:134] Downloading resource from 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/fetch/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/root/c1-mesos-fetc_rchive.tgz'
I0227 05:12:00.389154 31518 fetcher.cpp:289] Fetching from cache
I0227 05:12:00.389190 31518 fetcher.cpp:167] Copying resource with command:cp '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/fetch/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/root/c1-mesos-fetc_rchive.tgz' '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2/mesos-fetcher-test-archive.tgz'
I0227 05:12:00.391813 31518 fetcher.cpp:456] Fetched 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2/mesos-fetcher-test-archive.tgz'
I0227 05:12:00.391841 31518 fetcher.cpp:379] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd'
I0227 05:12:00.391860 31518 fetcher.cpp:250] Fetching directly into the sandbox directory
I0227 05:12:00.391890 31518 fetcher.cpp:187] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd'
I0227 05:12:00.391916 31518 fetcher.cpp:134] Downloading resource from 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2/mesos-fetcher-test-cmd'
I0227 05:12:00.393162 31518 fetcher.cpp:456] Fetched 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2/mesos-fetcher-test-cmd'
End file
Begin file contents of `mesos-fetcher-test-cmd`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `stdout`:
End file
Begin file contents of `mesos-fetcher-test-cmd0`:
End file
Begin file contents of `mesos-fetcher-test-archive.tgz`:
I0227 05:12:16.260110 27818 sched.cpp:1903] Asked to stop the driver
I0227 05:12:16.260190 27839 sched.cpp:1143] Stopping framework 'e1cdf701-b040-46a3-ba69-3389093cbc35-0000'
I0227 05:12:16.260447 27834 master.cpp:5941] Processing TEARDOWN call for framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:16.260470 27834 master.cpp:5953] Removing framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (default) at scheduler-ce7d98d9-26e7-4eba-9e08-7ced4bf18981@172.30.2.80:52121
I0227 05:12:16.260586 27838 hierarchical.cpp:375] Deactivated framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:16.260712 27836 slave.cpp:2079] Asked to shut down framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 by master@172.30.2.80:52121
I0227 05:12:16.260749 27836 slave.cpp:2104] Shutting down framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:16.260777 27834 master.cpp:6465] Updating the state of task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (latest state: TASK_FINISHED, status update state: TASK_KILLED)
I0227 05:12:16.260836 27836 slave.cpp:3990] Cleaning up executor '0' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 at executor(1)@172.30.2.80:33478
I0227 05:12:16.260810 27834 master.cpp:6531] Removing task 2 with resources cpus(*):1; mem(*):1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:16.261070 27834 master.cpp:6465] Updating the state of task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (latest state: TASK_FINISHED, status update state: TASK_KILLED)
I0227 05:12:16.261106 27834 master.cpp:6531] Removing task 1 with resources cpus(*):1; mem(*):1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io)
I0227 05:12:16.261216 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2' for gc 6.99999697840296days in the future
I0227 05:12:16.261379 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0' for gc 6.99999697624889days in the future
mesos-fetcher-test-acmd 0000777 0000000 0000000 00000000037 12664230040 014126 0 ustar root root touch mesos-fetcher-test-acmd$1
I0227 05:12:16.261380 27834 master.cpp:6465] Updating the state of task 0 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 (latest state: TASK_FINISHED, status update state: TASK_KILLED)
End file
End sandbox
I0227 05:12:16.261436 27834 master.cpp:6531] Removing task 0 with resources cpus(*):1; mem(*):1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 on slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0 at slave(56)@172.30.2.80:52121 (ip-172-30-2-80.mesosphere.io)
Begin listing sandbox `/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/latest`:
Begin file contents of `stderr`:
I0227 05:12:16.261507 27836 slave.cpp:3990] Cleaning up executor '1' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 at executor(1)@172.30.2.80:44339
I0227 05:12:00.379518 31512 logging.cpp:193] Logging to STDERR
I0227 05:12:16.261551 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0/runs/1b0dec2b-723a-4f74-a994-36e7181de6f2' for gc 6.99999697511704days in the future
I0227 05:12:00.379663 31512 fetcher.cpp:424] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheHttpTest_HttpMixed_6Zjmqr\/fetch\/slaves\/e1cdf701-b040-46a3-ba69-3389093cbc35-S0\/root","items":[{"action":"BYPASS_CACHE","uri":{"executable":false,"extract":true,"value":"http:\/\/172.30.2.80:52121\/(2374)\/mesos-fetcher-test-archive.tgz"}},{"action":"BYPASS_CACHE","uri":{"executable":false,"extract":true,"value":"http:\/\/172.30.2.80:52121\/(2374)\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheHttpTest_HttpMixed_6Zjmqr\/slaves\/e1cdf701-b040-46a3-ba69-3389093cbc35-S0\/frameworks\/e1cdf701-b040-46a3-ba69-3389093cbc35-0000\/executors\/1\/runs\/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512","user":"root"}
I0227 05:12:16.261764 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/0' for gc 6.99999697422519days in the future
I0227 05:12:00.385843 31512 fetcher.cpp:379] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz'
I0227 05:12:00.385865 31512 fetcher.cpp:250] Fetching directly into the sandbox directory
I0227 05:12:16.261814 27840 status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID: 41aa0b3e-97a4-45f4-8395-6af63d98d21b) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.385887 31512 fetcher.cpp:187] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz'
I0227 05:12:16.261857 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512' for gc 6.99999697131852days in the future
I0227 05:12:00.385916 31512 fetcher.cpp:134] Downloading resource from 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512/mesos-fetcher-test-archive.tgz'
I0227 05:12:16.261874 27840 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 41aa0b3e-97a4-45f4-8395-6af63d98d21b) for task 2 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
I0227 05:12:00.388011 31512 fetcher.cpp:84] Extracting with command: tar -C '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512' -xf '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512/mesos-fetcher-test-archive.tgz'
I0227 05:12:16.261948 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1' for gc 6.99999697008days in the future
I0227 05:12:00.391309 31512 fetcher.cpp:92] Extracted '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512/mesos-fetcher-test-archive.tgz' into '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512'
I0227 05:12:16.261986 27836 slave.cpp:3990] Cleaning up executor '2' of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 at executor(1)@172.30.2.80:41448
I0227 05:12:00.391345 31512 fetcher.cpp:456] Fetched 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512/mesos-fetcher-test-archive.tgz'
I0227 05:12:16.262037 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512' for gc 6.9999969692days in the future
I0227 05:12:00.391363 31512 fetcher.cpp:379] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd'
I0227 05:12:00.391378 31512 fetcher.cpp:250] Fetching directly into the sandbox directory
I0227 05:12:16.262125 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1' for gc 6.99999696837926days in the future
I0227 05:12:00.391403 31512 fetcher.cpp:187] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd'
I0227 05:12:16.262209 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812' for gc 6.99999696584593days in the future
I0227 05:12:00.391427 31512 fetcher.cpp:134] Downloading resource from 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512/mesos-fetcher-test-cmd'
I0227 05:12:16.262410 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2' for gc 6.9999969643763days in the future
W0227 05:12:00.392874 31512 fetcher.cpp:272] Copying instead of extracting resource from URI with 'extract' flag, because it does not seem to be an archive: http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd
I0227 05:12:16.262420 27834 master.cpp:1027] Master terminating
I0227 05:12:00.392891 31512 fetcher.cpp:456] Fetched 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/1/runs/3b5cecd7-a72d-4a2d-bb7a-3fe92c487512/mesos-fetcher-test-cmd'
I0227 05:12:16.262488 27837 hierarchical.cpp:326] Removed framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
End file
Begin file contents of `mesos-fetcher-test-cmd`:
touch mesos-fetcher-test-cmd$1
I0227 05:12:16.262501 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812' for gc 6.99999696329778days in the future
End file
Begin file contents of `mesos-fetcher-test-acmd`:
I0227 05:12:16.262519 27836 slave.cpp:4078] Cleaning up framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
touch mesos-fetcher-test-acmd$1
End file
I0227 05:12:16.262735 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2' for gc 6.99999696242963days in the future
Begin file contents of `mesos-fetcher-test-acmd1`:
End file
I0227 05:12:16.262799 27836 slave.cpp:3294] Status update manager successfully handled status update TASK_FINISHED (UUID: f9d44cbf-bba9-4870-9ada-fadfc554f11f) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000
Begin file contents of `stdout`:
I0227 05:12:16.262827 27837 hierarchical.cpp:505] Removed slave e1cdf701-b040-46a3-ba69-3389093cbc35-S0
End file
Begin file contents of `mesos-fetcher-test-archive.tgz`:
I0227 05:12:16.262828 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000' for gc 6.99999696034667days in the future
I0227 05:12:16.262843 27836 slave.cpp:3310] Sending acknowledgement for status update TASK_FINISHED (UUID: f9d44cbf-bba9-4870-9ada-fadfc554f11f) for task 1 of framework e1cdf701-b040-46a3-ba69-3389093cbc35-0000 to executor(1)@172.30.2.80:44339
I0227 05:12:16.262970 27838 gc.cpp:54] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/meta/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000' for gc 6.9999969592days in the future
I0227 05:12:16.263172 27836 poll_socket.cpp:110] Socket error while connecting
I0227 05:12:16.263253 27836 process.cpp:1655] Failed to send 'mesos.internal.StatusUpdateAcknowledgementMessage' to '172.30.2.80:44339', connect: Socket error while connecting
E0227 05:12:16.263365 27836 process.cpp:1963] Failed to shutdown socket with fd 9: Transport endpoint is not connected
I0227 05:12:16.263453 27836 slave.cpp:3528] master@172.30.2.80:52121 exited
W0227 05:12:16.263476 27836 slave.cpp:3531] Master disconnected! Waiting for a new master to be elected
mesos-fetcher-test-acmd 0000777 0000000 0000000 00000000037 12664230040 014126 0 ustar root root touch mesos-fetcher-test-acmd$1
End file
End sandbox
Begin listing sandbox `/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/latest`:
Begin file contents of `stderr`:
I0227 05:12:00.491427 31554 logging.cpp:193] Logging to STDERR
I0227 05:12:00.491583 31554 fetcher.cpp:424] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheHttpTest_HttpMixed_6Zjmqr\/fetch\/slaves\/e1cdf701-b040-46a3-ba69-3389093cbc35-S0\/root","items":[{"action":"RETRIEVE_FROM_CACHE","cache_filename":"c1-mesos-fetc_rchive.tgz","uri":{"cache":true,"executable":false,"extract":true,"value":"http:\/\/172.30.2.80:52121\/(2374)\/mesos-fetcher-test-archive.tgz"}},{"action":"BYPASS_CACHE","uri":{"executable":false,"extract":false,"value":"http:\/\/172.30.2.80:52121\/(2374)\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheHttpTest_HttpMixed_6Zjmqr\/slaves\/e1cdf701-b040-46a3-ba69-3389093cbc35-S0\/frameworks\/e1cdf701-b040-46a3-ba69-3389093cbc35-0000\/executors\/2\/runs\/3a0795e3-60f4-4c81-9839-57c57125f812","user":"root"}
I0227 05:12:00.502477 31554 fetcher.cpp:379] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz'
I0227 05:12:00.502506 31554 fetcher.cpp:289] Fetching from cache
I0227 05:12:00.502553 31554 fetcher.cpp:84] Extracting with command: tar -C '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812' -xf '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/fetch/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/root/c1-mesos-fetc_rchive.tgz'
I0227 05:12:00.506707 31554 fetcher.cpp:92] Extracted '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/fetch/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/root/c1-mesos-fetc_rchive.tgz' into '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812'
I0227 05:12:00.506747 31554 fetcher.cpp:456] Fetched 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-archive.tgz' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812'
I0227 05:12:00.506768 31554 fetcher.cpp:379] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd'
I0227 05:12:00.506788 31554 fetcher.cpp:250] Fetching directly into the sandbox directory
I0227 05:12:00.506826 31554 fetcher.cpp:187] Fetching URI 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd'
I0227 05:12:00.506882 31554 fetcher.cpp:134] Downloading resource from 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812/mesos-fetcher-test-cmd'
I0227 05:12:00.509740 31554 fetcher.cpp:456] Fetched 'http://172.30.2.80:52121/(2374)/mesos-fetcher-test-cmd' to '/tmp/FetcherCacheHttpTest_HttpMixed_6Zjmqr/slaves/e1cdf701-b040-46a3-ba69-3389093cbc35-S0/frameworks/e1cdf701-b040-46a3-ba69-3389093cbc35-0000/executors/2/runs/3a0795e3-60f4-4c81-9839-57c57125f812/mesos-fetcher-test-cmd'
End file
Begin file contents of `mesos-fetcher-test-cmd`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `mesos-fetcher-test-acmd`:
touch mesos-fetcher-test-acmd$1
End file
Begin file contents of `stdout`:
End file
Begin file contents of `mesos-fetcher-test-acmd2`:
End file
End sandbox
End sandboxes
I0227 05:12:17.206478 27837 slave.cpp:668] Slave terminating
[ FAILED ] FetcherCacheHttpTest.HttpMixed (18346 ms)
{noformat}
> FetcherCacheHttpTest.HttpMixed is flaky.
> ----------------------------------------
>
> Key: MESOS-2858
> URL: https://issues.apache.org/jira/browse/MESOS-2858
> Project: Mesos
> Issue Type: Bug
> Components: fetcher, test
> Reporter: Benjamin Mahler
> Assignee: Bernd Mathiske
> Labels: flaky-test, mesosphere
>
> From jenkins:
> {noformat}
> [ RUN ] FetcherCacheHttpTest.HttpMixed
> Using temporary directory '/tmp/FetcherCacheHttpTest_HttpMixed_qfpOOC'
> I0611 00:40:28.208909 26042 leveldb.cpp:176] Opened db in 3.831173ms
> I0611 00:40:28.209951 26042 leveldb.cpp:183] Compacted db in 997319ns
> I0611 00:40:28.210011 26042 leveldb.cpp:198] Created db iterator in 23917ns
> I0611 00:40:28.210032 26042 leveldb.cpp:204] Seeked to beginning of db in 2112ns
> I0611 00:40:28.210043 26042 leveldb.cpp:273] Iterated through 0 keys in the db in 392ns
> I0611 00:40:28.210095 26042 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0611 00:40:28.210741 26067 recover.cpp:449] Starting replica recovery
> I0611 00:40:28.211144 26067 recover.cpp:475] Replica is in EMPTY status
> I0611 00:40:28.212210 26074 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
> I0611 00:40:28.212728 26071 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I0611 00:40:28.213260 26069 recover.cpp:566] Updating replica status to STARTING
> I0611 00:40:28.214066 26073 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 590673ns
> I0611 00:40:28.214095 26073 replica.cpp:323] Persisted replica status to STARTING
> I0611 00:40:28.214350 26073 recover.cpp:475] Replica is in STARTING status
> I0611 00:40:28.214774 26061 master.cpp:363] Master 20150611-004028-1946161580-33349-26042 (658ddc752264) started on 172.17.0.116:33349
> I0611 00:40:28.214800 26061 master.cpp:365] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --credentials="/tmp/FetcherCacheHttpTest_HttpMixed_qfpOOC/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_HttpMixed_qfpOOC/master" --zk_session_timeout="10secs"
> I0611 00:40:28.215342 26061 master.cpp:410] Master only allowing authenticated frameworks to register
> I0611 00:40:28.215361 26061 master.cpp:415] Master only allowing authenticated slaves to register
> I0611 00:40:28.215397 26061 credentials.hpp:37] Loading credentials for authentication from '/tmp/FetcherCacheHttpTest_HttpMixed_qfpOOC/credentials'
> I0611 00:40:28.215589 26064 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
> I0611 00:40:28.215770 26061 master.cpp:454] Using default 'crammd5' authenticator
> I0611 00:40:28.215934 26061 master.cpp:491] Authorization enabled
> I0611 00:40:28.215932 26062 recover.cpp:195] Received a recover response from a replica in STARTING status
> I0611 00:40:28.216256 26070 whitelist_watcher.cpp:79] No whitelist given
> I0611 00:40:28.216310 26066 hierarchical.hpp:309] Initialized hierarchical allocator process
> I0611 00:40:28.216352 26067 recover.cpp:566] Updating replica status to VOTING
> I0611 00:40:28.216909 26070 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 374189ns
> I0611 00:40:28.216931 26070 replica.cpp:323] Persisted replica status to VOTING
> I0611 00:40:28.217052 26075 recover.cpp:580] Successfully joined the Paxos group
> I0611 00:40:28.217355 26063 master.cpp:1476] The newly elected leader is master@172.17.0.116:33349 with id 20150611-004028-1946161580-33349-26042
> I0611 00:40:28.217512 26063 master.cpp:1489] Elected as the leading master!
> I0611 00:40:28.217540 26063 master.cpp:1259] Recovering from registrar
> I0611 00:40:28.217753 26070 registrar.cpp:313] Recovering registrar
> I0611 00:40:28.217396 26075 recover.cpp:464] Recover process terminated
> I0611 00:40:28.218341 26065 log.cpp:661] Attempting to start the writer
> I0611 00:40:28.219391 26067 replica.cpp:477] Replica received implicit promise request with proposal 1
> I0611 00:40:28.219696 26067 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 276905ns
> I0611 00:40:28.219720 26067 replica.cpp:345] Persisted promised to 1
> I0611 00:40:28.220255 26064 coordinator.cpp:230] Coordinator attemping to fill missing position
> I0611 00:40:28.221247 26073 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
> I0611 00:40:28.221545 26073 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 265847ns
> I0611 00:40:28.221567 26073 replica.cpp:679] Persisted action at 0
> I0611 00:40:28.222412 26073 replica.cpp:511] Replica received write request for position 0
> I0611 00:40:28.222458 26073 leveldb.cpp:438] Reading position from leveldb took 23520ns
> I0611 00:40:28.222777 26073 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 280968ns
> I0611 00:40:28.222800 26073 replica.cpp:679] Persisted action at 0
> I0611 00:40:28.223316 26073 replica.cpp:658] Replica received learned notice for position 0
> I0611 00:40:28.223616 26073 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 276737ns
> I0611 00:40:28.223637 26073 replica.cpp:679] Persisted action at 0
> I0611 00:40:28.223654 26073 replica.cpp:664] Replica learned NOP action at position 0
> I0611 00:40:28.224063 26063 log.cpp:677] Writer started with ending position 0
> I0611 00:40:28.225039 26076 leveldb.cpp:438] Reading position from leveldb took 29011ns
> I0611 00:40:28.227192 26062 registrar.cpp:346] Successfully fetched the registry (0B) in 9.399808ms
> I0611 00:40:28.227277 26062 registrar.cpp:445] Applied 1 operations in 20073ns; attempting to update the 'registry'
> I0611 00:40:28.229274 26063 log.cpp:685] Attempting to append 131 bytes to the log
> I0611 00:40:28.229415 26066 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
> I0611 00:40:28.230022 26069 replica.cpp:511] Replica received write request for position 1
> I0611 00:40:28.230345 26069 leveldb.cpp:343] Persisting action (150 bytes) to leveldb took 292219ns
> I0611 00:40:28.230368 26069 replica.cpp:679] Persisted action at 1
> I0611 00:40:28.230881 26073 replica.cpp:658] Replica received learned notice for position 1
> I0611 00:40:28.231205 26073 leveldb.cpp:343] Persisting action (152 bytes) to leveldb took 299315ns
> I0611 00:40:28.231230 26073 replica.cpp:679] Persisted action at 1
> I0611 00:40:28.231256 26073 replica.cpp:664] Replica learned APPEND action at position 1
> I0611 00:40:28.232048 26061 registrar.cpp:490] Successfully updated the 'registry' in 4.71808ms
> I0611 00:40:28.232169 26061 registrar.cpp:376] Successfully recovered registrar
> I0611 00:40:28.232230 26075 log.cpp:704] Attempting to truncate the log to 1
> I0611 00:40:28.232393 26069 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
> I0611 00:40:28.232430 26071 master.cpp:1286] Recovered 0 slaves from the Registry (95B) ; allowing 10mins for slaves to re-register
> I0611 00:40:28.233050 26065 replica.cpp:511] Replica received write request for position 2
> I0611 00:40:28.233394 26065 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 315334ns
> I0611 00:40:28.233415 26065 replica.cpp:679] Persisted action at 2
> I0611 00:40:28.233902 26069 replica.cpp:658] Replica received learned notice for position 2
> I0611 00:40:28.234197 26069 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 268125ns
> I0611 00:40:28.234242 26069 leveldb.cpp:401] Deleting ~1 keys from leveldb took 23549ns
> I0611 00:40:28.234268 26069 replica.cpp:679] Persisted action at 2
> I0611 00:40:28.234295 26069 replica.cpp:664] Replica learned TRUNCATE action at position 2
> I0611 00:40:28.246417 26042 containerizer.cpp:111] Using isolation: posix/cpu,posix/mem
> I0611 00:40:28.251890 26076 slave.cpp:188] Slave started on 47)@172.17.0.116:33349
> I0611 00:40:28.252024 26076 slave.cpp:189] 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_HttpMixed_kwsjNe/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_HttpMixed_kwsjNe/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="true" --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_HttpMixed_kwsjNe"
> I0611 00:40:28.252583 26076 credentials.hpp:85] Loading credential for authentication from '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/credential'
> I0611 00:40:28.252779 26076 slave.cpp:319] Slave using credential for: test-principal
> I0611 00:40:28.253324 26076 slave.cpp:352] Slave resources: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0611 00:40:28.253428 26076 slave.cpp:382] Slave hostname: 658ddc752264
> I0611 00:40:28.253445 26076 slave.cpp:387] Slave checkpoint: true
> I0611 00:40:28.254259 26064 state.cpp:35] Recovering state from '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta'
> I0611 00:40:28.254647 26068 status_update_manager.cpp:201] Recovering status update manager
> I0611 00:40:28.254853 26069 containerizer.cpp:312] Recovering containerizer
> I0611 00:40:28.255537 26076 slave.cpp:3955] Finished recovery
> I0611 00:40:28.256093 26076 slave.cpp:4109] Querying resource estimator for oversubscribable resources
> I0611 00:40:28.256330 26076 slave.cpp:678] New master detected at master@172.17.0.116:33349
> I0611 00:40:28.256335 26063 status_update_manager.cpp:175] Pausing sending status updates
> I0611 00:40:28.256434 26076 slave.cpp:741] Authenticating with master master@172.17.0.116:33349
> I0611 00:40:28.256456 26076 slave.cpp:746] Using default CRAM-MD5 authenticatee
> I0611 00:40:28.256599 26076 slave.cpp:714] Detecting new master
> I0611 00:40:28.256702 26062 authenticatee.hpp:139] Creating new client SASL connection
> I0611 00:40:28.256769 26076 slave.cpp:4130] Received oversubscribable resources from the resource estimator
> I0611 00:40:28.256804 26076 slave.cpp:4134] No master detected. Re-querying resource estimator after 15secs
> I0611 00:40:28.257128 26074 master.cpp:4192] Authenticating slave(47)@172.17.0.116:33349
> I0611 00:40:28.257244 26061 authenticator.cpp:406] Starting authentication session for crammd5_authenticatee(140)@172.17.0.116:33349
> I0611 00:40:28.257448 26063 authenticator.cpp:92] Creating new server SASL connection
> I0611 00:40:28.257630 26064 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
> I0611 00:40:28.257660 26064 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0611 00:40:28.257786 26069 authenticator.cpp:197] Received SASL authentication start
> I0611 00:40:28.257855 26069 authenticator.cpp:319] Authentication requires more steps
> I0611 00:40:28.257948 26064 authenticatee.hpp:276] Received SASL authentication step
> I0611 00:40:28.258060 26064 authenticator.cpp:225] Received SASL authentication step
> I0611 00:40:28.258106 26064 auxprop.cpp:101] Request to lookup properties for user: 'test-principal' realm: '658ddc752264' server FQDN: '658ddc752264' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0611 00:40:28.258123 26064 auxprop.cpp:173] Looking up auxiliary property '*userPassword'
> I0611 00:40:28.258173 26064 auxprop.cpp:173] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0611 00:40:28.258203 26064 auxprop.cpp:101] Request to lookup properties for user: 'test-principal' realm: '658ddc752264' server FQDN: '658ddc752264' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0611 00:40:28.258215 26064 auxprop.cpp:123] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0611 00:40:28.258224 26064 auxprop.cpp:123] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0611 00:40:28.258242 26064 authenticator.cpp:311] Authentication success
> I0611 00:40:28.258389 26069 authenticatee.hpp:316] Authentication success
> I0611 00:40:28.258401 26065 master.cpp:4222] Successfully authenticated principal 'test-principal' at slave(47)@172.17.0.116:33349
> I0611 00:40:28.258450 26072 authenticator.cpp:424] Authentication session cleanup for crammd5_authenticatee(140)@172.17.0.116:33349
> I0611 00:40:28.258625 26068 slave.cpp:812] Successfully authenticated with master master@172.17.0.116:33349
> I0611 00:40:28.258744 26068 slave.cpp:1146] Will retry registration in 14.347946ms if necessary
> I0611 00:40:28.258904 26069 master.cpp:3168] Registering slave at slave(47)@172.17.0.116:33349 (658ddc752264) with id 20150611-004028-1946161580-33349-26042-S0
> I0611 00:40:28.259302 26065 registrar.cpp:445] Applied 1 operations in 65373ns; attempting to update the 'registry'
> I0611 00:40:28.262166 26067 log.cpp:685] Attempting to append 305 bytes to the log
> I0611 00:40:28.262317 26068 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
> I0611 00:40:28.263157 26070 replica.cpp:511] Replica received write request for position 3
> I0611 00:40:28.263372 26070 leveldb.cpp:343] Persisting action (324 bytes) to leveldb took 175524ns
> I0611 00:40:28.263404 26070 replica.cpp:679] Persisted action at 3
> I0611 00:40:28.264120 26064 replica.cpp:658] Replica received learned notice for position 3
> I0611 00:40:28.264689 26064 leveldb.cpp:343] Persisting action (326 bytes) to leveldb took 536529ns
> I0611 00:40:28.264717 26064 replica.cpp:679] Persisted action at 3
> I0611 00:40:28.264740 26064 replica.cpp:664] Replica learned APPEND action at position 3
> I0611 00:40:28.265750 26071 registrar.cpp:490] Successfully updated the 'registry' in 6.358784ms
> I0611 00:40:28.266057 26066 log.cpp:704] Attempting to truncate the log to 3
> I0611 00:40:28.266203 26073 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
> I0611 00:40:28.266695 26061 slave.cpp:2895] Received ping from slave-observer(46)@172.17.0.116:33349
> I0611 00:40:28.267076 26072 replica.cpp:511] Replica received write request for position 4
> I0611 00:40:28.267200 26065 master.cpp:3225] Registered slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0611 00:40:28.267371 26070 slave.cpp:846] Registered with master master@172.17.0.116:33349; given slave ID 20150611-004028-1946161580-33349-26042-S0
> I0611 00:40:28.267406 26070 fetcher.cpp:77] Clearing fetcher cache
> I0611 00:40:28.267385 26069 hierarchical.hpp:496] Added slave 20150611-004028-1946161580-33349-26042-S0 (658ddc752264) 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)
> I0611 00:40:28.267596 26069 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:28.267608 26072 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 493557ns
> I0611 00:40:28.267624 26069 hierarchical.hpp:852] Performed allocation for slave 20150611-004028-1946161580-33349-26042-S0 in 185107ns
> I0611 00:40:28.267640 26072 replica.cpp:679] Persisted action at 4
> I0611 00:40:28.267599 26066 status_update_manager.cpp:182] Resuming sending status updates
> I0611 00:40:28.267889 26070 slave.cpp:869] Checkpointing SlaveInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/slave.info'
> I0611 00:40:28.268245 26072 replica.cpp:658] Replica received learned notice for position 4
> I0611 00:40:28.268631 26072 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 358080ns
> I0611 00:40:28.268684 26072 leveldb.cpp:401] Deleting ~2 keys from leveldb took 29788ns
> I0611 00:40:28.268698 26072 replica.cpp:679] Persisted action at 4
> I0611 00:40:28.268718 26072 replica.cpp:664] Replica learned TRUNCATE action at position 4
> I0611 00:40:28.269922 26042 sched.cpp:157] Version: 0.23.0
> I0611 00:40:28.270370 26076 sched.cpp:254] New master detected at master@172.17.0.116:33349
> I0611 00:40:28.270438 26076 sched.cpp:310] Authenticating with master master@172.17.0.116:33349
> I0611 00:40:28.270457 26076 sched.cpp:317] Using default CRAM-MD5 authenticatee
> I0611 00:40:28.270597 26066 authenticatee.hpp:139] Creating new client SASL connection
> I0611 00:40:28.270895 26074 master.cpp:4192] Authenticating scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:28.270992 26068 authenticator.cpp:406] Starting authentication session for crammd5_authenticatee(141)@172.17.0.116:33349
> I0611 00:40:28.271212 26065 authenticator.cpp:92] Creating new server SASL connection
> I0611 00:40:28.271389 26076 authenticatee.hpp:230] Received SASL authentication mechanisms: CRAM-MD5
> I0611 00:40:28.271427 26076 authenticatee.hpp:256] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0611 00:40:28.271509 26068 authenticator.cpp:197] Received SASL authentication start
> I0611 00:40:28.271554 26068 authenticator.cpp:319] Authentication requires more steps
> I0611 00:40:28.271628 26070 authenticatee.hpp:276] Received SASL authentication step
> I0611 00:40:28.271734 26073 authenticator.cpp:225] Received SASL authentication step
> I0611 00:40:28.271761 26073 auxprop.cpp:101] Request to lookup properties for user: 'test-principal' realm: '658ddc752264' server FQDN: '658ddc752264' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0611 00:40:28.271770 26073 auxprop.cpp:173] Looking up auxiliary property '*userPassword'
> I0611 00:40:28.271803 26073 auxprop.cpp:173] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0611 00:40:28.271848 26073 auxprop.cpp:101] Request to lookup properties for user: 'test-principal' realm: '658ddc752264' server FQDN: '658ddc752264' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0611 00:40:28.271862 26073 auxprop.cpp:123] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0611 00:40:28.271867 26073 auxprop.cpp:123] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0611 00:40:28.271879 26073 authenticator.cpp:311] Authentication success
> I0611 00:40:28.271949 26070 authenticatee.hpp:316] Authentication success
> I0611 00:40:28.271985 26068 master.cpp:4222] Successfully authenticated principal 'test-principal' at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:28.272043 26070 authenticator.cpp:424] Authentication session cleanup for crammd5_authenticatee(141)@172.17.0.116:33349
> I0611 00:40:28.272197 26073 sched.cpp:398] Successfully authenticated with master master@172.17.0.116:33349
> I0611 00:40:28.272222 26073 sched.cpp:521] Sending registration request to master@172.17.0.116:33349
> I0611 00:40:28.272280 26073 sched.cpp:554] Will retry registration in 983.889094ms if necessary
> I0611 00:40:28.272351 26072 master.cpp:1716] Received registration request for framework 'default' at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> W0611 00:40:28.272406 26072 master.cpp:1539] Framework at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349 (authenticated as 'test-principal') does not specify principal in its FrameworkInfo
> I0611 00:40:28.272425 26072 master.cpp:1555] Authorizing framework principal '' to receive offers for role '*'
> I0611 00:40:28.272718 26067 master.cpp:1783] Registering framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349 with checkpointing enabled and capabilities [ ]
> I0611 00:40:28.273047 26063 hierarchical.hpp:354] Added framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.273154 26070 sched.cpp:448] Framework registered with 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.273200 26070 sched.cpp:462] Scheduler::registered took 22736ns
> I0611 00:40:28.273486 26063 hierarchical.hpp:834] Performed allocation for 1 slaves in 415024ns
> I0611 00:40:28.273775 26067 master.cpp:4111] Sending 1 offers to framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:28.274096 26061 sched.cpp:611] Scheduler::resourceOffers took 58588ns
> I0611 00:40:28.276064 26064 master.cpp:2424] Processing ACCEPT call for offers: [ 20150611-004028-1946161580-33349-26042-O0 ] on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264) for framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:28.276109 26064 master.cpp:2268] Authorizing framework principal '' to launch task 0 as user 'mesos'
> I0611 00:40:28.276221 26064 master.cpp:2268] Authorizing framework principal '' to launch task 1 as user 'mesos'
> I0611 00:40:28.276329 26064 master.cpp:2268] Authorizing framework principal '' to launch task 2 as user 'mesos'
> I0611 00:40:28.277539 26070 master.hpp:159] Adding task 0 with resources cpus(*):1; mem(*):1 on slave 20150611-004028-1946161580-33349-26042-S0 (658ddc752264)
> I0611 00:40:28.277657 26070 master.cpp:2751] Launching task 0 of framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349 with resources cpus(*):1; mem(*):1 on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.277953 26063 slave.cpp:1186] Got assigned task 0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.278112 26063 slave.cpp:4439] Checkpointing FrameworkInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/framework.info'
> I0611 00:40:28.278301 26070 master.hpp:159] Adding task 1 with resources cpus(*):1; mem(*):1 on slave 20150611-004028-1946161580-33349-26042-S0 (658ddc752264)
> I0611 00:40:28.278399 26070 master.cpp:2751] Launching task 1 of framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349 with resources cpus(*):1; mem(*):1 on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.278478 26063 slave.cpp:4446] Checkpointing framework pid 'scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349' to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/framework.pid'
> I0611 00:40:28.278982 26070 master.hpp:159] Adding task 2 with resources cpus(*):1; mem(*):1 on slave 20150611-004028-1946161580-33349-26042-S0 (658ddc752264)
> I0611 00:40:28.279062 26070 master.cpp:2751] Launching task 2 of framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349 with resources cpus(*):1; mem(*):1 on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.279366 26063 slave.cpp:1186] Got assigned task 1 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.279496 26065 hierarchical.hpp:741] Recovered cpus(*):997; mem(*):997; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):997; mem(*):997; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150611-004028-1946161580-33349-26042-S0 from framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.279634 26065 hierarchical.hpp:777] Framework 20150611-004028-1946161580-33349-26042-0000 filtered slave 20150611-004028-1946161580-33349-26042-S0 for 5secs
> I0611 00:40:28.280042 26063 slave.cpp:1186] Got assigned task 2 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.280503 26063 slave.cpp:1300] Launching task 0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.287946 26063 slave.cpp:4875] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0/executor.info'
> I0611 00:40:28.288858 26063 slave.cpp:4512] Launching executor 0 of framework 20150611-004028-1946161580-33349-26042-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0/runs/7bde6e5f-f6a9-4631-973b-3dbe57deae6d'
> I0611 00:40:28.289345 26072 containerizer.cpp:530] Starting container '7bde6e5f-f6a9-4631-973b-3dbe57deae6d' for executor '0' of framework '20150611-004028-1946161580-33349-26042-0000'
> I0611 00:40:28.289517 26063 slave.cpp:4898] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0/runs/7bde6e5f-f6a9-4631-973b-3dbe57deae6d/tasks/0/task.info'
> I0611 00:40:28.290138 26063 slave.cpp:1446] Queuing task '0' for executor 0 of framework '20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.290283 26063 slave.cpp:1300] Launching task 1 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.292667 26072 launcher.cpp:131] Forked child with pid '30601' for container '7bde6e5f-f6a9-4631-973b-3dbe57deae6d'
> I0611 00:40:28.292867 26072 containerizer.cpp:766] Checkpointing executor's forked pid 30601 to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0/runs/7bde6e5f-f6a9-4631-973b-3dbe57deae6d/pids/forked.pid'
> I0611 00:40:28.295876 26065 fetcher.cpp:299] Starting to fetch URIs for container: 7bde6e5f-f6a9-4631-973b-3dbe57deae6d, directory: /tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0/runs/7bde6e5f-f6a9-4631-973b-3dbe57deae6d
> I0611 00:40:28.298319 26063 slave.cpp:4875] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1/executor.info'
> I0611 00:40:28.299039 26063 slave.cpp:4512] Launching executor 1 of framework 20150611-004028-1946161580-33349-26042-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1/runs/fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef'
> I0611 00:40:28.299458 26073 containerizer.cpp:530] Starting container 'fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef' for executor '1' of framework '20150611-004028-1946161580-33349-26042-0000'
> I0611 00:40:28.299595 26063 slave.cpp:4898] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1/runs/fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef/tasks/1/task.info'
> I0611 00:40:28.300205 26063 slave.cpp:1446] Queuing task '1' for executor 1 of framework '20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.300290 26065 fetcher.cpp:873] Created cache entry 'mesos@http://172.17.0.116:33349/(1407)/mesos-fetcher-test-archive.tgz' with file: c1-mesos-fetc_rchive.tgz
> I0611 00:40:28.300354 26063 slave.cpp:1300] Launching task 2 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.301391 26064 fetcher.cpp:248] Fetching size for URI: http://172.17.0.116:33349/(1407)/mesos-fetcher-test-archive.tgz
> I0611 00:40:28.305124 26072 launcher.cpp:131] Forked child with pid '30612' for container 'fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef'
> I0611 00:40:28.305352 26072 containerizer.cpp:766] Checkpointing executor's forked pid 30612 to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1/runs/fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef/pids/forked.pid'
> I0611 00:40:28.307904 26073 fetcher.cpp:299] Starting to fetch URIs for container: fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef, directory: /tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1/runs/fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef
> I0611 00:40:28.309226 26063 slave.cpp:4875] Checkpointing ExecutorInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2/executor.info'
> I0611 00:40:28.310174 26063 slave.cpp:4512] Launching executor 2 of framework 20150611-004028-1946161580-33349-26042-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2/runs/09e97509-9ee7-4c22-b6ae-7017b778e120'
> I0611 00:40:28.310665 26076 containerizer.cpp:530] Starting container '09e97509-9ee7-4c22-b6ae-7017b778e120' for executor '2' of framework '20150611-004028-1946161580-33349-26042-0000'
> I0611 00:40:28.310803 26063 slave.cpp:4898] Checkpointing TaskInfo to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2/runs/09e97509-9ee7-4c22-b6ae-7017b778e120/tasks/2/task.info'
> I0611 00:40:28.311332 26063 slave.cpp:1446] Queuing task '2' for executor 2 of framework '20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.311569 26063 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0/runs/7bde6e5f-f6a9-4631-973b-3dbe57deae6d'
> I0611 00:40:28.311640 26063 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1/runs/fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef'
> I0611 00:40:28.311704 26063 slave.cpp:631] Successfully attached file '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2/runs/09e97509-9ee7-4c22-b6ae-7017b778e120'
> I0611 00:40:28.313941 26076 launcher.cpp:131] Forked child with pid '30631' for container '09e97509-9ee7-4c22-b6ae-7017b778e120'
> I0611 00:40:28.314162 26076 containerizer.cpp:766] Checkpointing executor's forked pid 30631 to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2/runs/09e97509-9ee7-4c22-b6ae-7017b778e120/pids/forked.pid'
> I0611 00:40:28.317991 26073 fetcher.cpp:299] Starting to fetch URIs for container: 09e97509-9ee7-4c22-b6ae-7017b778e120, directory: /tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2/runs/09e97509-9ee7-4c22-b6ae-7017b778e120
> I0611 00:40:28.325078 26069 process.cpp:2751] Handling HTTP event for process '(1407)' with path: '/(1407)/mesos-fetcher-test-archive.tgz'
> I0611 00:40:28.325812 26070 process.cpp:1082] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz' with length 145
> HTTP/1.1 200 OK
> Date: Thu, 11 Jun 2015 00:40:28 GMT
> Content-Length: 145
> I0611 00:40:28.331157 26073 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.23.0/_build/src/mesos-fetcher'
> I0611 00:40:28.333117 26073 fetcher.cpp:663] Claiming fetcher cache space for: mesos@http://172.17.0.116:33349/(1407)/mesos-fetcher-test-archive.tgz
> I0611 00:40:28.333161 26073 fetcher.cpp:1086] Claimed cache space: 145B, now using: 145B
> I0611 00:40:28.339479 26064 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.23.0/_build/src/mesos-fetcher'
> I0611 00:40:28.391845 26068 process.cpp:2751] Handling HTTP event for process '(1407)' with path: '/(1407)/mesos-fetcher-test-archive.tgz'
> I0611 00:40:28.392280 26071 process.cpp:1082] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz' with length 145
> I0611 00:40:28.394189 26070 process.cpp:2751] Handling HTTP event for process '(1407)' with path: '/(1407)/mesos-fetcher-test-archive.tgz'
> I0611 00:40:28.394484 26074 process.cpp:1082] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz' with length 145
> I0611 00:40:28.399312 26066 process.cpp:2751] Handling HTTP event for process '(1407)' with path: '/(1407)/mesos-fetcher-test-cmd'
> I0611 00:40:28.399658 26068 process.cpp:1082] Sending file at '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' with length 30
> E0611 00:40:28.491381 26062 fetcher.cpp:515] Failed to run mesos-fetcher: Failed to fetch all URIs for container 'fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef' with exit status: 256
> I0611 00:40:28.491879 26062 fetcher.cpp:1098] Released cache space: 0B, now using: 145B
> E0611 00:40:28.491886 26065 slave.cpp:3154] Container 'fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef' for executor '1' of framework '20150611-004028-1946161580-33349-26042-0000' failed to start: Failed to fetch all URIs for container 'fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef' with exit status: 256
> I0611 00:40:28.492027 26068 containerizer.cpp:997] Destroying container 'fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef'
> I0611 00:40:28.492053 26068 containerizer.cpp:1026] Waiting for the isolators to complete for container 'fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef'
> I0611 00:40:28.499197 26067 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.23.0/_build/src/mesos-fetcher'
> I0611 00:40:28.499322 26062 slave.cpp:3211] Monitoring executor '0' of framework '20150611-004028-1946161580-33349-26042-0000' in container '7bde6e5f-f6a9-4631-973b-3dbe57deae6d'
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0611 00:40:28.558794 30697 process.cpp:926] libprocess is initialized on 172.17.0.116:46512 for 16 cpus
> I0611 00:40:28.559777 30697 logging.cpp:177] Logging to STDERR
> I0611 00:40:28.562319 30697 exec.cpp:132] Version: 0.23.0
> I0611 00:40:28.572161 30732 exec.cpp:182] Executor started at: executor(1)@172.17.0.116:46512 with pid 30697
> I0611 00:40:28.574589 26071 slave.cpp:2198] Got registration for executor '0' of framework 20150611-004028-1946161580-33349-26042-0000 from executor(1)@172.17.0.116:46512
> I0611 00:40:28.574707 26071 slave.cpp:2284] Checkpointing executor pid 'executor(1)@172.17.0.116:46512' to '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0/runs/7bde6e5f-f6a9-4631-973b-3dbe57deae6d/pids/libprocess.pid'
> I0611 00:40:28.576479 26074 slave.cpp:1598] Sending queued task '0' to executor '0' of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.576915 30727 exec.cpp:206] Executor registered on slave 20150611-004028-1946161580-33349-26042-S0
> I0611 00:40:28.578711 30727 exec.cpp:218] Executor::registered took 242627ns
> Registered executor on 658ddc752264
> I0611 00:40:28.579038 30727 exec.cpp:293] Executor asked to run task '0'
> Starting task 0
> I0611 00:40:28.579160 30727 exec.cpp:302] Executor::launchTask took 95102ns
> Forked command at 30743
> sh -c './mesos-fetcher-test-cmd 0'
> I0611 00:40:28.582968 30730 exec.cpp:507] Executor sending status update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.583927 26071 slave.cpp:2564] Handling status update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 from executor(1)@172.17.0.116:46512
> I0611 00:40:28.584228 26072 status_update_manager.cpp:321] Received status update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.584264 26072 status_update_manager.cpp:498] Creating StatusUpdate stream for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.584704 26072 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.586175 26072 status_update_manager.cpp:375] Forwarding update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 to the slave
> I0611 00:40:28.586480 26072 slave.cpp:2819] Forwarding the update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 to master@172.17.0.116:33349
> I0611 00:40:28.586612 26072 slave.cpp:2746] Status update manager successfully handled status update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.586645 26072 slave.cpp:2752] Sending acknowledgement for status update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 to executor(1)@172.17.0.116:46512
> I0611 00:40:28.587002 26076 master.cpp:3585] Status update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 from slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.587038 26076 master.cpp:3624] Forwarding status update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.587162 26076 master.cpp:4978] Updating the latest state of task 0 of framework 20150611-004028-1946161580-33349-26042-0000 to TASK_RUNNING
> I0611 00:40:28.587364 26061 sched.cpp:717] Scheduler::statusUpdate took 119729ns
> I0611 00:40:28.587575 26062 master.cpp:3015] Forwarding status update acknowledgement 9e94363e-e0e1-4bd2-aa92-cf290a2530b1 for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349 to slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.587920 26068 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.587990 30725 exec.cpp:339] Executor received status update acknowledgement 9e94363e-e0e1-4bd2-aa92-cf290a2530b1 for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.588034 26068 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_RUNNING (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.588912 26076 slave.cpp:2138] Status update manager successfully handled status update acknowledgement (UUID: 9e94363e-e0e1-4bd2-aa92-cf290a2530b1) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.592269 26068 containerizer.cpp:1184] Executor for container 'fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef' has exited
> E0611 00:40:28.593114 26073 fetcher.cpp:515] Failed to run mesos-fetcher: Failed to fetch all URIs for container '09e97509-9ee7-4c22-b6ae-7017b778e120' with exit status: 256
> Failed to synchronize with slave (it's probably exited)
> E0611 00:40:28.593425 26063 slave.cpp:3154] Container '09e97509-9ee7-4c22-b6ae-7017b778e120' for executor '2' of framework '20150611-004028-1946161580-33349-26042-0000' failed to start: Failed to fetch all URIs for container '09e97509-9ee7-4c22-b6ae-7017b778e120' with exit status: 256
> I0611 00:40:28.593508 26072 containerizer.cpp:997] Destroying container '09e97509-9ee7-4c22-b6ae-7017b778e120'
> I0611 00:40:28.593530 26063 slave.cpp:3268] Executor '1' of framework 20150611-004028-1946161580-33349-26042-0000 terminated with signal Killed
> I0611 00:40:28.593530 26072 containerizer.cpp:1026] Waiting for the isolators to complete for container '09e97509-9ee7-4c22-b6ae-7017b778e120'
> E0611 00:40:28.593739 26069 slave.cpp:3515] Failed to unmonitor container for executor 1 of framework 20150611-004028-1946161580-33349-26042-0000: Not monitored
> I0611 00:40:28.595237 26063 slave.cpp:2564] Handling status update TASK_FAILED (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000 from @0.0.0.0:0
> I0611 00:40:28.595484 26063 slave.cpp:4813] Terminating task 1
> I0611 00:40:28.595937 26077 process.cpp:552] Decode failure: Connection reset by peer
> W0611 00:40:28.597589 26072 containerizer.cpp:881] Ignoring update for unknown container: fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef
> I0611 00:40:28.597913 26067 status_update_manager.cpp:321] Received status update TASK_FAILED (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.597955 26067 status_update_manager.cpp:498] Creating StatusUpdate stream for task 1 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.598310 26067 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_FAILED (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.599653 26067 status_update_manager.cpp:375] Forwarding update TASK_FAILED (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000 to the slave
> I0611 00:40:28.599859 26065 slave.cpp:2819] Forwarding the update TASK_FAILED (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000 to master@172.17.0.116:33349
> I0611 00:40:28.600031 26065 slave.cpp:2746] Status update manager successfully handled status update TASK_FAILED (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.600142 26064 master.cpp:3585] Status update TASK_FAILED (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000 from slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.600179 26064 master.cpp:3624] Forwarding status update TASK_FAILED (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.600316 26064 master.cpp:4978] Updating the latest state of task 1 of framework 20150611-004028-1946161580-33349-26042-0000 to TASK_FAILED
> I0611 00:40:28.600571 26069 sched.cpp:717] Scheduler::statusUpdate took 97941ns
> I0611 00:40:28.600594 26061 hierarchical.hpp:741] Recovered cpus(*):1; mem(*):1 (total allocatable: cpus(*):998; mem(*):998; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150611-004028-1946161580-33349-26042-S0 from framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.600893 26064 master.cpp:5046] Removing task 1 with resources cpus(*):1; mem(*):1 of framework 20150611-004028-1946161580-33349-26042-0000 on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.601007 26064 master.cpp:3015] Forwarding status update acknowledgement c4066d51-abab-43a2-bf20-f28063ed0153 for task 1 of framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349 to slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.601276 26066 status_update_manager.cpp:393] Received status update acknowledgement (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.601361 26066 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_FAILED (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.602502 26066 status_update_manager.cpp:529] Cleaning up status update stream for task 1 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.602725 26071 slave.cpp:2138] Status update manager successfully handled status update acknowledgement (UUID: c4066d51-abab-43a2-bf20-f28063ed0153) for task 1 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.602778 26071 slave.cpp:4854] Completing task 1
> I0611 00:40:28.602901 26071 slave.cpp:3378] Cleaning up executor '1' of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.603219 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1/runs/fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef' for gc 6.99999301946963days in the future
> I0611 00:40:28.603381 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1' for gc 6.99999301806518days in the future
> I0611 00:40:28.603464 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1/runs/fe2dae2c-3efc-49e2-98a9-c6ffd689e1ef' for gc 6.99999301674667days in the future
> I0611 00:40:28.603598 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/1' for gc 6.99999301563556days in the future
> Command exited with status 0 (pid: 30743)
> I0611 00:40:28.684661 30736 exec.cpp:507] Executor sending status update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.685423 26066 slave.cpp:2564] Handling status update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 from executor(1)@172.17.0.116:46512
> I0611 00:40:28.685531 26066 slave.cpp:4813] Terminating task 0
> I0611 00:40:28.686537 26067 status_update_manager.cpp:321] Received status update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.686595 26067 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.687923 26067 status_update_manager.cpp:375] Forwarding update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 to the slave
> I0611 00:40:28.688122 26073 slave.cpp:2819] Forwarding the update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 to master@172.17.0.116:33349
> I0611 00:40:28.688282 26073 slave.cpp:2746] Status update manager successfully handled status update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.688315 26073 slave.cpp:2752] Sending acknowledgement for status update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 to executor(1)@172.17.0.116:46512
> I0611 00:40:28.688357 26066 master.cpp:3585] Status update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 from slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.688396 26066 master.cpp:3624] Forwarding status update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.688534 26066 master.cpp:4978] Updating the latest state of task 0 of framework 20150611-004028-1946161580-33349-26042-0000 to TASK_FINISHED
> I0611 00:40:28.688725 26069 sched.cpp:717] Scheduler::statusUpdate took 102799ns
> I0611 00:40:28.688778 26065 hierarchical.hpp:741] Recovered cpus(*):1; mem(*):1 (total allocatable: cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150611-004028-1946161580-33349-26042-S0 from framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.689079 26072 master.cpp:5046] Removing task 0 with resources cpus(*):1; mem(*):1 of framework 20150611-004028-1946161580-33349-26042-0000 on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.689205 26072 master.cpp:3015] Forwarding status update acknowledgement e4609c35-53c8-42ee-b945-54bddad51ab6 for task 0 of framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349 to slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.689443 26061 status_update_manager.cpp:393] Received status update acknowledgement (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.689479 30728 exec.cpp:339] Executor received status update acknowledgement e4609c35-53c8-42ee-b945-54bddad51ab6 for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.689602 26061 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_FINISHED (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.690604 26061 status_update_manager.cpp:529] Cleaning up status update stream for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.690866 26067 slave.cpp:2138] Status update manager successfully handled status update acknowledgement (UUID: e4609c35-53c8-42ee-b945-54bddad51ab6) for task 0 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.690961 26067 slave.cpp:4854] Completing task 0
> I0611 00:40:28.693780 26066 containerizer.cpp:1184] Executor for container '09e97509-9ee7-4c22-b6ae-7017b778e120' has exited
> I0611 00:40:28.694926 26066 slave.cpp:3268] Executor '2' of framework 20150611-004028-1946161580-33349-26042-0000 exited with status 1
> E0611 00:40:28.695080 26072 slave.cpp:3515] Failed to unmonitor container for executor 2 of framework 20150611-004028-1946161580-33349-26042-0000: Not monitored
> I0611 00:40:28.696722 26066 slave.cpp:2564] Handling status update TASK_FAILED (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000 from @0.0.0.0:0
> I0611 00:40:28.696780 26066 slave.cpp:4813] Terminating task 2
> W0611 00:40:28.697016 26076 containerizer.cpp:881] Ignoring update for unknown container: 09e97509-9ee7-4c22-b6ae-7017b778e120
> I0611 00:40:28.697342 26076 status_update_manager.cpp:321] Received status update TASK_FAILED (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.697381 26076 status_update_manager.cpp:498] Creating StatusUpdate stream for task 2 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.697770 26076 status_update_manager.cpp:821] Checkpointing UPDATE for status update TASK_FAILED (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.699062 26076 status_update_manager.cpp:375] Forwarding update TASK_FAILED (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000 to the slave
> I0611 00:40:28.699250 26074 slave.cpp:2819] Forwarding the update TASK_FAILED (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000 to master@172.17.0.116:33349
> I0611 00:40:28.699416 26074 slave.cpp:2746] Status update manager successfully handled status update TASK_FAILED (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.699529 26061 master.cpp:3585] Status update TASK_FAILED (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000 from slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.699561 26061 master.cpp:3624] Forwarding status update TASK_FAILED (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.699686 26061 master.cpp:4978] Updating the latest state of task 2 of framework 20150611-004028-1946161580-33349-26042-0000 to TASK_FAILED
> I0611 00:40:28.699928 26070 sched.cpp:717] Scheduler::statusUpdate took 111157ns
> I0611 00:40:28.699976 26067 hierarchical.hpp:741] Recovered cpus(*):1; mem(*):1 (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150611-004028-1946161580-33349-26042-S0 from framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.700158 26065 master.cpp:5046] Removing task 2 with resources cpus(*):1; mem(*):1 of framework 20150611-004028-1946161580-33349-26042-0000 on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.700294 26065 master.cpp:3015] Forwarding status update acknowledgement 82f23559-b612-44ef-bc14-2c42368ba13d for task 2 of framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349 to slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264)
> I0611 00:40:28.700510 26065 status_update_manager.cpp:393] Received status update acknowledgement (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.700615 26065 status_update_manager.cpp:821] Checkpointing ACK for status update TASK_FAILED (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.701634 26065 status_update_manager.cpp:529] Cleaning up status update stream for task 2 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.701866 26061 slave.cpp:2138] Status update manager successfully handled status update acknowledgement (UUID: 82f23559-b612-44ef-bc14-2c42368ba13d) for task 2 of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.701918 26061 slave.cpp:4854] Completing task 2
> I0611 00:40:28.701962 26061 slave.cpp:3378] Cleaning up executor '2' of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:28.702255 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2/runs/09e97509-9ee7-4c22-b6ae-7017b778e120' for gc 6.9999918729037days in the future
> I0611 00:40:28.702478 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2' for gc 6.99999187138963days in the future
> I0611 00:40:28.702582 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2/runs/09e97509-9ee7-4c22-b6ae-7017b778e120' for gc 6.99999187020741days in the future
> I0611 00:40:28.702733 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/2' for gc 6.99999186917926days in the future
> I0611 00:40:29.217691 26069 hierarchical.hpp:834] Performed allocation for 1 slaves in 559962ns
> I0611 00:40:29.218114 26064 master.cpp:4111] Sending 1 offers to framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:29.218622 26069 sched.cpp:611] Scheduler::resourceOffers took 113704ns
> I0611 00:40:29.219339 26070 master.cpp:2424] Processing ACCEPT call for offers: [ 20150611-004028-1946161580-33349-26042-O1 ] on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264) for framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:29.219998 26066 hierarchical.hpp:741] Recovered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150611-004028-1946161580-33349-26042-S0 from framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:29.220055 26066 hierarchical.hpp:777] Framework 20150611-004028-1946161580-33349-26042-0000 filtered slave 20150611-004028-1946161580-33349-26042-S0 for 5secs
> I0611 00:40:29.700505 26075 containerizer.cpp:1184] Executor for container '7bde6e5f-f6a9-4631-973b-3dbe57deae6d' has exited
> I0611 00:40:29.700566 26075 containerizer.cpp:997] Destroying container '7bde6e5f-f6a9-4631-973b-3dbe57deae6d'
> I0611 00:40:29.703644 26065 slave.cpp:3268] Executor '0' of framework 20150611-004028-1946161580-33349-26042-0000 exited with status 0
> I0611 00:40:29.703851 26065 slave.cpp:3378] Cleaning up executor '0' of framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:29.704249 26066 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0/runs/7bde6e5f-f6a9-4631-973b-3dbe57deae6d' for gc 6.99999184983704days in the future
> I0611 00:40:29.704416 26075 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0' for gc 6.99999184786963days in the future
> I0611 00:40:29.704507 26075 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0/runs/7bde6e5f-f6a9-4631-973b-3dbe57deae6d' for gc 6.99999184659852days in the future
> I0611 00:40:29.704608 26065 slave.cpp:3465] Cleaning up framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:29.704639 26075 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000/executors/0' for gc 6.99999184553185days in the future
> I0611 00:40:29.704718 26062 status_update_manager.cpp:283] Closing status update streams for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:29.704789 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000' for gc 6.99999184344889days in the future
> I0611 00:40:29.704926 26062 gc.cpp:56] Scheduling '/tmp/FetcherCacheHttpTest_HttpMixed_kwsjNe/meta/slaves/20150611-004028-1946161580-33349-26042-S0/frameworks/20150611-004028-1946161580-33349-26042-0000' for gc 6.99999184208296days in the future
> I0611 00:40:30.219069 26070 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:30.219151 26070 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:30.219171 26070 hierarchical.hpp:834] Performed allocation for 1 slaves in 599271ns
> I0611 00:40:31.220145 26076 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:31.220199 26076 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:31.220218 26076 hierarchical.hpp:834] Performed allocation for 1 slaves in 361554ns
> I0611 00:40:32.220938 26072 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:32.220989 26072 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:32.221007 26072 hierarchical.hpp:834] Performed allocation for 1 slaves in 354664ns
> I0611 00:40:33.221792 26068 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:33.221897 26068 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:33.221930 26068 hierarchical.hpp:834] Performed allocation for 1 slaves in 444354ns
> I0611 00:40:34.223534 26073 hierarchical.hpp:834] Performed allocation for 1 slaves in 511375ns
> I0611 00:40:34.224037 26075 master.cpp:4111] Sending 1 offers to framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:34.224625 26075 sched.cpp:611] Scheduler::resourceOffers took 133787ns
> I0611 00:40:34.225481 26075 master.cpp:2424] Processing ACCEPT call for offers: [ 20150611-004028-1946161580-33349-26042-O2 ] on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264) for framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:34.226282 26075 hierarchical.hpp:741] Recovered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150611-004028-1946161580-33349-26042-S0 from framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:34.226343 26075 hierarchical.hpp:777] Framework 20150611-004028-1946161580-33349-26042-0000 filtered slave 20150611-004028-1946161580-33349-26042-S0 for 5secs
> I0611 00:40:35.224714 26064 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:35.224768 26064 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:35.224787 26064 hierarchical.hpp:834] Performed allocation for 1 slaves in 353370ns
> I0611 00:40:36.225898 26062 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:36.225947 26062 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:36.225965 26062 hierarchical.hpp:834] Performed allocation for 1 slaves in 366492ns
> I0611 00:40:37.227095 26070 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:37.227152 26070 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:37.227170 26070 hierarchical.hpp:834] Performed allocation for 1 slaves in 371931ns
> I0611 00:40:38.228006 26065 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:38.228065 26065 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:38.228096 26065 hierarchical.hpp:834] Performed allocation for 1 slaves in 417441ns
> I0611 00:40:39.229778 26071 hierarchical.hpp:834] Performed allocation for 1 slaves in 499278ns
> I0611 00:40:39.230177 26074 master.cpp:4111] Sending 1 offers to framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:39.230624 26068 sched.cpp:611] Scheduler::resourceOffers took 99803ns
> I0611 00:40:39.231348 26076 master.cpp:2424] Processing ACCEPT call for offers: [ 20150611-004028-1946161580-33349-26042-O3 ] on slave 20150611-004028-1946161580-33349-26042-S0 at slave(47)@172.17.0.116:33349 (658ddc752264) for framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:39.232098 26068 hierarchical.hpp:741] Recovered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total allocatable: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]) on slave 20150611-004028-1946161580-33349-26042-S0 from framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:39.232158 26068 hierarchical.hpp:777] Framework 20150611-004028-1946161580-33349-26042-0000 filtered slave 20150611-004028-1946161580-33349-26042-S0 for 5secs
> I0611 00:40:40.231142 26074 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:40.231194 26074 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:40.231211 26074 hierarchical.hpp:834] Performed allocation for 1 slaves in 340014ns
> I0611 00:40:41.231977 26066 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:41.232029 26066 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:41.232048 26066 hierarchical.hpp:834] Performed allocation for 1 slaves in 411628ns
> I0611 00:40:42.233392 26071 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:42.233444 26071 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:42.233463 26071 hierarchical.hpp:834] Performed allocation for 1 slaves in 358516ns
> I0611 00:40:43.234984 26076 hierarchical.hpp:997] Filtered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 20150611-004028-1946161580-33349-26042-S0 for framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:43.235039 26076 hierarchical.hpp:933] No resources available to allocate!
> I0611 00:40:43.235070 26076 hierarchical.hpp:834] Performed allocation for 1 slaves in 398273ns
> I0611 00:40:43.257271 26070 slave.cpp:4109] Querying resource estimator for oversubscribable resources
> I0611 00:40:43.257582 26062 slave.cpp:4130] Received oversubscribable resources from the resource estimator
> I0611 00:40:43.267734 26069 slave.cpp:2895] Received ping from slave-observer(46)@172.17.0.116:33349
> ../../src/tests/fetcher_cache_tests.cpp:1004: Failure
> Failed to wait 15secs for awaitFinished(tasks)
> I0611 00:40:43.329689 26042 sched.cpp:1591] Asked to stop the driver
> I0611 00:40:43.330145 26073 sched.cpp:831] Stopping framework '20150611-004028-1946161580-33349-26042-0000'
> I0611 00:40:43.330777 26074 master.cpp:2054] Asked to unregister framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:43.330893 26074 master.cpp:4532] Removing framework 20150611-004028-1946161580-33349-26042-0000 (default) at scheduler-e5bc28c2-aed6-461a-bb5e-77ec57032e75@172.17.0.116:33349
> I0611 00:40:43.331203 26063 hierarchical.hpp:437] Deactivated framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:43.331290 26065 slave.cpp:1811] Asked to shut down framework 20150611-004028-1946161580-33349-26042-0000 by master@172.17.0.116:33349
> W0611 00:40:43.331336 26065 slave.cpp:1826] Cannot shut down unknown framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:43.331665 26071 hierarchical.hpp:391] Removed framework 20150611-004028-1946161580-33349-26042-0000
> I0611 00:40:43.332484 26067 master.cpp:839] Master terminating
> I0611 00:40:43.332773 26074 hierarchical.hpp:527] Removed slave 20150611-004028-1946161580-33349-26042-S0
> I0611 00:40:43.333277 26063 slave.cpp:2980] master@172.17.0.116:33349 exited
> W0611 00:40:43.333305 26063 slave.cpp:2983] Master disconnected! Waiting for a new master to be elected
> I0611 00:40:43.338379 26067 slave.cpp:560] Slave terminating
> [ FAILED ] FetcherCacheHttpTest.HttpMixed (15148 ms)
> {noformat}
> [~bernd-mesos] couldn't find a ticket, sorry if this is a duplicate!
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)