You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Anand Mazumdar (JIRA)" <ji...@apache.org> on 2015/11/08 07:28:11 UTC
[jira] [Commented] (MESOS-2831) FetcherCacheTest.SimpleEviction is
flaky
[ https://issues.apache.org/jira/browse/MESOS-2831?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14995535#comment-14995535 ]
Anand Mazumdar commented on MESOS-2831:
---------------------------------------
This is still flaky. The root cause might be different though, not sure. [~bernd-mesos] Should I open a new JIRA or re-open this ?
Logs from a ASF CI Run:
https://builds.apache.org/job/Mesos/1193/COMPILER=gcc,CONFIGURATION=--verbose,OS=centos:7,label_exp=docker%7C%7CHadoop/console
{code}
[ RUN ] FetcherCacheTest.SimpleEviction
I1107 19:36:43.040343 30634 leveldb.cpp:176] Opened db in 5.759408ms
I1107 19:36:43.044983 30634 leveldb.cpp:183] Compacted db in 4.530307ms
I1107 19:36:43.045104 30634 leveldb.cpp:198] Created db iterator in 31039ns
I1107 19:36:43.045132 30634 leveldb.cpp:204] Seeked to beginning of db in 3710ns
I1107 19:36:43.045143 30634 leveldb.cpp:273] Iterated through 0 keys in the db in 345ns
I1107 19:36:43.045212 30634 replica.cpp:780] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1107 19:36:43.048341 30655 recover.cpp:449] Starting replica recovery
I1107 19:36:43.048702 30655 recover.cpp:475] Replica is in EMPTY status
I1107 19:36:43.050097 30665 replica.cpp:676] Replica in EMPTY status received a broadcasted recover request from (1366)@172.17.5.200:41587
I1107 19:36:43.050868 30655 recover.cpp:195] Received a recover response from a replica in EMPTY status
I1107 19:36:43.051520 30655 recover.cpp:566] Updating replica status to STARTING
I1107 19:36:43.052522 30655 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 670849ns
I1107 19:36:43.052634 30655 replica.cpp:323] Persisted replica status to STARTING
I1107 19:36:43.053145 30664 recover.cpp:475] Replica is in STARTING status
I1107 19:36:43.054857 30655 replica.cpp:676] Replica in STARTING status received a broadcasted recover request from (1367)@172.17.5.200:41587
I1107 19:36:43.056457 30655 recover.cpp:195] Received a recover response from a replica in STARTING status
I1107 19:36:43.057020 30655 recover.cpp:566] Updating replica status to VOTING
I1107 19:36:43.058007 30664 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 774859ns
I1107 19:36:43.058068 30664 replica.cpp:323] Persisted replica status to VOTING
I1107 19:36:43.058660 30664 recover.cpp:580] Successfully joined the Paxos group
I1107 19:36:43.058848 30664 recover.cpp:464] Recover process terminated
I1107 19:36:43.059594 30666 master.cpp:367] Master 7d94c7fb-8950-4bcf-80c1-46112292dcd6 (095b2d77f516) started on 172.17.5.200:41587
I1107 19:36:43.059622 30666 master.cpp:369] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/dpiizb/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" --work_dir="/tmp/dpiizb/master" --zk_session_timeout="10secs"
I1107 19:36:43.060155 30666 master.cpp:414] Master only allowing authenticated frameworks to register
I1107 19:36:43.060170 30666 master.cpp:419] Master only allowing authenticated slaves to register
I1107 19:36:43.060180 30666 credentials.hpp:37] Loading credentials for authentication from '/tmp/dpiizb/credentials'
I1107 19:36:43.060549 30666 master.cpp:458] Using default 'crammd5' authenticator
I1107 19:36:43.060745 30666 master.cpp:495] Authorization enabled
I1107 19:36:43.061125 30658 hierarchical.cpp:140] Initialized hierarchical allocator process
I1107 19:36:43.062026 30667 whitelist_watcher.cpp:79] No whitelist given
I1107 19:36:43.064836 30666 master.cpp:1606] The newly elected leader is master@172.17.5.200:41587 with id 7d94c7fb-8950-4bcf-80c1-46112292dcd6
I1107 19:36:43.064914 30666 master.cpp:1619] Elected as the leading master!
I1107 19:36:43.064952 30666 master.cpp:1379] Recovering from registrar
I1107 19:36:43.065999 30655 registrar.cpp:309] Recovering registrar
I1107 19:36:43.067461 30662 log.cpp:661] Attempting to start the writer
I1107 19:36:43.069129 30662 replica.cpp:496] Replica received implicit promise request from (1368)@172.17.5.200:41587 with proposal 1
I1107 19:36:43.069782 30662 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 478241ns
I1107 19:36:43.069875 30662 replica.cpp:345] Persisted promised to 1
I1107 19:36:43.071180 30662 coordinator.cpp:240] Coordinator attempting to fill missing positions
I1107 19:36:43.073106 30653 replica.cpp:391] Replica received explicit promise request from (1369)@172.17.5.200:41587 for position 0 with proposal 2
I1107 19:36:43.073653 30653 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 423937ns
I1107 19:36:43.073767 30653 replica.cpp:715] Persisted action at 0
I1107 19:36:43.075337 30666 replica.cpp:540] Replica received write request for position 0 from (1370)@172.17.5.200:41587
I1107 19:36:43.075439 30666 leveldb.cpp:438] Reading position from leveldb took 43579ns
I1107 19:36:43.075965 30666 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 477770ns
I1107 19:36:43.075991 30666 replica.cpp:715] Persisted action at 0
I1107 19:36:43.076710 30653 replica.cpp:694] Replica received learned notice for position 0 from @0.0.0.0:0
I1107 19:36:43.077033 30653 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 280879ns
I1107 19:36:43.077060 30653 replica.cpp:715] Persisted action at 0
I1107 19:36:43.077082 30653 replica.cpp:700] Replica learned NOP action at position 0
I1107 19:36:43.078001 30658 log.cpp:677] Writer started with ending position 0
I1107 19:36:43.079610 30658 leveldb.cpp:438] Reading position from leveldb took 45406ns
I1107 19:36:43.081060 30667 registrar.cpp:342] Successfully fetched the registry (0B) in 14.972928ms
I1107 19:36:43.081240 30667 registrar.cpp:441] Applied 1 operations in 37217ns; attempting to update the 'registry'
I1107 19:36:43.082367 30658 log.cpp:685] Attempting to append 176 bytes to the log
I1107 19:36:43.082617 30658 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 1
I1107 19:36:43.083832 30660 replica.cpp:540] Replica received write request for position 1 from (1371)@172.17.5.200:41587
I1107 19:36:43.084390 30660 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 504329ns
I1107 19:36:43.084424 30660 replica.cpp:715] Persisted action at 1
I1107 19:36:43.085222 30665 replica.cpp:694] Replica received learned notice for position 1 from @0.0.0.0:0
I1107 19:36:43.085559 30665 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 301012ns
I1107 19:36:43.085587 30665 replica.cpp:715] Persisted action at 1
I1107 19:36:43.085609 30665 replica.cpp:700] Replica learned APPEND action at position 1
I1107 19:36:43.087128 30654 registrar.cpp:486] Successfully updated the 'registry' in 5.793024ms
I1107 19:36:43.087345 30654 registrar.cpp:372] Successfully recovered registrar
I1107 19:36:43.087410 30665 log.cpp:704] Attempting to truncate the log to 1
I1107 19:36:43.087622 30654 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 2
I1107 19:36:43.088613 30663 replica.cpp:540] Replica received write request for position 2 from (1372)@172.17.5.200:41587
I1107 19:36:43.089138 30665 master.cpp:1416] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
I1107 19:36:43.089423 30663 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 762056ns
I1107 19:36:43.089452 30663 replica.cpp:715] Persisted action at 2
I1107 19:36:43.090332 30657 replica.cpp:694] Replica received learned notice for position 2 from @0.0.0.0:0
I1107 19:36:43.091979 30657 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 1.608383ms
I1107 19:36:43.092072 30657 leveldb.cpp:401] Deleting ~1 keys from leveldb took 45369ns
I1107 19:36:43.092097 30657 replica.cpp:715] Persisted action at 2
I1107 19:36:43.092128 30657 replica.cpp:700] Replica learned TRUNCATE action at position 2
I1107 19:36:43.104477 30634 containerizer.cpp:142] Using isolation: posix/cpu,posix/mem,filesystem/posix
W1107 19:36:43.105070 30634 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
I1107 19:36:43.110745 30664 slave.cpp:191] Slave started on 45)@172.17.5.200:41587
I1107 19:36:43.110796 30664 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --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/FetcherCacheTest_SimpleEviction_ckaUz0/fetch" --fetcher_cache_size="90B" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.26.0/_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_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/FetcherCacheTest_SimpleEviction_ckaUz0"
I1107 19:36:43.111352 30664 credentials.hpp:85] Loading credential for authentication from '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/credential'
I1107 19:36:43.111619 30664 slave.cpp:322] Slave using credential for: test-principal
I1107 19:36:43.112309 30664 slave.cpp:392] Slave resources: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
I1107 19:36:43.112391 30664 slave.cpp:400] Slave attributes: [ ]
I1107 19:36:43.112407 30664 slave.cpp:405] Slave hostname: 095b2d77f516
I1107 19:36:43.112416 30664 slave.cpp:410] Slave checkpoint: true
I1107 19:36:43.114186 30658 state.cpp:54] Recovering state from '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta'
I1107 19:36:43.114631 30658 status_update_manager.cpp:202] Recovering status update manager
I1107 19:36:43.114820 30658 containerizer.cpp:384] Recovering containerizer
I1107 19:36:43.116094 30658 slave.cpp:4230] Finished recovery
I1107 19:36:43.116660 30658 slave.cpp:4387] Querying resource estimator for oversubscribable resources
I1107 19:36:43.117130 30668 slave.cpp:4401] Received oversubscribable resources from the resource estimator
I1107 19:36:43.117326 30668 slave.cpp:729] New master detected at master@172.17.5.200:41587
I1107 19:36:43.117369 30666 status_update_manager.cpp:176] Pausing sending status updates
I1107 19:36:43.117403 30668 slave.cpp:792] Authenticating with master master@172.17.5.200:41587
I1107 19:36:43.117424 30668 slave.cpp:797] Using default CRAM-MD5 authenticatee
I1107 19:36:43.117570 30668 slave.cpp:765] Detecting new master
I1107 19:36:43.117645 30666 authenticatee.cpp:123] Creating new client SASL connection
I1107 19:36:43.117900 30668 master.cpp:5150] Authenticating slave(45)@172.17.5.200:41587
I1107 19:36:43.118093 30666 authenticator.cpp:415] Starting authentication session for crammd5_authenticatee(135)@172.17.5.200:41587
I1107 19:36:43.118415 30668 authenticator.cpp:100] Creating new server SASL connection
I1107 19:36:43.118680 30666 authenticatee.cpp:214] Received SASL authentication mechanisms: CRAM-MD5
I1107 19:36:43.118724 30666 authenticatee.cpp:240] Attempting to authenticate with mechanism 'CRAM-MD5'
I1107 19:36:43.118827 30666 authenticator.cpp:205] Received SASL authentication start
I1107 19:36:43.118892 30666 authenticator.cpp:327] Authentication requires more steps
I1107 19:36:43.119011 30666 authenticatee.cpp:260] Received SASL authentication step
I1107 19:36:43.119160 30667 authenticator.cpp:233] Received SASL authentication step
I1107 19:36:43.119196 30667 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '095b2d77f516' server FQDN: '095b2d77f516' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1107 19:36:43.119211 30667 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1107 19:36:43.119256 30667 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1107 19:36:43.119284 30667 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '095b2d77f516' server FQDN: '095b2d77f516' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1107 19:36:43.119298 30667 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1107 19:36:43.119307 30667 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1107 19:36:43.119324 30667 authenticator.cpp:319] Authentication success
I1107 19:36:43.119484 30667 authenticatee.cpp:300] Authentication success
I1107 19:36:43.119577 30667 master.cpp:5180] Successfully authenticated principal 'test-principal' at slave(45)@172.17.5.200:41587
I1107 19:36:43.119654 30667 authenticator.cpp:433] Authentication session cleanup for crammd5_authenticatee(135)@172.17.5.200:41587
I1107 19:36:43.119941 30667 slave.cpp:860] Successfully authenticated with master master@172.17.5.200:41587
I1107 19:36:43.120070 30667 slave.cpp:1254] Will retry registration in 16.796993ms if necessary
I1107 19:36:43.120344 30667 master.cpp:3859] Registering slave at slave(45)@172.17.5.200:41587 (095b2d77f516) with id 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:43.120836 30667 registrar.cpp:441] Applied 1 operations in 66680ns; attempting to update the 'registry'
I1107 19:36:43.122225 30667 log.cpp:685] Attempting to append 345 bytes to the log
I1107 19:36:43.122350 30663 coordinator.cpp:350] Coordinator attempting to write APPEND action at position 3
I1107 19:36:43.123267 30659 replica.cpp:540] Replica received write request for position 3 from (1385)@172.17.5.200:41587
I1107 19:36:43.123852 30659 leveldb.cpp:343] Persisting action (364 bytes) to leveldb took 543159ns
I1107 19:36:43.123878 30659 replica.cpp:715] Persisted action at 3
I1107 19:36:43.124594 30659 replica.cpp:694] Replica received learned notice for position 3 from @0.0.0.0:0
I1107 19:36:43.124948 30659 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 321897ns
I1107 19:36:43.124974 30659 replica.cpp:715] Persisted action at 3
I1107 19:36:43.124994 30659 replica.cpp:700] Replica learned APPEND action at position 3
I1107 19:36:43.126334 30663 registrar.cpp:486] Successfully updated the 'registry' in 5.434112ms
I1107 19:36:43.126546 30653 log.cpp:704] Attempting to truncate the log to 3
I1107 19:36:43.126694 30653 coordinator.cpp:350] Coordinator attempting to write TRUNCATE action at position 4
I1107 19:36:43.127226 30653 slave.cpp:3169] Received ping from slave-observer(44)@172.17.5.200:41587
I1107 19:36:43.127224 30663 master.cpp:3927] Registered slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
I1107 19:36:43.127470 30653 slave.cpp:904] Registered with master master@172.17.5.200:41587; given slave ID 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:43.127490 30653 fetcher.cpp:79] Clearing fetcher cache
I1107 19:36:43.127831 30663 status_update_manager.cpp:183] Resuming sending status updates
I1107 19:36:43.127837 30653 slave.cpp:927] Checkpointing SlaveInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/slave.info'
I1107 19:36:43.128013 30663 replica.cpp:540] Replica received write request for position 4 from (1386)@172.17.5.200:41587
I1107 19:36:43.128201 30653 slave.cpp:963] Forwarding total oversubscribed resources
I1107 19:36:43.128291 30654 hierarchical.cpp:335] Added slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 (095b2d77f516) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
I1107 19:36:43.128324 30653 master.cpp:4269] Received update of slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516) with total oversubscribed resources
I1107 19:36:43.128481 30654 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:43.128523 30654 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:43.128545 30654 hierarchical.cpp:867] Performed allocation for slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 in 219926ns
I1107 19:36:43.128563 30663 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 520183ns
I1107 19:36:43.128584 30663 replica.cpp:715] Persisted action at 4
I1107 19:36:43.128764 30654 hierarchical.cpp:391] Slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 (095b2d77f516) updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
I1107 19:36:43.128907 30654 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:43.128953 30654 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:43.128973 30654 hierarchical.cpp:867] Performed allocation for slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 in 176271ns
I1107 19:36:43.129747 30634 sched.cpp:166] Version: 0.26.0
I1107 19:36:43.131237 30661 replica.cpp:694] Replica received learned notice for position 4 from @0.0.0.0:0
I1107 19:36:43.131543 30664 sched.cpp:264] New master detected at master@172.17.5.200:41587
I1107 19:36:43.131642 30664 sched.cpp:320] Authenticating with master master@172.17.5.200:41587
I1107 19:36:43.131662 30664 sched.cpp:327] Using default CRAM-MD5 authenticatee
I1107 19:36:43.131695 30661 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 402326ns
I1107 19:36:43.131767 30661 leveldb.cpp:401] Deleting ~2 keys from leveldb took 45881ns
I1107 19:36:43.131793 30661 replica.cpp:715] Persisted action at 4
I1107 19:36:43.131826 30661 replica.cpp:700] Replica learned TRUNCATE action at position 4
I1107 19:36:43.131922 30660 authenticatee.cpp:123] Creating new client SASL connection
I1107 19:36:43.132253 30659 master.cpp:5150] Authenticating scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:43.132385 30660 authenticator.cpp:415] Starting authentication session for crammd5_authenticatee(136)@172.17.5.200:41587
I1107 19:36:43.132591 30659 authenticator.cpp:100] Creating new server SASL connection
I1107 19:36:43.132998 30653 authenticatee.cpp:214] Received SASL authentication mechanisms: CRAM-MD5
I1107 19:36:43.133031 30653 authenticatee.cpp:240] Attempting to authenticate with mechanism 'CRAM-MD5'
I1107 19:36:43.133180 30653 authenticator.cpp:205] Received SASL authentication start
I1107 19:36:43.133244 30653 authenticator.cpp:327] Authentication requires more steps
I1107 19:36:43.133345 30655 authenticatee.cpp:260] Received SASL authentication step
I1107 19:36:43.133455 30655 authenticator.cpp:233] Received SASL authentication step
I1107 19:36:43.133488 30655 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '095b2d77f516' server FQDN: '095b2d77f516' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1107 19:36:43.133502 30655 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I1107 19:36:43.133544 30655 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1107 19:36:43.133570 30655 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: '095b2d77f516' server FQDN: '095b2d77f516' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1107 19:36:43.133582 30655 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1107 19:36:43.133589 30655 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1107 19:36:43.133607 30655 authenticator.cpp:319] Authentication success
I1107 19:36:43.133713 30664 authenticatee.cpp:300] Authentication success
I1107 19:36:43.133744 30653 master.cpp:5180] Successfully authenticated principal 'test-principal' at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:43.133798 30654 authenticator.cpp:433] Authentication session cleanup for crammd5_authenticatee(136)@172.17.5.200:41587
I1107 19:36:43.134109 30667 sched.cpp:409] Successfully authenticated with master master@172.17.5.200:41587
I1107 19:36:43.134130 30667 sched.cpp:716] Sending SUBSCRIBE call to master@172.17.5.200:41587
I1107 19:36:43.134232 30667 sched.cpp:749] Will retry registration in 496.90906ms if necessary
I1107 19:36:43.134399 30662 master.cpp:2176] Received SUBSCRIBE call for framework 'default' at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
W1107 19:36:43.134435 30662 master.cpp:2183] Framework at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
I1107 19:36:43.134490 30662 master.cpp:1645] Authorizing framework principal '' to receive offers for role '*'
I1107 19:36:43.134762 30662 master.cpp:2247] Subscribing framework default with checkpointing enabled and capabilities [ ]
I1107 19:36:43.135298 30656 hierarchical.cpp:185] Added framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.135363 30662 sched.cpp:643] Framework registered with 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.135409 30662 sched.cpp:657] Scheduler::registered took 19956ns
I1107 19:36:43.136091 30656 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:43.136137 30656 hierarchical.cpp:851] Performed allocation for 1 slaves in 802971ns
I1107 19:36:43.136525 30663 master.cpp:4979] Sending 1 offers to framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:43.137083 30656 sched.cpp:813] Scheduler::resourceOffers took 153895ns
I1107 19:36:43.138983 30656 master.cpp:2915] Processing ACCEPT call for offers: [ 7d94c7fb-8950-4bcf-80c1-46112292dcd6-O0 ] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516) for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:43.139045 30656 master.cpp:2711] Authorizing framework principal '' to launch task 0 as user 'mesos'
I1107 19:36:43.140442 30656 master.hpp:176] Adding task 0 with resources cpus(*):1; mem(*):1 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 (095b2d77f516)
I1107 19:36:43.140554 30656 master.cpp:3245] Launching task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 with resources cpus(*):1; mem(*):1 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:43.140864 30668 slave.cpp:1294] Got assigned task 0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.141059 30668 slave.cpp:4920] Checkpointing FrameworkInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/framework.info'
I1107 19:36:43.141273 30656 hierarchical.cpp:739] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.141348 30656 hierarchical.cpp:776] Framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 filtered slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for 5secs
I1107 19:36:43.141613 30668 slave.cpp:4931] Checkpointing framework pid 'scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587' to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/framework.pid'
I1107 19:36:43.142480 30668 slave.cpp:1410] Launching task 0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.143267 30668 paths.cpp:417] Trying to chown '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49' to user 'mesos'
I1107 19:36:43.151273 30668 slave.cpp:5360] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/executor.info'
I1107 19:36:43.152088 30668 slave.cpp:4999] Launching executor 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49'
I1107 19:36:43.152746 30660 containerizer.cpp:618] Starting container 'd2a0999a-4e4a-45c5-a1ef-a75535eb4f49' for executor '0' of framework '7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000'
I1107 19:36:43.152895 30668 slave.cpp:5383] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49/tasks/0/task.info'
I1107 19:36:43.153411 30668 slave.cpp:1628] Queuing task '0' for executor ''0' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000'
I1107 19:36:43.153612 30668 slave.cpp:682] Successfully attached file '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49'
I1107 19:36:43.156604 30653 launcher.cpp:134] Forked child with pid '989' for container 'd2a0999a-4e4a-45c5-a1ef-a75535eb4f49'
I1107 19:36:43.156869 30653 containerizer.cpp:851] Checkpointing executor's forked pid 989 to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49/pids/forked.pid'
I1107 19:36:43.159538 30663 fetcher.cpp:301] Starting to fetch URIs for container: d2a0999a-4e4a-45c5-a1ef-a75535eb4f49, directory: /tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49
I1107 19:36:43.165120 30663 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd0' with file: c1-cmd0
I1107 19:36:43.166404 30655 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd0
I1107 19:36:43.170043 30663 fetcher.cpp:665] Claiming fetcher cache space for: mesos@/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd0
I1107 19:36:43.170192 30663 fetcher.cpp:1110] Claimed cache space: 30B, now using: 30B
I1107 19:36:43.182997 30663 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
I1107 19:36:43.319833 30668 fetcher.cpp:1122] Released cache space: 0B, now using: 30B
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1107 19:36:43.418843 989 process.cpp:965] libprocess is initialized on 172.17.5.200:39128 for 16 cpus
I1107 19:36:43.419946 989 logging.cpp:177] Logging to STDERR
I1107 19:36:43.422473 989 exec.cpp:136] Version: 0.26.0
I1107 19:36:43.436002 1044 exec.cpp:186] Executor started at: executor(1)@172.17.5.200:39128 with pid 989
I1107 19:36:43.439517 30668 slave.cpp:2405] Got registration for executor '0' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:39128
I1107 19:36:43.439682 30668 slave.cpp:2490] Checkpointing executor pid 'executor(1)@172.17.5.200:39128' to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49/pids/libprocess.pid'
I1107 19:36:43.443613 30660 slave.cpp:1793] Sending queued task '0' to executor ''0' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 at executor(1)@172.17.5.200:39128'
I1107 19:36:43.445300 1046 exec.cpp:210] Executor registered on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:43.449869 1046 exec.cpp:222] Executor::registered took 441794ns
I1107 19:36:43.450309 1046 exec.cpp:297] Executor asked to run task '0'
I1107 19:36:43.450423 1046 exec.cpp:306] Executor::launchTask took 86123ns
Registered executor on 095b2d77f516
Starting task 0
sh -c './cmd0 0'
Forked command at 1052
I1107 19:36:43.465239 1048 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.467710 30668 slave.cpp:2762] Handling status update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:39128
I1107 19:36:43.468336 30666 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.468389 30666 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.469044 30666 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.470412 30666 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to the slave
I1107 19:36:43.471180 30668 slave.cpp:3087] Forwarding the update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to master@172.17.5.200:41587
I1107 19:36:43.471391 30668 slave.cpp:3005] Status update manager successfully handled status update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.471431 30668 slave.cpp:3011] Sending acknowledgement for status update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to executor(1)@172.17.5.200:39128
I1107 19:36:43.471897 30660 master.cpp:4414] Status update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:43.472090 30660 master.cpp:4462] Forwarding status update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.472484 30660 master.cpp:6066] Updating the state of task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1107 19:36:43.472852 30655 sched.cpp:921] Scheduler::statusUpdate took 200832ns
I1107 19:36:43.473162 30660 master.cpp:3571] Processing ACKNOWLEDGE call 3275989f-6697-4bf9-a403-8cb0b0dac98f for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:43.473502 30660 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.473660 30660 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.474750 30660 slave.cpp:2345] Status update manager successfully handled status update acknowledgement (UUID: 3275989f-6697-4bf9-a403-8cb0b0dac98f) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.475124 1046 exec.cpp:343] Executor received status update acknowledgement 3275989f-6697-4bf9-a403-8cb0b0dac98f for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
Command exited with status 0 (pid: 1052)
I1107 19:36:43.567967 1037 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.569074 30655 slave.cpp:2762] Handling status update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:39128
I1107 19:36:43.569306 30655 slave.cpp:5298] Terminating task 0
I1107 19:36:43.571573 30660 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.571643 30660 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.572872 30660 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to the slave
I1107 19:36:43.573335 30660 slave.cpp:3087] Forwarding the update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to master@172.17.5.200:41587
I1107 19:36:43.573489 30660 slave.cpp:3005] Status update manager successfully handled status update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.573523 30660 slave.cpp:3011] Sending acknowledgement for status update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to executor(1)@172.17.5.200:39128
I1107 19:36:43.574225 30660 master.cpp:4414] Status update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:43.574268 30660 master.cpp:4462] Forwarding status update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.574424 30660 master.cpp:6066] Updating the state of task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
II1107 19:36:43.575372 30658 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.575917 30660 sched.cpp:921] Scheduler::statusUpdate took 1.125629ms
I1107 19:36:43.576342 30654 master.cpp:3571] Processing ACKNOWLEDGE call d5cc0471-27e2-47aa-b1dd-2743f0391121 for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:43.576494 30654 master.cpp:6132] Removing task 0 with resources cpus(*):1; mem(*):1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:43.577185 30654 status_update_manager.cpp:394] Received status update acknowledgement (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.577443 30654 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FINISHED (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
1107 19:36:43.575441 1037 exec.cpp:343] Executor received status update acknowledgement d5cc0471-27e2-47aa-b1dd-2743f0391121 for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.578343 30654 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.578773 30654 slave.cpp:2345] Status update manager successfully handled status update acknowledgement (UUID: d5cc0471-27e2-47aa-b1dd-2743f0391121) for task 0 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:43.578817 30654 slave.cpp:5339] Completing task 0
I1107 19:36:44.063208 30664 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:44.063308 30664 hierarchical.cpp:851] Performed allocation for 1 slaves in 1.169904ms
I1107 19:36:44.063901 30664 master.cpp:4979] Sending 1 offers to framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:44.064527 30664 sched.cpp:813] Scheduler::resourceOffers took 151445ns
I1107 19:36:44.066936 30664 master.cpp:2915] Processing ACCEPT call for offers: [ 7d94c7fb-8950-4bcf-80c1-46112292dcd6-O1 ] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516) for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:44.067023 30664 master.cpp:2711] Authorizing framework principal '' to launch task 1 as user 'mesos'
I1107 19:36:44.069103 30664 master.hpp:176] Adding task 1 with resources cpus(*):1; mem(*):1 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 (095b2d77f516)
I1107 19:36:44.069250 30664 master.cpp:3245] Launching task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 with resources cpus(*):1; mem(*):1 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:44.069703 30667 slave.cpp:1294] Got assigned task 1 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.070060 30664 hierarchical.cpp:739] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.070137 30664 hierarchical.cpp:776] Framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 filtered slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for 5secs
I1107 19:36:44.070557 30667 slave.cpp:1410] Launching task 1 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.071336 30667 paths.cpp:417] Trying to chown '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d' to user 'mesos'
I1107 19:36:44.080117 30667 slave.cpp:5360] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/executor.info'
I1107 19:36:44.081410 30667 slave.cpp:4999] Launching executor 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d'
I1107 19:36:44.082427 30653 containerizer.cpp:618] Starting container '91a41a5f-b53e-4b80-93ca-d5aa9789e49d' for executor '1' of framework '7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000'
I1107 19:36:44.089359 30653 launcher.cpp:134] Forked child with pid '1055' for container '91a41a5f-b53e-4b80-93ca-d5aa9789e49d'
I1107 19:36:44.090152 30653 containerizer.cpp:851] Checkpointing executor's forked pid 1055 to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d/pids/forked.pid'
I1107 19:36:44.092819 30667 slave.cpp:5383] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d/tasks/1/task.info'
I1107 19:36:44.093750 30658 fetcher.cpp:301] Starting to fetch URIs for container: 91a41a5f-b53e-4b80-93ca-d5aa9789e49d, directory: /tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d
I1107 19:36:44.095595 30667 slave.cpp:1628] Queuing task '1' for executor ''1' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000'
I1107 19:36:44.095862 30667 slave.cpp:682] Successfully attached file '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d'
I1107 19:36:44.100383 30658 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd1' with file: c2-cmd1
I1107 19:36:44.101696 30656 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd1
I1107 19:36:44.104075 30658 fetcher.cpp:665] Claiming fetcher cache space for: mesos@/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd1
I1107 19:36:44.104116 30658 fetcher.cpp:1110] Claimed cache space: 30B, now using: 60B
I1107 19:36:44.110196 30656 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
I1107 19:36:44.228247 30668 fetcher.cpp:1122] Released cache space: 0B, now using: 60B
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1107 19:36:44.324614 1055 process.cpp:965] libprocess is initialized on 172.17.5.200:39936 for 16 cpus
I1107 19:36:44.325397 1055 logging.cpp:177] Logging to STDERR
I1107 19:36:44.328882 1055 exec.cpp:136] Version: 0.26.0
I1107 19:36:44.340692 1103 exec.cpp:186] Executor started at: executor(1)@172.17.5.200:39936 with pid 1055
I1107 19:36:44.344118 30654 slave.cpp:2405] Got registration for executor '1' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:39936
I1107 19:36:44.344275 30654 slave.cpp:2490] Checkpointing executor pid 'executor(1)@172.17.5.200:39936' to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d/pids/libprocess.pid'
I1107 19:36:44.347863 30655 slave.cpp:1793] Sending queued task '1' to executor ''1' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 at executor(1)@172.17.5.200:39936'
I1107 19:36:44.348451 1104 exec.cpp:210] Executor registered on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:44.350980 1104 exec.cpp:222] Executor::registered took 426873ns
I1107 19:36:44.351419 1104 exec.cpp:297] Executor asked to run task '1'
I1107 19:36:44.351526 1104 exec.cpp:306] Executor::launchTask took 79061ns
Registered executor on 095b2d77f516
Starting task 1
Forked command at 1118
I1107 19:36:44.358775 1108 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
sh -c './cmd1 1'
I1107 19:36:44.361147 30655 slave.cpp:2762] Handling status update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:39936
I1107 19:36:44.361663 30655 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.361703 30655 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.362545 30655 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.364029 30655 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to the slave
I1107 19:36:44.364349 30656 slave.cpp:3087] Forwarding the update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to master@172.17.5.200:41587
I1107 19:36:44.364680 30656 master.cpp:4414] Status update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:44.364720 30656 master.cpp:4462] Forwarding status update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.364881 30656 master.cpp:6066] Updating the state of task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1107 19:36:44.365459 30656 sched.cpp:921] Scheduler::statusUpdate took 160578ns
I1107 19:36:44.365841 30656 master.cpp:3571] Processing ACKNOWLEDGE call a08cbee6-2600-464d-a623-505f4bbe0917 for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:44.366561 30662 slave.cpp:3005] Status update manager successfully handled status update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.366610 30662 slave.cpp:3011] Sending acknowledgement for status update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to executor(1)@172.17.5.200:39936
I1107 19:36:44.366561 30655 status_update_manager.cpp:394] Received status update acknowledgement (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.367118 30655 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.368137 30655 slave.cpp:2345] Status update manager successfully handled status update acknowledgement (UUID: a08cbee6-2600-464d-a623-505f4bbe0917) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.368320 1112 exec.cpp:343] Executor received status update acknowledgement a08cbee6-2600-464d-a623-505f4bbe0917 for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
Command exited with status 0 (pid: 1118)
I1107 19:36:44.459184 1113 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.460513 30657 slave.cpp:2762] Handling status update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:39936
I1107 19:36:44.460739 30657 slave.cpp:5298] Terminating task 1
I1107 19:36:44.462074 30666 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.462155 30666 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.463040 30666 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to the slave
I1107 19:36:44.463302 30657 slave.cpp:3087] Forwarding the update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to master@172.17.5.200:41587
I1107 19:36:44.463495 30657 slave.cpp:3005] Status update manager successfully handled status update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.463531 30657 slave.cpp:3011] Sending acknowledgement for status update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to executor(1)@172.17.5.200:39936
I1107 19:36:44.463620 30666 master.cpp:4414] Status update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:44.463663 30666 master.cpp:4462] Forwarding status update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.463840 30666 master.cpp:6066] Updating the state of task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
I1107 19:36:44.464337 30657 sched.cpp:921] Scheduler::statusUpdate took 187859ns
I1107 19:36:44.464371 30666 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.464584 30657 master.cpp:3571] Processing ACKNOWLEDGE call 40fd2aa3-7d39-47b2-afc1-9f492632f7d8 for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:44.464648 30657 master.cpp:6132] Removing task 1 with resources cpus(*):1; mem(*):1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:44.465107 30657 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.465260 30657 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FINISHED (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.465626 1115 exec.cpp:343] Executor received status update acknowledgement 40fd2aa3-7d39-47b2-afc1-9f492632f7d8 for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.466136 30657 status_update_manager.cpp:530] Cleaning up status update stream for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.466526 30667 slave.cpp:2345] Status update manager successfully handled status update acknowledgement (UUID: 40fd2aa3-7d39-47b2-afc1-9f492632f7d8) for task 1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:44.466611 30667 slave.cpp:5339] Completing task 1
I1107 19:36:44.632086 30664 containerizer.cpp:1257] Executor for container 'd2a0999a-4e4a-45c5-a1ef-a75535eb4f49' has exited
I1107 19:36:44.632154 30664 containerizer.cpp:1074] Destroying container 'd2a0999a-4e4a-45c5-a1ef-a75535eb4f49'
I1107 19:36:44.637640 30664 slave.cpp:3553] Executor '0' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 exited with status 0
I1107 19:36:44.637761 30664 slave.cpp:3657] Cleaning up executor '0' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 at executor(1)@172.17.5.200:39128
I1107 19:36:44.638382 30662 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49' for gc 6.99999261318222days in the future
I1107 19:36:44.638873 30663 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0' for gc 6.99999260796148days in the future
I1107 19:36:44.639230 30653 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49' for gc 6.99999260360889days in the future
I1107 19:36:44.639551 30661 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0' for gc 6.99999259974815days in the future
I1107 19:36:45.065361 30667 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:45.065441 30667 hierarchical.cpp:851] Performed allocation for 1 slaves in 999013ns
I1107 19:36:45.065940 30667 master.cpp:4979] Sending 1 offers to framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:45.066483 30667 sched.cpp:813] Scheduler::resourceOffers took 126707ns
I1107 19:36:45.068840 30667 master.cpp:2915] Processing ACCEPT call for offers: [ 7d94c7fb-8950-4bcf-80c1-46112292dcd6-O2 ] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516) for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:45.068938 30667 master.cpp:2711] Authorizing framework principal '' to launch task 2 as user 'mesos'
I1107 19:36:45.071200 30667 master.hpp:176] Adding task 2 with resources cpus(*):1; mem(*):1 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 (095b2d77f516)
I1107 19:36:45.071346 30667 master.cpp:3245] Launching task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 with resources cpus(*):1; mem(*):1 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:45.071820 30660 slave.cpp:1294] Got assigned task 2 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.072638 30667 hierarchical.cpp:739] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.072846 30667 hierarchical.cpp:776] Framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 filtered slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for 5secs
I1107 19:36:45.072867 30660 slave.cpp:1410] Launching task 2 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.073788 30660 paths.cpp:417] Trying to chown '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854' to user 'mesos'
I1107 19:36:45.080005 30660 slave.cpp:5360] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/executor.info'
I1107 19:36:45.080965 30660 slave.cpp:4999] Launching executor 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854'
I1107 19:36:45.081532 30656 containerizer.cpp:618] Starting container '6553a617-6b4a-418d-9759-5681f45ff854' for executor '2' of framework '7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000'
I1107 19:36:45.081714 30660 slave.cpp:5383] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854/tasks/2/task.info'
I1107 19:36:45.082206 30660 slave.cpp:1628] Queuing task '2' for executor ''2' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000'
I1107 19:36:45.082336 30660 slave.cpp:682] Successfully attached file '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854'
I1107 19:36:45.085137 30656 launcher.cpp:134] Forked child with pid '1121' for container '6553a617-6b4a-418d-9759-5681f45ff854'
I1107 19:36:45.085301 30656 containerizer.cpp:851] Checkpointing executor's forked pid 1121 to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854/pids/forked.pid'
I1107 19:36:45.087652 30667 fetcher.cpp:301] Starting to fetch URIs for container: 6553a617-6b4a-418d-9759-5681f45ff854, directory: /tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854
I1107 19:36:45.094226 30667 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd2' with file: c3-cmd2
I1107 19:36:45.096156 30661 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd2
I1107 19:36:45.098718 30667 fetcher.cpp:665] Claiming fetcher cache space for: mesos@/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd2
I1107 19:36:45.098835 30667 fetcher.cpp:1110] Claimed cache space: 30B, now using: 90B
I1107 19:36:45.107599 30667 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
I1107 19:36:45.238361 30657 fetcher.cpp:1122] Released cache space: 0B, now using: 90B
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1107 19:36:45.315680 1121 process.cpp:965] libprocess is initialized on 172.17.5.200:55861 for 16 cpus
I1107 19:36:45.329735 1121 logging.cpp:177] Logging to STDERR
I1107 19:36:45.332973 1121 exec.cpp:136] Version: 0.26.0
I1107 19:36:45.334202 1170 exec.cpp:186] Executor started at: executor(1)@172.17.5.200:55861 with pid 1121
I1107 19:36:45.337172 30657 slave.cpp:2405] Got registration for executor '2' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:55861
I1107 19:36:45.337662 30657 slave.cpp:2490] Checkpointing executor pid 'executor(1)@172.17.5.200:55861' to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854/pids/libprocess.pid'
I1107 19:36:45.340437 30668 slave.cpp:1793] Sending queued task '2' to executor ''2' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 at executor(1)@172.17.5.200:55861'
I1107 19:36:45.343097 1177 exec.cpp:210] Executor registered on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
Registered executor on 095b2d77f516
I1107 19:36:45.355082 1177 exec.cpp:222] Executor::registered took 9.799009ms
I1107 19:36:45.355692 1177 exec.cpp:297] Executor asked to run task '2'
IStarting task 2
1107 19:36:45.355882 1177 exec.cpp:306] Executor::launchTask took 106726ns
Forked command at 1184
sh -c './cmd2 2'
I1107 19:36:45.361232 1173 exec.cpp:519] Executor sending status update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.363498 30662 slave.cpp:2762] Handling status update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:55861
I1107 19:36:45.364037 30662 status_update_manager.cpp:322] Received status update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.364079 30662 status_update_manager.cpp:499] Creating StatusUpdate stream for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.364655 30662 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.365856 30662 status_update_manager.cpp:376] Forwarding update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to the slave
I1107 19:36:45.366300 30662 slave.cpp:3087] Forwarding the update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to master@172.17.5.200:41587
I1107 19:36:45.366464 30662 slave.cpp:3005] Status update manager successfully handled status update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.366499 30662 slave.cpp:3011] Sending acknowledgement for status update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to executor(1)@172.17.5.200:55861
I1107 19:36:45.366698 30668 master.cpp:4414] Status update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:45.366745 30668 master.cpp:4462] Forwarding status update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.366917 30668 master.cpp:6066] Updating the state of task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
I1107 19:36:45.367224 30662 sched.cpp:921] Scheduler::statusUpdate took 152941ns
I1107 19:36:45.367471 30662 master.cpp:3571] Processing ACKNOWLEDGE call e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4 for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:45.367759 30662 status_update_manager.cpp:394] Received status update acknowledgement (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.367887 30662 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_RUNNING (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.368746 30662 slave.cpp:2345] Status update manager successfully handled status update acknowledgement (UUID: e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.369518 1168 exec.cpp:343] Executor received status update acknowledgement e4a7fbac-a6ac-4fba-aefa-78ec39a5f8c4 for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
Command exited with status 0 (pid: 1184)
I1107 19:36:45.463112 1180 exec.cpp:519] Executor sending status update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.465121 30662 slave.cpp:2762] Handling status update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:55861
I1107 19:36:45.465328 30662 slave.cpp:5298] Terminating task 2
I1107 19:36:45.467548 30662 status_update_manager.cpp:322] Received status update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.467617 30662 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.471096 30662 status_update_manager.cpp:376] Forwarding update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to the slave
I1107 19:36:45.471540 30662 slave.cpp:3087] Forwarding the update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to master@172.17.5.200:41587
I1107 19:36:45.471689 30662 slave.cpp:3005] Status update manager successfully handled status update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.471720 30662 slave.cpp:3011] Sending acknowledgement for status update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to executor(1)@172.17.5.200:55861
I1107 19:36:45.472199 30655 master.cpp:4414] Status update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:45.472254 30655 master.cpp:4462] Forwarding status update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.472416 30655 master.cpp:6066] Updating the state of task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (latest state: TASK_FINISHED, status update state: TASK_FINISHED)
I1107 19:36:45.473271 30667 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.473634 30653 sched.cpp:921] Scheduler::statusUpdate took 771310ns
I1107 19:36:45.473877 30653 master.cpp:3571] Processing ACKNOWLEDGE call 82fc89e3-f919-484c-9a06-bb75ccd20d35 for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:45.473944 30653 master.cpp:6132] Removing task 2 with resources cpus(*):1; mem(*):1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:45.477097 30665 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.477174 1178 exec.cpp:343] Executor received status update acknowledgement 82fc89e3-f919-484c-9a06-bb75ccd20d35 for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.477403 30665 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FINISHED (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.480686 30665 status_update_manager.cpp:530] Cleaning up status update stream for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.481199 30665 slave.cpp:2345] Status update manager successfully handled status update acknowledgement (UUID: 82fc89e3-f919-484c-9a06-bb75ccd20d35) for task 2 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:45.481264 30665 slave.cpp:5339] Completing task 2
I1107 19:36:45.540711 30663 containerizer.cpp:1257] Executor for container '91a41a5f-b53e-4b80-93ca-d5aa9789e49d' has exited
I1107 19:36:45.540778 30663 containerizer.cpp:1074] Destroying container '91a41a5f-b53e-4b80-93ca-d5aa9789e49d'
I1107 19:36:45.545699 30660 slave.cpp:3553] Executor '1' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 exited with status 0
I1107 19:36:45.545831 30660 slave.cpp:3657] Cleaning up executor '1' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 at executor(1)@172.17.5.200:39936
I1107 19:36:45.546818 30660 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d' for gc 6.9999936764237days in the future
I1107 19:36:45.547041 30660 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1' for gc 6.99999367446815days in the future
I1107 19:36:45.547189 30660 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d' for gc 6.99999367326518days in the future
I1107 19:36:45.547355 30660 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1' for gc 6.99999367229037days in the future
I1107 19:36:46.067595 30665 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:46.067673 30665 hierarchical.cpp:851] Performed allocation for 1 slaves in 1.151544ms
I1107 19:36:46.068194 30665 master.cpp:4979] Sending 1 offers to framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:46.068734 30665 sched.cpp:813] Scheduler::resourceOffers took 117496ns
I1107 19:36:46.070858 30665 master.cpp:2915] Processing ACCEPT call for offers: [ 7d94c7fb-8950-4bcf-80c1-46112292dcd6-O3 ] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516) for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:46.070921 30665 master.cpp:2711] Authorizing framework principal '' to launch task 3 as user 'mesos'
I1107 19:36:46.072576 30665 master.hpp:176] Adding task 3 with resources cpus(*):1; mem(*):1 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 (095b2d77f516)
I1107 19:36:46.072676 30665 master.cpp:3245] Launching task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 with resources cpus(*):1; mem(*):1 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:46.073215 30655 slave.cpp:1294] Got assigned task 3 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.073423 30657 hierarchical.cpp:739] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.073489 30657 hierarchical.cpp:776] Framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 filtered slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for 5secs
I1107 19:36:46.073951 30655 slave.cpp:1410] Launching task 3 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.074681 30655 paths.cpp:417] Trying to chown '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873' to user 'mesos'
I1107 19:36:46.081043 30655 slave.cpp:5360] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/executor.info'
I1107 19:36:46.081836 30655 slave.cpp:4999] Launching executor 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873'
I1107 19:36:46.082309 30666 containerizer.cpp:618] Starting container 'd2c1f924-c92a-453e-82b1-c294d09c4873' for executor '3' of framework '7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000'
I1107 19:36:46.082411 30655 slave.cpp:5383] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873/tasks/3/task.info'
I1107 19:36:46.082850 30655 slave.cpp:1628] Queuing task '3' for executor ''3' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000'
I1107 19:36:46.083267 30655 slave.cpp:682] Successfully attached file '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873'
I1107 19:36:46.086489 30664 launcher.cpp:134] Forked child with pid '1187' for container 'd2c1f924-c92a-453e-82b1-c294d09c4873'
I1107 19:36:46.086634 30664 containerizer.cpp:851] Checkpointing executor's forked pid 1187 to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873/pids/forked.pid'
I1107 19:36:46.089447 30668 fetcher.cpp:301] Starting to fetch URIs for container: d2c1f924-c92a-453e-82b1-c294d09c4873, directory: /tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873
I1107 19:36:46.097071 30668 fetcher.cpp:890] Created cache entry 'mesos@/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd3' with file: c4-cmd3
I1107 19:36:46.098377 30661 fetcher.cpp:250] Fetching size for URI: /tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd3
I1107 19:36:46.100539 30668 fetcher.cpp:1031] Freeing up fetcher cache space for: 30B
I1107 19:36:46.100831 30668 fetcher.cpp:967] Removing cache entry 'mesos@/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd0' with filename: c1-cmd0
I1107 19:36:46.101053 30668 fetcher.cpp:1122] Released cache space: 30B, now using: 60B
I1107 19:36:46.101141 30668 fetcher.cpp:665] Claiming fetcher cache space for: mesos@/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd3
I1107 19:36:46.101232 30668 fetcher.cpp:1110] Claimed cache space: 30B, now using: 90B
I1107 19:36:46.121825 30668 fetcher.cpp:758] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
I1107 19:36:46.247297 30657 fetcher.cpp:1122] Released cache space: 0B, now using: 90B
WARNING: Logging before InitGoogleLogging() is written to STDERR
I1107 19:36:46.337827 1187 process.cpp:965] libprocess is initialized on 172.17.5.200:33871 for 16 cpus
I1107 19:36:46.338824 1187 logging.cpp:177] Logging to STDERR
I1107 19:36:46.350026 1187 exec.cpp:136] Version: 0.26.0
I1107 19:36:46.353343 1235 exec.cpp:186] Executor started at: executor(1)@172.17.5.200:33871 with pid 1187
I1107 19:36:46.356576 30657 slave.cpp:2405] Got registration for executor '3' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from executor(1)@172.17.5.200:33871
I1107 19:36:46.357162 30657 slave.cpp:2490] Checkpointing executor pid 'executor(1)@172.17.5.200:33871' to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873/pids/libprocess.pid'
I1107 19:36:46.360908 30657 slave.cpp:1793] Sending queued task '3' to executor ''3' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 at executor(1)@172.17.5.200:33871'
I1107 19:36:46.363682 1236 exec.cpp:297] Executor asked to run task '3'
IStarting task 3
1107 19:36:46.363988 1236 exec.cpp:306] Executor::launchTask took 153278ns
F1107 19:36:46.364225 1237 executor.cpp:184] CHECK_SOME(executorInfo): is NONE
*** Check failure stack trace: ***
I1107 19:36:46.373569 1245 exec.cpp:210] Executor registered on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
@ 0x7f9f5a7db3fa google::LogMessage::Fail()
I1107 19:36:46.394081 1245 exec.cpp:222] Executor::registered took 395411ns
@ 0x7f9f5a7db359 google::LogMessage::SendToLog()
@ 0x7f9f5a7dad6a google::LogMessage::Flush()
@ 0x7f9f5a7dda9e google::LogMessageFatal::~LogMessageFatal()
@ 0x48d00a _CheckFatal::~_CheckFatal()
@ 0x49c99d mesos::internal::CommandExecutorProcess::launchTask()
@ 0x4b3dd7 _ZZN7process8dispatchIN5mesos8internal22CommandExecutorProcessEPNS1_14ExecutorDriverERKNS1_8TaskInfoES5_S6_EEvRKNS_3PIDIT_EEMSA_FvT0_T1_ET2_T3_ENKUlPNS_11ProcessBaseEE_clESL_
@ 0x4c470c _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchIN5mesos8internal22CommandExecutorProcessEPNS5_14ExecutorDriverERKNS5_8TaskInfoES9_SA_EEvRKNS0_3PIDIT_EEMSE_FvT0_T1_ET2_T3_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_
@ 0x7f9f5a761b1b std::function<>::operator()()
@ 0x7f9f5a749935 process::ProcessBase::visit()
@ 0x7f9f5a74d700 process::DispatchEvent::visit()
@ 0x48e004 process::ProcessBase::serve()
@ 0x7f9f5a745d21 process::ProcessManager::resume()
@ 0x7f9f5a742f52 _ZZN7process14ProcessManager12init_threadsEvENKUlRKSt11atomic_boolE_clES3_
@ 0x7f9f5a74cf2c _ZNSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS3_EEE6__callIvIEILm0EEEET_OSt5tupleIIDpT0_EESt12_Index_tupleIIXspT1_EEE
@ 0x7f9f5a74cedc _ZNSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS3_EEEclIIEvEET0_DpOT_
@ 0x7f9f5a74ce6e _ZNSt12_Bind_simpleIFSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS4_EEEvEE9_M_invokeIIEEEvSt12_Index_tupleIIXspT_EEE
@ 0x7f9f5a74cdc5 _ZNSt12_Bind_simpleIFSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS4_EEEvEEclEv
@ 0x7f9f5a74cd5e _ZNSt6thread5_ImplISt12_Bind_simpleIFSt5_BindIFZN7process14ProcessManager12init_threadsEvEUlRKSt11atomic_boolE_St17reference_wrapperIS6_EEEvEEE6_M_runEv
@ 0x7f9f5624f1e0 (unknown)
@ 0x7f9f564a8df5 start_thread
@ 0x7f9f559b71ad __clone
I1107 19:36:46.551370 30656 containerizer.cpp:1257] Executor for container '6553a617-6b4a-418d-9759-5681f45ff854' has exited
I1107 19:36:46.551429 30656 containerizer.cpp:1074] Destroying container '6553a617-6b4a-418d-9759-5681f45ff854'
I1107 19:36:46.553869 30656 containerizer.cpp:1257] Executor for container 'd2c1f924-c92a-453e-82b1-c294d09c4873' has exited
I1107 19:36:46.553899 30656 containerizer.cpp:1074] Destroying container 'd2c1f924-c92a-453e-82b1-c294d09c4873'
I1107 19:36:46.559680 30667 slave.cpp:3553] Executor '3' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 terminated with signal Aborted
I1107 19:36:46.559854 30667 slave.cpp:2762] Handling status update TASK_FAILED (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from @0.0.0.0:0
I1107 19:36:46.561332 30667 slave.cpp:5298] Terminating task 3
I1107 19:36:46.561820 30667 slave.cpp:3553] Executor '2' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 exited with status 0
I1107 19:36:46.562058 30667 slave.cpp:3657] Cleaning up executor '2' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 at executor(1)@172.17.5.200:55861
W1107 19:36:46.561987 30658 containerizer.cpp:966] Ignoring update for unknown container: d2c1f924-c92a-453e-82b1-c294d09c4873
I1107 19:36:46.562988 30658 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854' for gc 6.99999348802074days in the future
I1107 19:36:46.563206 30658 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2' for gc 6.99999348626074days in the future
I1107 19:36:46.563371 30658 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854' for gc 6.99999348522074days in the future
I1107 19:36:46.563972 30658 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2' for gc 6.99999347685037days in the future
I1107 19:36:46.564075 30658 status_update_manager.cpp:322] Received status update TASK_FAILED (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.564136 30658 status_update_manager.cpp:499] Creating StatusUpdate stream for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.564709 30658 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FAILED (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.565945 30658 status_update_manager.cpp:376] Forwarding update TASK_FAILED (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to the slave
I1107 19:36:46.566432 30658 slave.cpp:3087] Forwarding the update TASK_FAILED (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 to master@172.17.5.200:41587
I1107 19:36:46.566607 30658 slave.cpp:3005] Status update manager successfully handled status update TASK_FAILED (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.566871 30658 master.cpp:4414] Status update TASK_FAILED (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 from slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:46.566916 30658 master.cpp:4462] Forwarding status update TASK_FAILED (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.567101 30658 master.cpp:6066] Updating the state of task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (latest state: TASK_FAILED, status update state: TASK_FAILED)
I1107 19:36:46.567816 30658 sched.cpp:921] Scheduler::statusUpdate took 179327ns
I1107 19:36:46.568172 30658 hierarchical.cpp:739] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.568414 30658 master.cpp:3571] Processing ACKNOWLEDGE call 7702c09e-fead-4e15-acd5-2613a3d729ef for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:36:46.568475 30658 master.cpp:6132] Removing task 3 with resources cpus(*):1; mem(*):1 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 at slave(45)@172.17.5.200:41587 (095b2d77f516)
I1107 19:36:46.568858 30658 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.569103 30658 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FAILED (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.570204 30658 status_update_manager.cpp:530] Cleaning up status update stream for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.570665 30653 slave.cpp:2345] Status update manager successfully handled status update acknowledgement (UUID: 7702c09e-fead-4e15-acd5-2613a3d729ef) for task 3 of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.570719 30653 slave.cpp:5339] Completing task 3
I1107 19:36:46.570757 30653 slave.cpp:3657] Cleaning up executor '3' of framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 at executor(1)@172.17.5.200:33871
I1107 19:36:46.571321 30664 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873' for gc 6.99999339031111days in the future
I1107 19:36:46.571441 30664 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3' for gc 6.99999338850667days in the future
I1107 19:36:46.571462 30653 slave.cpp:3745] Cleaning up framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.571524 30664 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873' for gc 6.99999338741926days in the future
I1107 19:36:46.571604 30664 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3' for gc 6.99999338645926days in the future
I1107 19:36:46.571684 30664 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000' for gc 6.99999338479111days in the future
I1107 19:36:46.571751 30658 status_update_manager.cpp:284] Closing status update streams for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:46.571764 30664 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/meta/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000' for gc 6.99999338394667days in the future
I1107 19:36:47.069972 30667 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:47.070056 30667 hierarchical.cpp:851] Performed allocation for 1 slaves in 1.000108ms
I1107 19:36:47.070539 30667 master.cpp:4979] Sending 1 offers to framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:47.071069 30667 sched.cpp:813] Scheduler::resourceOffers took 125233ns
I1107 19:36:47.071385 30667 master.cpp:3297] Processing DECLINE call for offers: [ 7d94c7fb-8950-4bcf-80c1-46112292dcd6-O4 ] for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:47.072212 30667 hierarchical.cpp:739] Recovered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:47.072281 30667 hierarchical.cpp:776] Framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 filtered slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for 5secs
I1107 19:36:48.071390 30661 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:48.071497 30661 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:48.071548 30661 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:48.071580 30661 hierarchical.cpp:851] Performed allocation for 1 slaves in 870969ns
I1107 19:36:49.073005 30653 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:49.073112 30653 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:49.073165 30653 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:49.073199 30653 hierarchical.cpp:851] Performed allocation for 1 slaves in 825477ns
I1107 19:36:50.075573 30668 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:50.075677 30668 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:50.075726 30668 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:50.075757 30668 hierarchical.cpp:851] Performed allocation for 1 slaves in 762769ns
I1107 19:36:51.076812 30663 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:51.076912 30663 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:51.076968 30663 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:51.077000 30663 hierarchical.cpp:851] Performed allocation for 1 slaves in 751466ns
I1107 19:36:52.078121 30656 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:52.078203 30656 hierarchical.cpp:851] Performed allocation for 1 slaves in 905142ns
I1107 19:36:52.078529 30660 master.cpp:4979] Sending 1 offers to framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:52.079062 30660 sched.cpp:813] Scheduler::resourceOffers took 85742ns
I1107 19:36:52.079329 30660 master.cpp:3297] Processing DECLINE call for offers: [ 7d94c7fb-8950-4bcf-80c1-46112292dcd6-O5 ] for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:52.080106 30660 hierarchical.cpp:739] Recovered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:52.080173 30660 hierarchical.cpp:776] Framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 filtered slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for 5secs
I1107 19:36:53.079228 30661 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:53.079326 30661 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:53.079375 30661 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:53.079404 30661 hierarchical.cpp:851] Performed allocation for 1 slaves in 774274ns
I1107 19:36:54.081024 30664 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:54.081116 30664 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:54.081163 30664 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:54.081193 30664 hierarchical.cpp:851] Performed allocation for 1 slaves in 754287ns
I1107 19:36:55.082958 30658 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:55.083060 30658 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:55.083113 30658 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:55.083147 30658 hierarchical.cpp:851] Performed allocation for 1 slaves in 820986ns
I1107 19:36:56.085124 30668 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:56.085233 30668 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:56.085288 30668 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:56.085324 30668 hierarchical.cpp:851] Performed allocation for 1 slaves in 816628ns
I1107 19:36:57.087527 30653 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:57.087610 30653 hierarchical.cpp:851] Performed allocation for 1 slaves in 976459ns
I1107 19:36:57.088138 30653 master.cpp:4979] Sending 1 offers to framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:57.088662 30653 sched.cpp:813] Scheduler::resourceOffers took 92105ns
I1107 19:36:57.088958 30653 master.cpp:3297] Processing DECLINE call for offers: [ 7d94c7fb-8950-4bcf-80c1-46112292dcd6-O6 ] for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:36:57.089756 30653 hierarchical.cpp:739] Recovered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 from framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:57.089825 30653 hierarchical.cpp:776] Framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 filtered slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for 5secs
I1107 19:36:58.089390 30658 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:58.089505 30658 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:58.089578 30658 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:58.089625 30658 hierarchical.cpp:851] Performed allocation for 1 slaves in 903466ns
I1107 19:36:58.117602 30663 slave.cpp:4387] Querying resource estimator for oversubscribable resources
I1107 19:36:58.117940 30663 slave.cpp:4401] Received oversubscribable resources from the resource estimator
I1107 19:36:58.127810 30663 slave.cpp:3169] Received ping from slave-observer(44)@172.17.5.200:41587
I1107 19:36:59.091483 30666 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:36:59.091589 30666 hierarchical.cpp:952] No resources available to allocate!
I1107 19:36:59.091642 30666 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:36:59.091677 30666 hierarchical.cpp:851] Performed allocation for 1 slaves in 841159ns
I1107 19:37:00.093631 30655 hierarchical.cpp:1139] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0 for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:37:00.093749 30655 hierarchical.cpp:952] No resources available to allocate!
I1107 19:37:00.093808 30655 hierarchical.cpp:1045] No inverse offers to send out!
I1107 19:37:00.093850 30655 hierarchical.cpp:851] Performed allocation for 1 slaves in 1.127808ms
../../src/tests/fetcher_cache_tests.cpp:1273: Failure
Failed to wait 15secs for awaitFinished(task.get())
Begin listing sandboxes
Begin listing sandbox `/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/latest`:
Begin file contents of `stdout`:
End file
Begin file contents of `stderr`:
I1107 19:36:43.265862 1005 logging.cpp:177] Logging to STDERR
I1107 19:36:43.266121 1005 fetcher.cpp:422] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/fetch\/slaves\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0\/mesos","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-cmd0","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/mesos-fetcher-test-assets\/cmd0"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/slaves\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0\/frameworks\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000\/executors\/0\/runs\/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49","user":"mesos"}
I1107 19:36:43.275835 1005 fetcher.cpp:377] Fetching URI '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd0'
I1107 19:36:43.275905 1005 fetcher.cpp:347] Downloading into cache
I1107 19:36:43.276168 1005 fetcher.cpp:185] Fetching URI '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd0'
I1107 19:36:43.276239 1005 fetcher.cpp:165] Copying resource with command:cp '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd0' '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/fetch/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/mesos/c1-cmd0'
I1107 19:36:43.281396 1005 fetcher.cpp:287] Fetching from cache
I1107 19:36:43.281508 1005 fetcher.cpp:165] Copying resource with command:cp '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/fetch/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/mesos/c1-cmd0' '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49/cmd0'
I1107 19:36:43.287910 1005 fetcher.cpp:454] Fetched '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd0' to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/0/runs/d2a0999a-4e4a-45c5-a1ef-a75535eb4f49/cmd0'
End file
Begin file contents of `cmd0`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `mesos-fetcher-test-cmd0`:
End file
End sandbox
Begin listing sandbox `/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/latest`:
Begin file contents of `stdout`:
End file
Begin file contents of `mesos-fetcher-test-cmd1`:
End file
Begin file contents of `cmd1`:
touch mesos-fetcher-test-cmd$1
End file
IBegin file contents of `stderr`:
I1107 19:36:44.180100 1071 logging.cpp:177] Logging to STDERR
I1107 19:36:44.180349 1071 fetcher.cpp:422] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/fetch\/slaves\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0\/mesos","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c2-cmd1","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/mesos-fetcher-test-assets\/cmd1"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/slaves\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0\/frameworks\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000\/executors\/1\/runs\/91a41a5f-b53e-4b80-93ca-d5aa9789e49d","user":"mesos"}
I1107 19:36:44.189716 1071 fetcher.cpp:377] Fetching URI '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd1'
I1107 19:36:44.189774 1071 fetcher.cpp:347] Downloading into cache
I1107 19:36:44.189877 1071 fetcher.cpp:185] Fetching URI '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd1'
I1107 19:36:44.189965 1071 fetcher.cpp:165] Copying resource with command:cp '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd1' '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/fetch/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/mesos/c2-cmd1'
I1107 19:36:44.195561 1071 fetcher.cpp:287] Fetching from cache
I1107 19:36:44.195663 1071 fetcher.cpp:165] Copying resource with command:cp '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/fetch/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/mesos/c2-cmd1' '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d/cmd1'
I1107 19:36:44.200572 1071 fetcher.cpp:454] Fetched '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd1' to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/1/runs/91a41a5f-b53e-4b80-93ca-d5aa9789e49d/cmd1'
End file
End sandbox
Begin listing sandbox `/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/latest`:
Begin file contents of `cmd2`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `stdout`:
End file
Begin file contents of `stderr`:
I1107 19:36:45.188294 1137 logging.cpp:177] Logging to STDERR
I1107 19:36:45.188562 1137 fetcher.cpp:422] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/fetch\/slaves\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0\/mesos","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c3-cmd2","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/mesos-fetcher-test-assets\/cmd2"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/slaves\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0\/frameworks\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000\/executors\/2\/runs\/6553a617-6b4a-418d-9759-5681f45ff854","user":"mesos"}
I1107 19:36:45.198669 1137 fetcher.cpp:377] Fetching URI '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd2'
I1107 19:36:45.198742 1137 fetcher.cpp:347] Downloading into cache
I1107 19:36:45.198854 1137 fetcher.cpp:185] Fetching URI '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd2'
I1107 19:36:45.198959 1137 fetcher.cpp:165] Copying resource with command:cp '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd2' '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/fetch/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/mesos/c3-cmd2'
I1107 19:36:45.205759 1137 fetcher.cpp:287] Fetching from cache
I1107 19:36:45.205849 1137 fetcher.cpp:165] Copying resource with command:cp '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/fetch/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/mesos/c3-cmd2' '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854/cmd2'
I1107 19:36:45.211871 1137 fetcher.cpp:454] Fetched '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd2' to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/2/runs/6553a617-6b4a-418d-9759-5681f45ff854/cmd2'
End file
Begin file contents of `mesos-fetcher-test-cmd2`:
End file
End sandbox
Begin listing sandbox `/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/latest`:
Begin file contents of `cmd3`:
touch mesos-fetcher-test-cmd$1
End file
Begin file contents of `stdout`:
End file
Begin file contents of `stderr`:
I1107 19:36:46.208904 1203 logging.cpp:177] Logging to STDERR
I1107 19:36:46.209199 1203 fetcher.cpp:422] Fetcher Info: {"cache_directory":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/fetch\/slaves\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0\/mesos","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c4-cmd3","uri":{"cache":true,"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/mesos-fetcher-test-assets\/cmd3"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_SimpleEviction_ckaUz0\/slaves\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0\/frameworks\/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000\/executors\/3\/runs\/d2c1f924-c92a-453e-82b1-c294d09c4873","user":"mesos"}
I1107 19:36:46.219807 1203 fetcher.cpp:377] Fetching URI '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd3'
I1107 19:36:46.219877 1203 fetcher.cpp:347] Downloading into cache
I1107 19:36:46.219998 1203 fetcher.cpp:185] Fetching URI '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd3'
I1107 19:36:46.220082 1203 fetcher.cpp:165] Copying resource with command:cp '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd3' '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/fetch/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/mesos/c4-cmd3'
I1107 19:36:46.225587 1203 fetcher.cpp:287] Fetching from cache
I1107 19:36:46.225641 1203 fetcher.cpp:165] Copying resource with command:cp '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/fetch/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/mesos/c4-cmd3' '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873/cmd3'
I1107 19:36:46.231015 1203 fetcher.cpp:454] Fetched '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/mesos-fetcher-test-assets/cmd3' to '/tmp/FetcherCacheTest_SimpleEviction_ckaUz0/slaves/7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0/frameworks/7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000/executors/3/runs/d2c1f924-c92a-453e-82b1-c294d09c4873/cmd3'
End file
End sandbox
End sandboxes
1107 19:37:01.087862 30634 sched.cpp:1805] Asked to stop the driver
I1107 19:37:01.089032 30661 sched.cpp:1043] Stopping framework '7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000'
I1107 19:37:01.089821 30661 master.cpp:5547] Processing TEARDOWN call for framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:37:01.089881 30661 master.cpp:5559] Removing framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 (default) at scheduler-bae66de0-c814-4a38-82ec-9b0483d92347@172.17.5.200:41587
I1107 19:37:01.090523 30661 hierarchical.cpp:263] Deactivated framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:37:01.090648 30661 hierarchical.cpp:220] Removed framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:37:01.090729 30661 slave.cpp:2009] Asked to shut down framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000 by master@172.17.5.200:41587
W1107 19:37:01.090756 30661 slave.cpp:2024] Cannot shut down unknown framework 7d94c7fb-8950-4bcf-80c1-46112292dcd6-0000
I1107 19:37:01.091835 30661 master.cpp:922] Master terminating
I1107 19:37:01.092877 30661 hierarchical.cpp:364] Removed slave 7d94c7fb-8950-4bcf-80c1-46112292dcd6-S0
I1107 19:37:01.092944 30661 slave.cpp:3215] master@172.17.5.200:41587 exited
W1107 19:37:01.092970 30661 slave.cpp:3218] Master disconnected! Waiting for a new master to be elected
I1107 19:37:01.133751 30654 slave.cpp:601] Slave terminating
[ FAILED ] FetcherCacheTest.SimpleEviction (18126 ms)
{code}
> FetcherCacheTest.SimpleEviction is flaky
> ----------------------------------------
>
> Key: MESOS-2831
> URL: https://issues.apache.org/jira/browse/MESOS-2831
> Project: Mesos
> Issue Type: Bug
> Components: fetcher
> Affects Versions: 0.23.0
> Reporter: Vinod Kone
> Assignee: Bernd Mathiske
> Labels: flaky-test, mesosphere
>
> Saw this when reviewbot was testing an unrelated review https://reviews.apache.org/r/35119/
> {code}
> [ RUN ] FetcherCacheTest.SimpleEviction
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
> Function call: resourceOffers(0x5365320, @0x2b7bef9f1b20 { 128-byte object <B0-C0 36-E6 7B-2B 00-00 00-00 00-00 00-00 00-00 20-75 00-18 7C-2B 00-00 C0-75 00-18 7C-2B 00-00 60-76 00-18 7C-2B 00-00 00-77 00-18 7C-2B 00-00 40-3A 00-18 7C-2B 00-00 04-00 00-00 04-00 00-00 04-00 00-00 7C-2B 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 0F-00 00-00> })
> Stack trace:
> F0607 21:19:23.181392 4246 fetcher_cache_tests.cpp:354] CHECK_READY(offers): is PENDING Failed to wait for resource offers
> *** Check failure stack trace: ***
> @ 0x2b7be56c5972 google::LogMessage::Fail()
> @ 0x2b7be56c58be google::LogMessage::SendToLog()
> @ 0x2b7be56c52c0 google::LogMessage::Flush()
> @ 0x2b7be56c81d4 google::LogMessageFatal::~LogMessageFatal()
> @ 0x97d182 _CheckFatal::~_CheckFatal()
> @ 0xb58a28 mesos::internal::tests::FetcherCacheTest::launchTask()
> @ 0xb65b50 mesos::internal::tests::FetcherCacheTest_SimpleEviction_Test::TestBody()
> @ 0x11923b7 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x118d5b4 testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x1175975 testing::Test::Run()
> @ 0x1176098 testing::TestInfo::Run()
> @ 0x1176620 testing::TestCase::Run()
> @ 0x117b2ea testing::internal::UnitTestImpl::RunAllTests()
> @ 0x1193229 testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x118e2a5 testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x117a1f6 testing::UnitTest::Run()
> @ 0xcc832b main
> @ 0x2b7be7d46ec5 (unknown)
> @ 0x872379 (unknown)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)