Anand Mazumdar created MESOS-5025:
-------------------------------------
Summary: FetcherCacheTest.LocalUncached is flaky
Key: MESOS-5025
URL: https://issues.apache.org/jira/browse/MESOS-5025
Project: Mesos
Issue Type: Bug
Components: fetcher
Environment: CentOS 7
Reporter: Anand Mazumdar
Showed up on an internal CI:
{code}
[17:57:05] : [Step 11/11] [ RUN ] FetcherCacheTest.LocalUncached
[17:57:05]W: [Step 11/11] I0324 17:57:05.653718 1813 cluster.cpp:139]
Creating default 'local' authorizer
[17:57:05]W: [Step 11/11] I0324 17:57:05.659001 1813 leveldb.cpp:174]
Opened db in 5.09329ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.660393 1813 leveldb.cpp:181]
Compacted db in 1.367077ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.660434 1813 leveldb.cpp:196]
Created db iterator in 13516ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.660446 1813 leveldb.cpp:202]
Seeked to beginning of db in 1531ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.660454 1813 leveldb.cpp:271]
Iterated through 0 keys in the db in 284ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.660478 1813 replica.cpp:779]
Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[17:57:05]W: [Step 11/11] I0324 17:57:05.660815 1831 recover.cpp:447]
Starting replica recovery
[17:57:05]W: [Step 11/11] I0324 17:57:05.661001 1831 recover.cpp:473]
Replica is in EMPTY status
[17:57:05]W: [Step 11/11] I0324 17:57:05.661866 1830 replica.cpp:673]
Replica in EMPTY status received a broadcasted recover request from
(1886)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.662237 1831 recover.cpp:193]
Received a recover response from a replica in EMPTY status
[17:57:05]W: [Step 11/11] I0324 17:57:05.662652 1827 recover.cpp:564]
Updating replica status to STARTING
[17:57:05]W: [Step 11/11] I0324 17:57:05.663151 1829 master.cpp:376]
Master 2574ed73-b254-4829-9efc-f76d89150396 (ip-172-30-2-131.mesosphere.io)
started on 172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.663172 1829 master.cpp:378] Flags
at startup: --acls="" --allocation_interval="1secs"
--allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true"
--authenticate_slaves="true" --authenticators="crammd5" --authorizers="local"
--credentials="/tmp/VRasc1/credentials" --framework_sorter="drf" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
--max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
--quiet="false" --recovery_slave_removal_limit="100%"
--registry="replicated_log" --registry_fetch_timeout="1mins"
--registry_store_timeout="100secs" --registry_strict="true"
--root_submissions="true" --slave_ping_timeout="15secs"
--slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
--webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/VRasc1/master"
--zk_session_timeout="10secs"
[17:57:05]W: [Step 11/11] I0324 17:57:05.663374 1829 master.cpp:427]
Master only allowing authenticated frameworks to register
[17:57:05]W: [Step 11/11] I0324 17:57:05.663384 1829 master.cpp:432]
Master only allowing authenticated slaves to register
[17:57:05]W: [Step 11/11] I0324 17:57:05.663390 1829 credentials.hpp:35]
Loading credentials for authentication from '/tmp/VRasc1/credentials'
[17:57:05]W: [Step 11/11] I0324 17:57:05.663595 1829 master.cpp:474] Using
default 'crammd5' authenticator
[17:57:05]W: [Step 11/11] I0324 17:57:05.663725 1829 master.cpp:545] Using
default 'basic' HTTP authenticator
[17:57:05]W: [Step 11/11] I0324 17:57:05.663880 1829 master.cpp:583]
Authorization enabled
[17:57:05]W: [Step 11/11] I0324 17:57:05.664001 1827 hierarchical.cpp:144]
Initialized hierarchical allocator process
[17:57:05]W: [Step 11/11] I0324 17:57:05.664010 1831
whitelist_watcher.cpp:77] No whitelist given
[17:57:05]W: [Step 11/11] I0324 17:57:05.664114 1834 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 1.271881ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.664136 1834 replica.cpp:320]
Persisted replica status to STARTING
[17:57:05]W: [Step 11/11] I0324 17:57:05.664353 1833 recover.cpp:473]
Replica is in STARTING status
[17:57:05]W: [Step 11/11] I0324 17:57:05.665315 1833 replica.cpp:673]
Replica in STARTING status received a broadcasted recover request from
(1888)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.665621 1827 recover.cpp:193]
Received a recover response from a replica in STARTING status
[17:57:05]W: [Step 11/11] I0324 17:57:05.666237 1833 master.cpp:1826] The
newly elected leader is [email protected]:51675 with id
2574ed73-b254-4829-9efc-f76d89150396
[17:57:05]W: [Step 11/11] I0324 17:57:05.666265 1833 master.cpp:1839]
Elected as the leading master!
[17:57:05]W: [Step 11/11] I0324 17:57:05.666286 1833 master.cpp:1526]
Recovering from registrar
[17:57:05]W: [Step 11/11] I0324 17:57:05.666302 1829 recover.cpp:564]
Updating replica status to VOTING
[17:57:05]W: [Step 11/11] I0324 17:57:05.666453 1828 registrar.cpp:307]
Recovering registrar
[17:57:05]W: [Step 11/11] I0324 17:57:05.667702 1834 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 1.284762ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.667726 1834 replica.cpp:320]
Persisted replica status to VOTING
[17:57:05]W: [Step 11/11] I0324 17:57:05.667820 1829 recover.cpp:578]
Successfully joined the Paxos group
[17:57:05]W: [Step 11/11] I0324 17:57:05.667979 1829 recover.cpp:462]
Recover process terminated
[17:57:05]W: [Step 11/11] I0324 17:57:05.668354 1832 log.cpp:659]
Attempting to start the writer
[17:57:05]W: [Step 11/11] I0324 17:57:05.669368 1827 replica.cpp:493]
Replica received implicit promise request from (1889)@172.30.2.131:51675 with
proposal 1
[17:57:05]W: [Step 11/11] I0324 17:57:05.670606 1827 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 1.21276ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.670629 1827 replica.cpp:342]
Persisted promised to 1
[17:57:05]W: [Step 11/11] I0324 17:57:05.671175 1827 coordinator.cpp:238]
Coordinator attempting to fill missing positions
[17:57:05]W: [Step 11/11] I0324 17:57:05.672204 1828 replica.cpp:388]
Replica received explicit promise request from (1890)@172.30.2.131:51675 for
position 0 with proposal 2
[17:57:05]W: [Step 11/11] I0324 17:57:05.673405 1828 leveldb.cpp:341]
Persisting action (8 bytes) to leveldb took 1.162883ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.673429 1828 replica.cpp:712]
Persisted action at 0
[17:57:05]W: [Step 11/11] I0324 17:57:05.674235 1828 replica.cpp:537]
Replica received write request for position 0 from (1891)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.674288 1828 leveldb.cpp:436]
Reading position from leveldb took 23327ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.675454 1828 leveldb.cpp:341]
Persisting action (14 bytes) to leveldb took 1.136428ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.675477 1828 replica.cpp:712]
Persisted action at 0
[17:57:05]W: [Step 11/11] I0324 17:57:05.675941 1829 replica.cpp:691]
Replica received learned notice for position 0 from @0.0.0.0:0
[17:57:05]W: [Step 11/11] I0324 17:57:05.677085 1829 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 1.115099ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.677109 1829 replica.cpp:712]
Persisted action at 0
[17:57:05]W: [Step 11/11] I0324 17:57:05.677124 1829 replica.cpp:697]
Replica learned NOP action at position 0
[17:57:05]W: [Step 11/11] I0324 17:57:05.677489 1834 log.cpp:675] Writer
started with ending position 0
[17:57:05]W: [Step 11/11] I0324 17:57:05.678406 1830 leveldb.cpp:436]
Reading position from leveldb took 29311ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.679182 1833 registrar.cpp:340]
Successfully fetched the registry (0B) in 12.684288ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.679265 1833 registrar.cpp:439]
Applied 1 operations in 19954ns; attempting to update the 'registry'
[17:57:05]W: [Step 11/11] I0324 17:57:05.679831 1832 log.cpp:683]
Attempting to append 210 bytes to the log
[17:57:05]W: [Step 11/11] I0324 17:57:05.679929 1831 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 1
[17:57:05]W: [Step 11/11] I0324 17:57:05.680533 1830 replica.cpp:537]
Replica received write request for position 1 from (1892)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.683586 1830 leveldb.cpp:341]
Persisting action (229 bytes) to leveldb took 3.018164ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.683609 1830 replica.cpp:712]
Persisted action at 1
[17:57:05]W: [Step 11/11] I0324 17:57:05.684149 1828 replica.cpp:691]
Replica received learned notice for position 1 from @0.0.0.0:0
[17:57:05]W: [Step 11/11] I0324 17:57:05.685715 1828 leveldb.cpp:341]
Persisting action (231 bytes) to leveldb took 1.542509ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.685739 1828 replica.cpp:712]
Persisted action at 1
[17:57:05]W: [Step 11/11] I0324 17:57:05.685753 1828 replica.cpp:697]
Replica learned APPEND action at position 1
[17:57:05]W: [Step 11/11] I0324 17:57:05.686549 1829 registrar.cpp:484]
Successfully updated the 'registry' in 7.241984ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.686678 1829 registrar.cpp:370]
Successfully recovered registrar
[17:57:05]W: [Step 11/11] I0324 17:57:05.686734 1834 log.cpp:702]
Attempting to truncate the log to 1
[17:57:05]W: [Step 11/11] I0324 17:57:05.686836 1831 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 2
[17:57:05]W: [Step 11/11] I0324 17:57:05.687144 1830 master.cpp:1634]
Recovered 0 slaves from the Registry (171B) ; allowing 10mins for slaves to
re-register
[17:57:05]W: [Step 11/11] I0324 17:57:05.687191 1828 hierarchical.cpp:171]
Skipping recovery of hierarchical allocator: nothing to recover
[17:57:05]W: [Step 11/11] I0324 17:57:05.687652 1828 replica.cpp:537]
Replica received write request for position 2 from (1893)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.688832 1828 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 1.150168ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.688855 1828 replica.cpp:712]
Persisted action at 2
[17:57:05]W: [Step 11/11] I0324 17:57:05.689348 1832 replica.cpp:691]
Replica received learned notice for position 2 from @0.0.0.0:0
[17:57:05]W: [Step 11/11] I0324 17:57:05.690568 1832 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 1.190974ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.690620 1832 leveldb.cpp:399]
Deleting ~1 keys from leveldb took 28009ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.690636 1832 replica.cpp:712]
Persisted action at 2
[17:57:05]W: [Step 11/11] I0324 17:57:05.690651 1832 replica.cpp:697]
Replica learned TRUNCATE action at position 2
[17:57:05]W: [Step 11/11] I0324 17:57:05.698376 1813
containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
[17:57:05]W: [Step 11/11] I0324 17:57:05.705034 1813
linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
for the Linux launcher
[17:57:05]W: [Step 11/11] I0324 17:57:05.708708 1829 slave.cpp:200] Slave
started on 46)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.708725 1829 slave.cpp:201] Flags
at startup: --appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
--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_LocalUncached_XP781E/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/FetcherCacheTest_LocalUncached_XP781E/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="true"
--hostname_lookup="true" --http_authenticators="basic"
--http_credentials="/tmp/FetcherCacheTest_LocalUncached_XP781E/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0"
--logging_level="INFO" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:1000;mem:1000" --revocable_cpu_low_priority="true"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/FetcherCacheTest_LocalUncached_XP781E"
[17:57:05]W: [Step 11/11] I0324 17:57:05.709116 1829 credentials.hpp:83]
Loading credential for authentication from
'/tmp/FetcherCacheTest_LocalUncached_XP781E/credential'
[17:57:05]W: [Step 11/11] I0324 17:57:05.709246 1829 slave.cpp:338] Slave
using credential for: test-principal
[17:57:05]W: [Step 11/11] I0324 17:57:05.709270 1829 credentials.hpp:35]
Loading credentials for authentication from
'/tmp/FetcherCacheTest_LocalUncached_XP781E/http_credentials'
[17:57:05]W: [Step 11/11] I0324 17:57:05.709431 1829 slave.cpp:390] Using
default 'basic' HTTP authenticator
[17:57:05]W: [Step 11/11] I0324 17:57:05.709714 1829 resources.cpp:572]
Parsing resources as JSON failed: cpus:1000;mem:1000
[17:57:05]W: [Step 11/11] Trying semicolon-delimited string format instead
[17:57:05]W: [Step 11/11] I0324 17:57:05.710072 1829 slave.cpp:589] Slave
resources: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000]
[17:57:05]W: [Step 11/11] I0324 17:57:05.710126 1829 slave.cpp:597] Slave
attributes: [ ]
[17:57:05]W: [Step 11/11] I0324 17:57:05.710136 1829 slave.cpp:602] Slave
hostname: ip-172-30-2-131.mesosphere.io
[17:57:05]W: [Step 11/11] I0324 17:57:05.711079 1834 state.cpp:58]
Recovering state from '/tmp/FetcherCacheTest_LocalUncached_XP781E/meta'
[17:57:05]W: [Step 11/11] I0324 17:57:05.711343 1828
status_update_manager.cpp:200] Recovering status update manager
[17:57:05]W: [Step 11/11] I0324 17:57:05.711530 1831
containerizer.cpp:407] Recovering containerizer
[17:57:05]W: [Step 11/11] I0324 17:57:05.713354 1828 provisioner.cpp:245]
Provisioner recovery complete
[17:57:05]W: [Step 11/11] I0324 17:57:05.713668 1827 slave.cpp:4726]
Finished recovery
[17:57:05]W: [Step 11/11] I0324 17:57:05.713943 1827 slave.cpp:4898]
Querying resource estimator for oversubscribable resources
[17:57:05]W: [Step 11/11] I0324 17:57:05.714146 1832
status_update_manager.cpp:174] Pausing sending status updates
[17:57:05]W: [Step 11/11] I0324 17:57:05.714148 1827 slave.cpp:928] New
master detected at [email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.714213 1827 slave.cpp:991]
Authenticating with master [email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.714228 1827 slave.cpp:996] Using
default CRAM-MD5 authenticatee
[17:57:05]W: [Step 11/11] I0324 17:57:05.714349 1827 slave.cpp:964]
Detecting new master
[17:57:05]W: [Step 11/11] I0324 17:57:05.714381 1828
authenticatee.cpp:121] Creating new client SASL connection
[17:57:05]W: [Step 11/11] I0324 17:57:05.714493 1827 slave.cpp:4912]
Received oversubscribable resources from the resource estimator
[17:57:05]W: [Step 11/11] I0324 17:57:05.714701 1832 master.cpp:5679]
Authenticating slave(46)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.714797 1830
authenticator.cpp:413] Starting authentication session for
crammd5_authenticatee(137)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.715004 1833 authenticator.cpp:98]
Creating new server SASL connection
[17:57:05]W: [Step 11/11] I0324 17:57:05.715246 1828
authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[17:57:05]W: [Step 11/11] I0324 17:57:05.715270 1828
authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[17:57:05]W: [Step 11/11] I0324 17:57:05.715348 1828
authenticator.cpp:203] Received SASL authentication start
[17:57:05]W: [Step 11/11] I0324 17:57:05.715390 1828
authenticator.cpp:325] Authentication requires more steps
[17:57:05]W: [Step 11/11] I0324 17:57:05.715466 1828
authenticatee.cpp:258] Received SASL authentication step
[17:57:05]W: [Step 11/11] I0324 17:57:05.715585 1832
authenticator.cpp:231] Received SASL authentication step
[17:57:05]W: [Step 11/11] I0324 17:57:05.715620 1832 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-131.mesosphere.io' server FQDN: 'ip-172-30-2-131.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[17:57:05]W: [Step 11/11] I0324 17:57:05.715636 1832 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[17:57:05]W: [Step 11/11] I0324 17:57:05.715677 1832 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[17:57:05]W: [Step 11/11] I0324 17:57:05.715734 1832 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-131.mesosphere.io' server FQDN: 'ip-172-30-2-131.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[17:57:05]W: [Step 11/11] I0324 17:57:05.715751 1832 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[17:57:05]W: [Step 11/11] I0324 17:57:05.715761 1832 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[17:57:05]W: [Step 11/11] I0324 17:57:05.715778 1832
authenticator.cpp:317] Authentication success
[17:57:05]W: [Step 11/11] I0324 17:57:05.715862 1828
authenticatee.cpp:298] Authentication success
[17:57:05]W: [Step 11/11] I0324 17:57:05.715942 1833 master.cpp:5709]
Successfully authenticated principal 'test-principal' at
slave(46)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.716002 1828
authenticator.cpp:431] Authentication session cleanup for
crammd5_authenticatee(137)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.716163 1829 slave.cpp:1061]
Successfully authenticated with master [email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.716281 1829 slave.cpp:1457] Will
retry registration in 3.158987ms if necessary
[17:57:05]W: [Step 11/11] I0324 17:57:05.716405 1833 master.cpp:4390]
Registering slave at slave(46)@172.30.2.131:51675
(ip-172-30-2-131.mesosphere.io) with id 2574ed73-b254-4829-9efc-f76d89150396-S0
[17:57:05]W: [Step 11/11] I0324 17:57:05.716760 1834 registrar.cpp:439]
Applied 1 operations in 46146ns; attempting to update the 'registry'
[17:57:05]W: [Step 11/11] I0324 17:57:05.717321 1834 log.cpp:683]
Attempting to append 396 bytes to the log
[17:57:05]W: [Step 11/11] I0324 17:57:05.717409 1830 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 3
[17:57:05]W: [Step 11/11] I0324 17:57:05.717975 1828 replica.cpp:537]
Replica received write request for position 3 from (1910)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.719166 1828 leveldb.cpp:341]
Persisting action (415 bytes) to leveldb took 1.158936ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.719189 1828 replica.cpp:712]
Persisted action at 3
[17:57:05]W: [Step 11/11] I0324 17:57:05.719735 1829 replica.cpp:691]
Replica received learned notice for position 3 from @0.0.0.0:0
[17:57:05]W: [Step 11/11] I0324 17:57:05.719853 1827 slave.cpp:1457] Will
retry registration in 750973ns if necessary
[17:57:05]W: [Step 11/11] I0324 17:57:05.719950 1828 master.cpp:4378]
Ignoring register slave message from slave(46)@172.30.2.131:51675
(ip-172-30-2-131.mesosphere.io) as admission is already in progress
[17:57:05]W: [Step 11/11] I0324 17:57:05.720948 1829 leveldb.cpp:341]
Persisting action (417 bytes) to leveldb took 1.184121ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.720969 1829 replica.cpp:712]
Persisted action at 3
[17:57:05]W: [Step 11/11] I0324 17:57:05.720984 1829 replica.cpp:697]
Replica learned APPEND action at position 3
[17:57:05]W: [Step 11/11] I0324 17:57:05.721307 1830 slave.cpp:1457] Will
retry registration in 66.736924ms if necessary
[17:57:05]W: [Step 11/11] I0324 17:57:05.721436 1833 master.cpp:4378]
Ignoring register slave message from slave(46)@172.30.2.131:51675
(ip-172-30-2-131.mesosphere.io) as admission is already in progress
[17:57:05]W: [Step 11/11] I0324 17:57:05.722131 1827 registrar.cpp:484]
Successfully updated the 'registry' in 5.325056ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.722312 1830 log.cpp:702]
Attempting to truncate the log to 3
[17:57:05]W: [Step 11/11] I0324 17:57:05.722414 1831 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 4
[17:57:05]W: [Step 11/11] I0324 17:57:05.722780 1827 slave.cpp:3618]
Received ping from slave-observer(45)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.722901 1833 master.cpp:4458]
Registered slave 2574ed73-b254-4829-9efc-f76d89150396-S0 at
slave(46)@172.30.2.131:51675 (ip-172-30-2-131.mesosphere.io) with cpus(*):1000;
mem(*):1000; disk(*):15342; ports(*):[31000-32000]
[17:57:05]W: [Step 11/11] I0324 17:57:05.723099 1827 slave.cpp:1105]
Registered with master [email protected]:51675; given slave ID
2574ed73-b254-4829-9efc-f76d89150396-S0
[17:57:05]W: [Step 11/11] I0324 17:57:05.723124 1827 fetcher.cpp:81]
Clearing fetcher cache
[17:57:05]W: [Step 11/11] I0324 17:57:05.723160 1828 hierarchical.cpp:473]
Added slave 2574ed73-b254-4829-9efc-f76d89150396-S0
(ip-172-30-2-131.mesosphere.io) with cpus(*):1000; mem(*):1000; disk(*):15342;
ports(*):[31000-32000] (allocated: )
[17:57:05]W: [Step 11/11] I0324 17:57:05.723296 1831 replica.cpp:537]
Replica received write request for position 4 from (1911)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.723310 1829
status_update_manager.cpp:181] Resuming sending status updates
[17:57:05]W: [Step 11/11] I0324 17:57:05.723318 1828
hierarchical.cpp:1487] No resources available to allocate!
[17:57:05]W: [Step 11/11] I0324 17:57:05.723383 1828
hierarchical.cpp:1161] Performed allocation for slave
2574ed73-b254-4829-9efc-f76d89150396-S0 in 179141ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.723459 1827 slave.cpp:1128]
Checkpointing SlaveInfo to
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/slave.info'
[17:57:05]W: [Step 11/11] I0324 17:57:05.723779 1827 slave.cpp:1165]
Forwarding total oversubscribed resources
[17:57:05]W: [Step 11/11] I0324 17:57:05.723881 1813 sched.cpp:222]
Version: 0.29.0
[17:57:05]W: [Step 11/11] I0324 17:57:05.723970 1827 master.cpp:4802]
Received update of slave 2574ed73-b254-4829-9efc-f76d89150396-S0 at
slave(46)@172.30.2.131:51675 (ip-172-30-2-131.mesosphere.io) with total
oversubscribed resources
[17:57:05]W: [Step 11/11] I0324 17:57:05.724351 1827 sched.cpp:326] New
master detected at [email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.724434 1827 sched.cpp:382]
Authenticating with master [email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.724452 1827 sched.cpp:389] Using
default CRAM-MD5 authenticatee
[17:57:05]W: [Step 11/11] I0324 17:57:05.724459 1829 hierarchical.cpp:531]
Slave 2574ed73-b254-4829-9efc-f76d89150396-S0 (ip-172-30-2-131.mesosphere.io)
updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000;
disk(*):15342; ports(*):[31000-32000], allocated: )
[17:57:05]W: [Step 11/11] I0324 17:57:05.724562 1829
hierarchical.cpp:1487] No resources available to allocate!
[17:57:05]W: [Step 11/11] I0324 17:57:05.724560 1831 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 1.226528ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.724588 1831 replica.cpp:712]
Persisted action at 4
[17:57:05]W: [Step 11/11] I0324 17:57:05.724606 1829
hierarchical.cpp:1161] Performed allocation for slave
2574ed73-b254-4829-9efc-f76d89150396-S0 in 117017ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.724692 1833
authenticatee.cpp:121] Creating new client SASL connection
[17:57:05]W: [Step 11/11] I0324 17:57:05.724995 1829 master.cpp:5679]
Authenticating [email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.725083 1831
authenticator.cpp:413] Starting authentication session for
crammd5_authenticatee(138)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.725359 1830 replica.cpp:691]
Replica received learned notice for position 4 from @0.0.0.0:0
[17:57:05]W: [Step 11/11] I0324 17:57:05.725435 1833 authenticator.cpp:98]
Creating new server SASL connection
[17:57:05]W: [Step 11/11] I0324 17:57:05.725682 1827
authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[17:57:05]W: [Step 11/11] I0324 17:57:05.725709 1827
authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[17:57:05]W: [Step 11/11] I0324 17:57:05.725814 1831
authenticator.cpp:203] Received SASL authentication start
[17:57:05]W: [Step 11/11] I0324 17:57:05.725848 1831
authenticator.cpp:325] Authentication requires more steps
[17:57:05]W: [Step 11/11] I0324 17:57:05.725919 1831
authenticatee.cpp:258] Received SASL authentication step
[17:57:05]W: [Step 11/11] I0324 17:57:05.726004 1831
authenticator.cpp:231] Received SASL authentication step
[17:57:05]W: [Step 11/11] I0324 17:57:05.726027 1831 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-131.mesosphere.io' server FQDN: 'ip-172-30-2-131.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[17:57:05]W: [Step 11/11] I0324 17:57:05.726034 1831 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[17:57:05]W: [Step 11/11] I0324 17:57:05.726058 1831 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[17:57:05]W: [Step 11/11] I0324 17:57:05.726079 1831 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-131.mesosphere.io' server FQDN: 'ip-172-30-2-131.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[17:57:05]W: [Step 11/11] I0324 17:57:05.726088 1831 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[17:57:05]W: [Step 11/11] I0324 17:57:05.726094 1831 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[17:57:05]W: [Step 11/11] I0324 17:57:05.726104 1831
authenticator.cpp:317] Authentication success
[17:57:05]W: [Step 11/11] I0324 17:57:05.726196 1834
authenticatee.cpp:298] Authentication success
[17:57:05]W: [Step 11/11] I0324 17:57:05.726238 1828 master.cpp:5709]
Successfully authenticated principal 'test-principal' at
[email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.726310 1833
authenticator.cpp:431] Authentication session cleanup for
crammd5_authenticatee(138)@172.30.2.131:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.726505 1830 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 1.117222ms
[17:57:05]W: [Step 11/11] I0324 17:57:05.726516 1831 sched.cpp:472]
Successfully authenticated with master [email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.726533 1831 sched.cpp:777]
Sending SUBSCRIBE call to [email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.726580 1830 leveldb.cpp:399]
Deleting ~2 keys from leveldb took 47012ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.726600 1830 replica.cpp:712]
Persisted action at 4
[17:57:05]W: [Step 11/11] I0324 17:57:05.726603 1831 sched.cpp:810] Will
retry registration in 479.464188ms if necessary
[17:57:05]W: [Step 11/11] I0324 17:57:05.726620 1830 replica.cpp:697]
Replica learned TRUNCATE action at position 4
[17:57:05]W: [Step 11/11] I0324 17:57:05.726689 1828 master.cpp:2346]
Received SUBSCRIBE call for framework 'default' at
[email protected]:51675
[17:57:05]W: [Step 11/11] W0324 17:57:05.726716 1828 master.cpp:2353]
Framework at [email protected]:51675
(authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
[17:57:05]W: [Step 11/11] I0324 17:57:05.726766 1828 master.cpp:1865]
Authorizing framework principal '' to receive offers for role '*'
[17:57:05]W: [Step 11/11] I0324 17:57:05.726979 1830 master.cpp:2417]
Subscribing framework default with checkpointing enabled and capabilities [ ]
[17:57:05]W: [Step 11/11] I0324 17:57:05.727299 1827 hierarchical.cpp:265]
Added framework 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:05]W: [Step 11/11] I0324 17:57:05.727388 1830 sched.cpp:704]
Framework registered with 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:05]W: [Step 11/11] I0324 17:57:05.727426 1830 sched.cpp:718]
Scheduler::registered took 15985ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.727911 1827
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:05]W: [Step 11/11] I0324 17:57:05.727977 1827
hierarchical.cpp:1138] Performed allocation for 1 slaves in 654777ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.728184 1833 master.cpp:5508]
Sending 1 offers to framework 2574ed73-b254-4829-9efc-f76d89150396-0000
(default) at [email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.728536 1834 sched.cpp:874]
Scheduler::resourceOffers took 96103ns
[17:57:05]W: [Step 11/11] I0324 17:57:05.728922 1813 resources.cpp:572]
Parsing resources as JSON failed: cpus:1;mem:1
[17:57:05]W: [Step 11/11] Trying semicolon-delimited string format instead
[17:57:05]W: [Step 11/11] I0324 17:57:05.730013 1834 master.cpp:3288]
Processing ACCEPT call for offers: [ 2574ed73-b254-4829-9efc-f76d89150396-O0 ]
on slave 2574ed73-b254-4829-9efc-f76d89150396-S0 at
slave(46)@172.30.2.131:51675 (ip-172-30-2-131.mesosphere.io) for framework
2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at
[email protected]:51675
[17:57:05]W: [Step 11/11] I0324 17:57:05.730049 1834 master.cpp:2891]
Authorizing framework principal '' to launch task 0 as user 'root'
[17:57:05]W: [Step 11/11] I0324 17:57:05.731073 1834 master.hpp:177]
Adding task 0 with resources cpus(*):1; mem(*):1 on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 (ip-172-30-2-131.mesosphere.io)
[17:57:05]W: [Step 11/11] I0324 17:57:05.731160 1834 master.cpp:3773]
Launching task 0 of framework 2574ed73-b254-4829-9efc-f76d89150396-0000
(default) at [email protected]:51675
with resources cpus(*):1; mem(*):1 on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 at slave(46)@172.30.2.131:51675
(ip-172-30-2-131.mesosphere.io)
[17:57:05]W: [Step 11/11] I0324 17:57:05.731400 1829 slave.cpp:1497] Got
assigned task 0 for framework 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:05]W: [Step 11/11] I0324 17:57:05.731499 1829 slave.cpp:5448]
Checkpointing FrameworkInfo to
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/framework.info'
[17:57:05]W: [Step 11/11] I0324 17:57:05.731719 1829 slave.cpp:5459]
Checkpointing framework pid
'[email protected]:51675' to
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/framework.pid'
[17:57:05]W: [Step 11/11] I0324 17:57:05.731758 1832 hierarchical.cpp:890]
Recovered cpus(*):999; mem(*):999; disk(*):15342; ports(*):[31000-32000]
(total: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000],
allocated: cpus(*):1; mem(*):1) on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 from framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:05]W: [Step 11/11] I0324 17:57:05.731803 1832 hierarchical.cpp:927]
Framework 2574ed73-b254-4829-9efc-f76d89150396-0000 filtered slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for 5secs
[17:57:05]W: [Step 11/11] I0324 17:57:05.731899 1829 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[17:57:05]W: [Step 11/11] Trying semicolon-delimited string format instead
[17:57:05]W: [Step 11/11] I0324 17:57:05.732260 1829 slave.cpp:1616]
Launching task 0 for framework 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:05]W: [Step 11/11] I0324 17:57:05.732321 1829 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[17:57:05]W: [Step 11/11] Trying semicolon-delimited string format instead
[17:57:05]W: [Step 11/11] I0324 17:57:05.732815 1829 paths.cpp:528] Trying
to chown
'/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
to user 'root'
[17:57:05]W: [Step 11/11] I0324 17:57:05.736246 1829 slave.cpp:5900]
Checkpointing ExecutorInfo to
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/executor.info'
[17:57:05]W: [Step 11/11] I0324 17:57:05.736605 1829 slave.cpp:5528]
Launching executor 0 of framework 2574ed73-b254-4829-9efc-f76d89150396-0000
with resources cpus(*):0.1; mem(*):32 in work directory
'/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
[17:57:05]W: [Step 11/11] I0324 17:57:05.737045 1830
containerizer.cpp:666] Starting container
'dec4d561-2aee-4468-a2e1-ef0a76586d45' for executor '0' of framework
'2574ed73-b254-4829-9efc-f76d89150396-0000'
[17:57:05]W: [Step 11/11] I0324 17:57:05.737095 1829 slave.cpp:5923]
Checkpointing TaskInfo to
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/tasks/0/task.info'
[17:57:05]W: [Step 11/11] I0324 17:57:05.737313 1829 slave.cpp:1834]
Queuing task '0' for executor '0' of framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:05]W: [Step 11/11] I0324 17:57:05.737398 1829 slave.cpp:881]
Successfully attached file
'/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
[17:57:05]W: [Step 11/11] I0324 17:57:05.741648 1830
linux_launcher.cpp:304] Cloning child process with flags =
[17:57:05]W: [Step 11/11] I0324 17:57:05.743307 1830
containerizer.cpp:1147] Checkpointing executor's forked pid 3809 to
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/pids/forked.pid'
[17:57:05]W: [Step 11/11] I0324 17:57:05.744854 1828 fetcher.cpp:323]
Starting to fetch URIs for container: dec4d561-2aee-4468-a2e1-ef0a76586d45,
directory:
/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45
[17:57:05]W: [Step 11/11] I0324 17:57:05.753646 1828 fetcher.cpp:785]
Fetching URIs using command
'/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
[17:57:06]W: [Step 11/11] I0324 17:57:06.665369 1834
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:06]W: [Step 11/11] I0324 17:57:06.665452 1834
hierarchical.cpp:1487] No resources available to allocate!
[17:57:06]W: [Step 11/11] I0324 17:57:06.665495 1834
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:06]W: [Step 11/11] I0324 17:57:06.665580 1834
hierarchical.cpp:1138] Performed allocation for 1 slaves in 934998ns
[17:57:06]W: [Step 11/11] II0324 17:57:06.855301 3770 exec.cpp:98]
Committing suicide by killing the process group
[17:57:06]W: [Step 11/11] 0324 17:57:06.855304 3774 exec.cpp:98]
Committing suicide by killing the process group
[17:57:06]W: [Step 11/11] I0324 17:57:06.855320 3784 exec.cpp:98]
Committing suicide by killing the process group
[17:57:07]W: [Step 11/11] I0324 17:57:07.667490 1831
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:07]W: [Step 11/11] I0324 17:57:07.667592 1831
hierarchical.cpp:1487] No resources available to allocate!
[17:57:07]W: [Step 11/11] I0324 17:57:07.667650 1831
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:07]W: [Step 11/11] I0324 17:57:07.667773 1831
hierarchical.cpp:1138] Performed allocation for 1 slaves in 1.240959ms
[17:57:08]W: [Step 11/11] WARNING: Logging before InitGoogleLogging() is
written to STDERR
[17:57:08]W: [Step 11/11] I0324 17:57:08.410621 3809 process.cpp:986]
libprocess is initialized on 172.30.2.131:58574 for 8 cpus
[17:57:08]W: [Step 11/11] I0324 17:57:08.411312 3809 logging.cpp:195]
Logging to STDERR
[17:57:08]W: [Step 11/11] I0324 17:57:08.412731 3809 exec.cpp:150]
Version: 0.29.0
[17:57:08]W: [Step 11/11] I0324 17:57:08.418478 3859 exec.cpp:200]
Executor started at: executor(1)@172.30.2.131:58574 with pid 3809
[17:57:08]W: [Step 11/11] I0324 17:57:08.420289 1829 slave.cpp:2779] Got
registration for executor '0' of framework
2574ed73-b254-4829-9efc-f76d89150396-0000 from executor(1)@172.30.2.131:58574
[17:57:08]W: [Step 11/11] I0324 17:57:08.420810 1829 slave.cpp:2865]
Checkpointing executor pid 'executor(1)@172.30.2.131:58574' to
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/pids/libprocess.pid'
[17:57:08]W: [Step 11/11] I0324 17:57:08.422251 3861 exec.cpp:225]
Executor registered on slave 2574ed73-b254-4829-9efc-f76d89150396-S0
[17:57:08]W: [Step 11/11] I0324 17:57:08.422477 1829 slave.cpp:1999]
Sending queued task '0' to executor '0' of framework
2574ed73-b254-4829-9efc-f76d89150396-0000 at executor(1)@172.30.2.131:58574
[17:57:08]W: [Step 11/11] I0324 17:57:08.423581 3861 exec.cpp:237]
Executor::registered took 236929ns
[17:57:08] : [Step 11/11] Registered executor on
ip-172-30-2-131.mesosphere.io
[17:57:08] : [Step 11/11] Starting task 0
[17:57:08]W: [Step 11/11] I0324 17:57:08.423842 3861 exec.cpp:312]
Executor asked to run task '0'
[17:57:08]W: [Step 11/11] I0324 17:57:08.423938 3861 exec.cpp:321]
Executor::launchTask took 73921ns
[17:57:08] : [Step 11/11] Forked command at 3868
[17:57:08] : [Step 11/11] sh -c './mesos-fetcher-test-cmd 0'
[17:57:08]W: [Step 11/11] I0324 17:57:08.426338 3863 exec.cpp:535]
Executor sending status update TASK_RUNNING (UUID:
0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:08]W: [Step 11/11] I0324 17:57:08.427075 1827 slave.cpp:3138]
Handling status update TASK_RUNNING (UUID:
0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of framework
2574ed73-b254-4829-9efc-f76d89150396-0000 from executor(1)@172.30.2.131:58574
[17:57:08]W: [Step 11/11] I0324 17:57:08.428362 1831
status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:08]W: [Step 11/11] I0324 17:57:08.428397 1831
status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of
framework 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:08]W: [Step 11/11] I0324 17:57:08.428829 1831
status_update_manager.cpp:824] Checkpointing UPDATE for status update
TASK_RUNNING (UUID: 0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of
framework 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:08] : [Step 11/11] Command exited with status 0 (pid: 3868)
[17:57:08]W: [Step 11/11] I0324 17:57:08.526938 3861 exec.cpp:535]
Executor sending status update TASK_FINISHED (UUID:
53dcf02a-3319-4f33-9334-9f2e485036ef) for task 0 of framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:08]W: [Step 11/11] I0324 17:57:08.527662 1828 slave.cpp:3138]
Handling status update TASK_FINISHED (UUID:
53dcf02a-3319-4f33-9334-9f2e485036ef) for task 0 of framework
2574ed73-b254-4829-9efc-f76d89150396-0000 from executor(1)@172.30.2.131:58574
[17:57:08]W: [Step 11/11] I0324 17:57:08.528662 1828 slave.cpp:5838]
Terminating task 0
[17:57:08]W: [Step 11/11] I0324 17:57:08.668975 1830
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:08]W: [Step 11/11] I0324 17:57:08.669055 1830
hierarchical.cpp:1487] No resources available to allocate!
[17:57:08]W: [Step 11/11] I0324 17:57:08.669098 1830
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:08]W: [Step 11/11] I0324 17:57:08.669176 1830
hierarchical.cpp:1138] Performed allocation for 1 slaves in 906316ns
[17:57:09]W: [Step 11/11] I0324 17:57:09.530968 1833 slave.cpp:3664]
executor(1)@172.30.2.131:58574 exited
[17:57:09]W: [Step 11/11] I0324 17:57:09.570600 1828
containerizer.cpp:1656] Executor for container
'dec4d561-2aee-4468-a2e1-ef0a76586d45' has exited
[17:57:09]W: [Step 11/11] I0324 17:57:09.570631 1828
containerizer.cpp:1421] Destroying container
'dec4d561-2aee-4468-a2e1-ef0a76586d45'
[17:57:09]W: [Step 11/11] I0324 17:57:09.573117 1829 cgroups.cpp:2427]
Freezing cgroup
/sys/fs/cgroup/freezer/mesos/dec4d561-2aee-4468-a2e1-ef0a76586d45
[17:57:09]W: [Step 11/11] I0324 17:57:09.575049 1828 cgroups.cpp:1409]
Successfully froze cgroup
/sys/fs/cgroup/freezer/mesos/dec4d561-2aee-4468-a2e1-ef0a76586d45 after
1.881856ms
[17:57:09]W: [Step 11/11] I0324 17:57:09.577164 1827 cgroups.cpp:2445]
Thawing cgroup /sys/fs/cgroup/freezer/mesos/dec4d561-2aee-4468-a2e1-ef0a76586d45
[17:57:09]W: [Step 11/11] I0324 17:57:09.579040 1827 cgroups.cpp:1438]
Successfullly thawed cgroup
/sys/fs/cgroup/freezer/mesos/dec4d561-2aee-4468-a2e1-ef0a76586d45 after
1.83296ms
[17:57:09]W: [Step 11/11] I0324 17:57:09.581919 1833 provisioner.cpp:306]
Ignoring destroy request for unknown container
dec4d561-2aee-4468-a2e1-ef0a76586d45
[17:57:09]W: [Step 11/11] I0324 17:57:09.582213 1827 slave.cpp:4039]
Executor '0' of framework 2574ed73-b254-4829-9efc-f76d89150396-0000 exited with
status 0
[17:57:09]W: [Step 11/11] I0324 17:57:09.670363 1832
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:09]W: [Step 11/11] I0324 17:57:09.670410 1832
hierarchical.cpp:1487] No resources available to allocate!
[17:57:09]W: [Step 11/11] I0324 17:57:09.670450 1832
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:09]W: [Step 11/11] I0324 17:57:09.670526 1832
hierarchical.cpp:1138] Performed allocation for 1 slaves in 755961ns
[17:57:10]W: [Step 11/11] I0324 17:57:10.671383 1833
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:10]W: [Step 11/11] I0324 17:57:10.671463 1833
hierarchical.cpp:1487] No resources available to allocate!
[17:57:10]W: [Step 11/11] I0324 17:57:10.671505 1833
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:10]W: [Step 11/11] I0324 17:57:10.671603 1833
hierarchical.cpp:1138] Performed allocation for 1 slaves in 865268ns
[17:57:11]W: [Step 11/11] I0324 17:57:11.673375 1828
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:11]W: [Step 11/11] I0324 17:57:11.673506 1828
hierarchical.cpp:1138] Performed allocation for 1 slaves in 1.052611ms
[17:57:11]W: [Step 11/11] I0324 17:57:11.673781 1827 master.cpp:5508]
Sending 1 offers to framework 2574ed73-b254-4829-9efc-f76d89150396-0000
(default) at [email protected]:51675
[17:57:11]W: [Step 11/11] I0324 17:57:11.674330 1834 sched.cpp:874]
Scheduler::resourceOffers took 137578ns
[17:57:11]W: [Step 11/11] I0324 17:57:11.674687 1827 master.cpp:3825]
Processing DECLINE call for offers: [ 2574ed73-b254-4829-9efc-f76d89150396-O1 ]
for framework 2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at
[email protected]:51675
[17:57:11]W: [Step 11/11] I0324 17:57:11.675212 1834 hierarchical.cpp:890]
Recovered cpus(*):999; mem(*):999; disk(*):15342; ports(*):[31000-32000]
(total: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000],
allocated: cpus(*):1; mem(*):1) on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 from framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:11]W: [Step 11/11] I0324 17:57:11.675263 1834 hierarchical.cpp:927]
Framework 2574ed73-b254-4829-9efc-f76d89150396-0000 filtered slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for 5secs
[17:57:12]W: [Step 11/11] I0324 17:57:12.674986 1832
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:12]W: [Step 11/11] I0324 17:57:12.675068 1832
hierarchical.cpp:1487] No resources available to allocate!
[17:57:12]W: [Step 11/11] I0324 17:57:12.675112 1832
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:12]W: [Step 11/11] I0324 17:57:12.675192 1832
hierarchical.cpp:1138] Performed allocation for 1 slaves in 907825ns
[17:57:13]W: [Step 11/11] I0324 17:57:13.676286 1833
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:13]W: [Step 11/11] I0324 17:57:13.676365 1833
hierarchical.cpp:1487] No resources available to allocate!
[17:57:13]W: [Step 11/11] I0324 17:57:13.676409 1833
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:13]W: [Step 11/11] I0324 17:57:13.676487 1833
hierarchical.cpp:1138] Performed allocation for 1 slaves in 888181ns
[17:57:14]W: [Step 11/11] I0324 17:57:14.678243 1833
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:14]W: [Step 11/11] I0324 17:57:14.678321 1833
hierarchical.cpp:1487] No resources available to allocate!
[17:57:14]W: [Step 11/11] I0324 17:57:14.678377 1833
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:14]W: [Step 11/11] I0324 17:57:14.678460 1833
hierarchical.cpp:1138] Performed allocation for 1 slaves in 883895ns
[17:57:15]W: [Step 11/11] I0324 17:57:15.680117 1828
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:15]W: [Step 11/11] I0324 17:57:15.680197 1828
hierarchical.cpp:1487] No resources available to allocate!
[17:57:15]W: [Step 11/11] I0324 17:57:15.680241 1828
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:15]W: [Step 11/11] I0324 17:57:15.680321 1828
hierarchical.cpp:1138] Performed allocation for 1 slaves in 894275ns
[17:57:16]W: [Step 11/11] I0324 17:57:16.681751 1827
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:16]W: [Step 11/11] I0324 17:57:16.681871 1827
hierarchical.cpp:1138] Performed allocation for 1 slaves in 983355ns
[17:57:16]W: [Step 11/11] I0324 17:57:16.682093 1832 master.cpp:5508]
Sending 1 offers to framework 2574ed73-b254-4829-9efc-f76d89150396-0000
(default) at [email protected]:51675
[17:57:16]W: [Step 11/11] I0324 17:57:16.682575 1828 sched.cpp:874]
Scheduler::resourceOffers took 80669ns
[17:57:16]W: [Step 11/11] I0324 17:57:16.682859 1828 master.cpp:3825]
Processing DECLINE call for offers: [ 2574ed73-b254-4829-9efc-f76d89150396-O2 ]
for framework 2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at
[email protected]:51675
[17:57:16]W: [Step 11/11] I0324 17:57:16.683562 1830 hierarchical.cpp:890]
Recovered cpus(*):999; mem(*):999; disk(*):15342; ports(*):[31000-32000]
(total: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000],
allocated: cpus(*):1; mem(*):1) on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 from framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:16]W: [Step 11/11] I0324 17:57:16.683617 1830 hierarchical.cpp:927]
Framework 2574ed73-b254-4829-9efc-f76d89150396-0000 filtered slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for 5secs
[17:57:17]W: [Step 11/11] I0324 17:57:17.683616 1827
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:17]W: [Step 11/11] I0324 17:57:17.683712 1827
hierarchical.cpp:1487] No resources available to allocate!
[17:57:17]W: [Step 11/11] I0324 17:57:17.683758 1827
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:17]W: [Step 11/11] I0324 17:57:17.683840 1827
hierarchical.cpp:1138] Performed allocation for 1 slaves in 870485ns
[17:57:18]W: [Step 11/11] I0324 17:57:18.685564 1834
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:18]W: [Step 11/11] I0324 17:57:18.685636 1834
hierarchical.cpp:1487] No resources available to allocate!
[17:57:18]W: [Step 11/11] I0324 17:57:18.685675 1834
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:18]W: [Step 11/11] I0324 17:57:18.685780 1834
hierarchical.cpp:1138] Performed allocation for 1 slaves in 822978ns
[17:57:19]W: [Step 11/11] I0324 17:57:19.686969 1832
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:19]W: [Step 11/11] I0324 17:57:19.687032 1832
hierarchical.cpp:1487] No resources available to allocate!
[17:57:19]W: [Step 11/11] I0324 17:57:19.687069 1832
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:19]W: [Step 11/11] I0324 17:57:19.687140 1832
hierarchical.cpp:1138] Performed allocation for 1 slaves in 808659ns
[17:57:20]W: [Step 11/11] I0324 17:57:20.688407 1832
hierarchical.cpp:1673] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 for framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:20]W: [Step 11/11] I0324 17:57:20.688484 1832
hierarchical.cpp:1487] No resources available to allocate!
[17:57:20]W: [Step 11/11] I0324 17:57:20.688524 1832
hierarchical.cpp:1582] No inverse offers to send out!
[17:57:20]W: [Step 11/11] I0324 17:57:20.688611 1832
hierarchical.cpp:1138] Performed allocation for 1 slaves in 835708ns
[17:57:20]W: [Step 11/11] I0324 17:57:20.715385 1834 slave.cpp:4898]
Querying resource estimator for oversubscribable resources
[17:57:20]W: [Step 11/11] I0324 17:57:20.715633 1834 slave.cpp:4912]
Received oversubscribable resources from the resource estimator
[17:57:20]W: [Step 11/11] I0324 17:57:20.723800 1832 slave.cpp:3618]
Received ping from slave-observer(45)@172.30.2.131:51675
[17:57:20] : [Step 11/11] ../../src/tests/fetcher_cache_tests.cpp:617:
Failure
[17:57:20]W: [Step 11/11] I0324 17:57:20.730820 1813 sched.cpp:1904] Asked
to stop the driver
[17:57:20] : [Step 11/11] Failed to wait 15secs for
awaitFinished(task.get())
[17:57:20] : [Step 11/11] Begin listing sandboxes
[17:57:20]W: [Step 11/11] I0324 17:57:20.730908 1833 sched.cpp:1144]
Stopping framework '2574ed73-b254-4829-9efc-f76d89150396-0000'
[17:57:20] : [Step 11/11] Begin listing sandbox
`/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/latest`:
[17:57:20] : [Step 11/11] Begin file contents of `stdout`:
[17:57:20]W: [Step 11/11] I0324 17:57:20.731181 1832 master.cpp:6081]
Processing TEARDOWN call for framework
2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at
[email protected]:51675
[17:57:20] : [Step 11/11]
[17:57:20] : [Step 11/11] End file
[17:57:20]W: [Step 11/11] I0324 17:57:20.731218 1832 master.cpp:6093]
Removing framework 2574ed73-b254-4829-9efc-f76d89150396-0000 (default) at
[email protected]:51675
[17:57:20] : [Step 11/11] Begin file contents of `stderr`:
[17:57:20] : [Step 11/11] I0324 17:57:08.306455 3825 logging.cpp:195]
Logging to STDERR
[17:57:20]W: [Step 11/11] I0324 17:57:20.731464 1834 hierarchical.cpp:375]
Deactivated framework 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:20] : [Step 11/11] I0324 17:57:08.306619 3825 fetcher.cpp:430]
Fetcher Info:
{"cache_directory":"\/tmp\/FetcherCacheTest_LocalUncached_XP781E\/fetch\/slaves\/2574ed73-b254-4829-9efc-f76d89150396-S0\/root","items":[{"action":"BYPASS_CACHE","uri":{"executable":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_LocalUncached_XP781E\/mesos-fetcher-test-assets\/mesos-fetcher-test-cmd"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_LocalUncached_XP781E\/slaves\/2574ed73-b254-4829-9efc-f76d89150396-S0\/frameworks\/2574ed73-b254-4829-9efc-f76d89150396-0000\/executors\/0\/runs\/dec4d561-2aee-4468-a2e1-ef0a76586d45","user":"root"}
[17:57:20]W: [Step 11/11] I0324 17:57:20.731489 1833 slave.cpp:2215] Asked
to shut down framework 2574ed73-b254-4829-9efc-f76d89150396-0000 by
[email protected]:51675
[17:57:20] : [Step 11/11] I0324 17:57:08.312544 3825 fetcher.cpp:385]
Fetching URI
'/tmp/FetcherCacheTest_LocalUncached_XP781E/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
[17:57:20]W: [Step 11/11] I0324 17:57:20.731530 1833 slave.cpp:2240]
Shutting down framework 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:20] : [Step 11/11] I0324 17:57:08.312567 3825 fetcher.cpp:250]
Fetching directly into the sandbox directory
[17:57:20]W: [Step 11/11] I0324 17:57:20.731570 1832 master.cpp:6608]
Updating the state of task 0 of framework
2574ed73-b254-4829-9efc-f76d89150396-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
[17:57:20] : [Step 11/11] I0324 17:57:08.312592 3825 fetcher.cpp:187]
Fetching URI
'/tmp/FetcherCacheTest_LocalUncached_XP781E/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
[17:57:20]W: [Step 11/11] I0324 17:57:20.731607 1833 slave.cpp:4143]
Cleaning up executor '0' of framework 2574ed73-b254-4829-9efc-f76d89150396-0000
at executor(1)@172.30.2.131:58574
[17:57:20] : [Step 11/11] I0324 17:57:08.312630 3825 fetcher.cpp:167]
Copying resource with command:cp
'/tmp/FetcherCacheTest_LocalUncached_XP781E/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
'/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/mesos-fetcher-test-cmd'
[17:57:20] : [Step 11/11] I0324 17:57:08.315564 3825 fetcher.cpp:462]
Fetched
'/tmp/FetcherCacheTest_LocalUncached_XP781E/mesos-fetcher-test-assets/mesos-fetcher-test-cmd'
to
'/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45/mesos-fetcher-test-cmd'
[17:57:20]W: [Step 11/11] I0324 17:57:20.732023 1834 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
for gc 6.99999152859852days in the future
[17:57:20] : [Step 11/11]
[17:57:20] : [Step 11/11] End file
[17:57:20]W: [Step 11/11] I0324 17:57:20.732002 1832 master.cpp:6674]
Removing task 0 with resources cpus(*):1; mem(*):1 of framework
2574ed73-b254-4829-9efc-f76d89150396-0000 on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 at slave(46)@172.30.2.131:51675
(ip-172-30-2-131.mesosphere.io)
[17:57:20] : [Step 11/11] Begin file contents of `mesos-fetcher-test-cmd`:
[17:57:20] : [Step 11/11] touch mesos-fetcher-test-cmd$1
[17:57:20]W: [Step 11/11] I0324 17:57:20.732062 1827 hierarchical.cpp:890]
Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):15342;
ports(*):[31000-32000], allocated: ) on slave
2574ed73-b254-4829-9efc-f76d89150396-S0 from framework
2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:20] : [Step 11/11] End file
[17:57:20] : [Step 11/11] Begin file contents of `mesos-fetcher-test-cmd0`:
[17:57:20] : [Step 11/11]
[17:57:20]W: [Step 11/11] I0324 17:57:20.732177 1834 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0'
for gc 6.99999152667852days in the future
[17:57:20] : [Step 11/11] End file
[17:57:20] : [Step 11/11] End sandbox
[17:57:20]W: [Step 11/11] I0324 17:57:20.732273 1833 slave.cpp:4231]
Cleaning up framework 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:20] : [Step 11/11] End sandboxes
[17:57:20]W: [Step 11/11] I0324 17:57:20.732314 1834 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0/runs/dec4d561-2aee-4468-a2e1-ef0a76586d45'
for gc 6.99999152579852days in the future
[17:57:20]W: [Step 11/11] I0324 17:57:20.732450 1834 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000/executors/0'
for gc 6.99999152519704days in the future
[17:57:20]W: [Step 11/11] I0324 17:57:20.732465 1832 master.cpp:1083]
Master terminating
[17:57:20]W: [Step 11/11] I0324 17:57:20.732508 1827 hierarchical.cpp:326]
Removed framework 2574ed73-b254-4829-9efc-f76d89150396-0000
[17:57:20]W: [Step 11/11] I0324 17:57:20.732548 1834 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_XP781E/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000'
for gc 6.99999152388741days in the future
[17:57:20]W: [Step 11/11] I0324 17:57:20.732643 1834 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_XP781E/meta/slaves/2574ed73-b254-4829-9efc-f76d89150396-S0/frameworks/2574ed73-b254-4829-9efc-f76d89150396-0000'
for gc 6.99999152215407days in the future
[17:57:20]W: [Step 11/11] I0324 17:57:20.732834 1827 hierarchical.cpp:505]
Removed slave 2574ed73-b254-4829-9efc-f76d89150396-S0
[17:57:20]W: [Step 11/11] I0324 17:57:20.733188 1828 slave.cpp:3664]
[email protected]:51675 exited
[17:57:20]W: [Step 11/11] W0324 17:57:20.733211 1828 slave.cpp:3667]
Master disconnected! Waiting for a new master to be elected
[17:57:20]W: [Step 11/11] I0324 17:57:20.737687 1827 slave.cpp:800] Slave
terminating
[17:57:21]W: [Step 11/11] I0324 17:57:21.864037 1831
status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
0c7a33a7-1e10-41f4-8e11-4e016593dc54) for task 0 of framework
2574ed73-b254-4829-9efc-f76d89150396-0000 to the slave
[17:57:21] : [Step 11/11] [ FAILED ] FetcherCacheTest.LocalUncached
(16222 ms)
{code}
Logs from a good previous run
{code}
[12:21:04] : [Step 11/11] [ RUN ] FetcherCacheTest.LocalUncached
[12:21:04]W: [Step 11/11] I0324 12:21:04.567256 1814 cluster.cpp:139]
Creating default 'local' authorizer
[12:21:04]W: [Step 11/11] I0324 12:21:04.571188 1814 leveldb.cpp:174]
Opened db in 3.736423ms
[12:21:04]W: [Step 11/11] I0324 12:21:04.572331 1814 leveldb.cpp:181]
Compacted db in 1.117018ms
[12:21:04]W: [Step 11/11] I0324 12:21:04.572370 1814 leveldb.cpp:196]
Created db iterator in 13259ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.572381 1814 leveldb.cpp:202]
Seeked to beginning of db in 1417ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.572387 1814 leveldb.cpp:271]
Iterated through 0 keys in the db in 270ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.572413 1814 replica.cpp:779]
Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[12:21:04]W: [Step 11/11] I0324 12:21:04.572785 1833 recover.cpp:447]
Starting replica recovery
[12:21:04]W: [Step 11/11] I0324 12:21:04.573035 1833 recover.cpp:473]
Replica is in EMPTY status
[12:21:04]W: [Step 11/11] I0324 12:21:04.573856 1830 replica.cpp:673]
Replica in EMPTY status received a broadcasted recover request from
(1889)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.574309 1832 recover.cpp:193]
Received a recover response from a replica in EMPTY status
[12:21:04]W: [Step 11/11] I0324 12:21:04.574671 1835 recover.cpp:564]
Updating replica status to STARTING
[12:21:04]W: [Step 11/11] I0324 12:21:04.575477 1828 master.cpp:376]
Master bc02c3e1-1349-4721-827f-b111f17ad00d (ip-172-30-2-102.mesosphere.io)
started on 172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.575500 1828 master.cpp:378] Flags
at startup: --acls="" --allocation_interval="1secs"
--allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true"
--authenticate_slaves="true" --authenticators="crammd5" --authorizers="local"
--credentials="/tmp/B6KjIF/credentials" --framework_sorter="drf" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
--max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
--quiet="false" --recovery_slave_removal_limit="100%"
--registry="replicated_log" --registry_fetch_timeout="1mins"
--registry_store_timeout="100secs" --registry_strict="true"
--root_submissions="true" --slave_ping_timeout="15secs"
--slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
--webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/B6KjIF/master"
--zk_session_timeout="10secs"
[12:21:04]W: [Step 11/11] I0324 12:21:04.575721 1828 master.cpp:427]
Master only allowing authenticated frameworks to register
[12:21:04]W: [Step 11/11] I0324 12:21:04.575731 1828 master.cpp:432]
Master only allowing authenticated slaves to register
[12:21:04]W: [Step 11/11] I0324 12:21:04.575736 1828 credentials.hpp:35]
Loading credentials for authentication from '/tmp/B6KjIF/credentials'
[12:21:04]W: [Step 11/11] I0324 12:21:04.575953 1828 master.cpp:474] Using
default 'crammd5' authenticator
[12:21:04]W: [Step 11/11] I0324 12:21:04.576073 1828 master.cpp:545] Using
default 'basic' HTTP authenticator
[12:21:04]W: [Step 11/11] I0324 12:21:04.576164 1830 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 1.327792ms
[12:21:04]W: [Step 11/11] I0324 12:21:04.576186 1830 replica.cpp:320]
Persisted replica status to STARTING
[12:21:04]W: [Step 11/11] I0324 12:21:04.576200 1828 master.cpp:583]
Authorization enabled
[12:21:04]W: [Step 11/11] I0324 12:21:04.576340 1833 hierarchical.cpp:144]
Initialized hierarchical allocator process
[12:21:04]W: [Step 11/11] I0324 12:21:04.576367 1832
whitelist_watcher.cpp:77] No whitelist given
[12:21:04]W: [Step 11/11] I0324 12:21:04.576372 1834 recover.cpp:473]
Replica is in STARTING status
[12:21:04]W: [Step 11/11] I0324 12:21:04.577231 1831 replica.cpp:673]
Replica in STARTING status received a broadcasted recover request from
(1891)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.577499 1830 recover.cpp:193]
Received a recover response from a replica in STARTING status
[12:21:04]W: [Step 11/11] I0324 12:21:04.577994 1835 recover.cpp:564]
Updating replica status to VOTING
[12:21:04]W: [Step 11/11] I0324 12:21:04.578761 1831 master.cpp:1826] The
newly elected leader is [email protected]:40940 with id
bc02c3e1-1349-4721-827f-b111f17ad00d
[12:21:04]W: [Step 11/11] I0324 12:21:04.578784 1831 master.cpp:1839]
Elected as the leading master!
[12:21:04]W: [Step 11/11] I0324 12:21:04.578796 1831 master.cpp:1526]
Recovering from registrar
[12:21:04]W: [Step 11/11] I0324 12:21:04.578905 1830 registrar.cpp:307]
Recovering registrar
[12:21:04]W: [Step 11/11] I0324 12:21:04.579027 1833 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 918129ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.579046 1833 replica.cpp:320]
Persisted replica status to VOTING
[12:21:04]W: [Step 11/11] I0324 12:21:04.579139 1835 recover.cpp:578]
Successfully joined the Paxos group
[12:21:04]W: [Step 11/11] I0324 12:21:04.579337 1835 recover.cpp:462]
Recover process terminated
[12:21:04]W: [Step 11/11] I0324 12:21:04.579701 1830 log.cpp:659]
Attempting to start the writer
[12:21:04]W: [Step 11/11] I0324 12:21:04.580749 1834 replica.cpp:493]
Replica received implicit promise request from (1892)@172.30.2.102:40940 with
proposal 1
[12:21:04]W: [Step 11/11] I0324 12:21:04.581714 1834 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 936238ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.581732 1834 replica.cpp:342]
Persisted promised to 1
[12:21:04]W: [Step 11/11] I0324 12:21:04.582298 1833 coordinator.cpp:238]
Coordinator attempting to fill missing positions
[12:21:04]W: [Step 11/11] I0324 12:21:04.583406 1828 replica.cpp:388]
Replica received explicit promise request from (1893)@172.30.2.102:40940 for
position 0 with proposal 2
[12:21:04]W: [Step 11/11] I0324 12:21:04.584342 1828 leveldb.cpp:341]
Persisting action (8 bytes) to leveldb took 904348ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.584362 1828 replica.cpp:712]
Persisted action at 0
[12:21:04]W: [Step 11/11] I0324 12:21:04.585230 1835 replica.cpp:537]
Replica received write request for position 0 from (1894)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.585275 1835 leveldb.cpp:436]
Reading position from leveldb took 21110ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.586259 1835 leveldb.cpp:341]
Persisting action (14 bytes) to leveldb took 952672ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.586278 1835 replica.cpp:712]
Persisted action at 0
[12:21:04]W: [Step 11/11] I0324 12:21:04.586763 1834 replica.cpp:691]
Replica received learned notice for position 0 from @0.0.0.0:0
[12:21:04]W: [Step 11/11] I0324 12:21:04.587682 1834 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 893753ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.587700 1834 replica.cpp:712]
Persisted action at 0
[12:21:04]W: [Step 11/11] I0324 12:21:04.587714 1834 replica.cpp:697]
Replica learned NOP action at position 0
[12:21:04]W: [Step 11/11] I0324 12:21:04.588202 1828 log.cpp:675] Writer
started with ending position 0
[12:21:04]W: [Step 11/11] I0324 12:21:04.589071 1832 leveldb.cpp:436]
Reading position from leveldb took 28408ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.589875 1828 registrar.cpp:340]
Successfully fetched the registry (0B) in 10.928896ms
[12:21:04]W: [Step 11/11] I0324 12:21:04.589977 1828 registrar.cpp:439]
Applied 1 operations in 22584ns; attempting to update the 'registry'
[12:21:04]W: [Step 11/11] I0324 12:21:04.590565 1835 log.cpp:683]
Attempting to append 210 bytes to the log
[12:21:04]W: [Step 11/11] I0324 12:21:04.590685 1829 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 1
[12:21:04]W: [Step 11/11] I0324 12:21:04.591286 1834 replica.cpp:537]
Replica received write request for position 1 from (1895)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.592260 1834 leveldb.cpp:341]
Persisting action (229 bytes) to leveldb took 940368ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.592279 1834 replica.cpp:712]
Persisted action at 1
[12:21:04]W: [Step 11/11] I0324 12:21:04.592784 1832 replica.cpp:691]
Replica received learned notice for position 1 from @0.0.0.0:0
[12:21:04]W: [Step 11/11] I0324 12:21:04.593720 1832 leveldb.cpp:341]
Persisting action (231 bytes) to leveldb took 912364ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.593739 1832 replica.cpp:712]
Persisted action at 1
[12:21:04]W: [Step 11/11] I0324 12:21:04.593755 1832 replica.cpp:697]
Replica learned APPEND action at position 1
[12:21:04]W: [Step 11/11] I0324 12:21:04.594544 1833 registrar.cpp:484]
Successfully updated the 'registry' in 4.509952ms
[12:21:04]W: [Step 11/11] I0324 12:21:04.594656 1833 registrar.cpp:370]
Successfully recovered registrar
[12:21:04]W: [Step 11/11] I0324 12:21:04.594738 1835 log.cpp:702]
Attempting to truncate the log to 1
[12:21:04]W: [Step 11/11] I0324 12:21:04.594861 1831 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 2
[12:21:04]W: [Step 11/11] I0324 12:21:04.595152 1828 master.cpp:1634]
Recovered 0 slaves from the Registry (171B) ; allowing 10mins for slaves to
re-register
[12:21:04]W: [Step 11/11] I0324 12:21:04.595176 1835 hierarchical.cpp:171]
Skipping recovery of hierarchical allocator: nothing to recover
[12:21:04]W: [Step 11/11] I0324 12:21:04.595652 1832 replica.cpp:537]
Replica received write request for position 2 from (1896)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.596577 1832 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 896605ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.596597 1832 replica.cpp:712]
Persisted action at 2
[12:21:04]W: [Step 11/11] I0324 12:21:04.597105 1828 replica.cpp:691]
Replica received learned notice for position 2 from @0.0.0.0:0
[12:21:04]W: [Step 11/11] I0324 12:21:04.598078 1828 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 943692ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.598124 1828 leveldb.cpp:399]
Deleting ~1 keys from leveldb took 26966ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.598139 1828 replica.cpp:712]
Persisted action at 2
[12:21:04]W: [Step 11/11] I0324 12:21:04.598153 1828 replica.cpp:697]
Replica learned TRUNCATE action at position 2
[12:21:04]W: [Step 11/11] I0324 12:21:04.606338 1814
containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
[12:21:04]W: [Step 11/11] I0324 12:21:04.612812 1814
linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
for the Linux launcher
[12:21:04]W: [Step 11/11] I0324 12:21:04.617058 1835 slave.cpp:199] Slave
started on 46)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.617077 1835 slave.cpp:200] Flags
at startup: --appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
--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_LocalUncached_GCYrPs/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/FetcherCacheTest_LocalUncached_GCYrPs/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="true"
--hostname_lookup="true" --http_authenticators="basic"
--http_credentials="/tmp/FetcherCacheTest_LocalUncached_GCYrPs/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0"
--logging_level="INFO" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:1000;mem:1000" --revocable_cpu_low_priority="true"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/FetcherCacheTest_LocalUncached_GCYrPs"
[12:21:04]W: [Step 11/11] I0324 12:21:04.617379 1835 credentials.hpp:83]
Loading credential for authentication from
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/credential'
[12:21:04]W: [Step 11/11] I0324 12:21:04.617516 1835 slave.cpp:337] Slave
using credential for: test-principal
[12:21:04]W: [Step 11/11] I0324 12:21:04.617538 1835 credentials.hpp:35]
Loading credentials for authentication from
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/http_credentials'
[12:21:04]W: [Step 11/11] I0324 12:21:04.617687 1835 slave.cpp:389] Using
default 'basic' HTTP authenticator
[12:21:04]W: [Step 11/11] I0324 12:21:04.617929 1835 resources.cpp:572]
Parsing resources as JSON failed: cpus:1000;mem:1000
[12:21:04]W: [Step 11/11] Trying semicolon-delimited string format instead
[12:21:04]W: [Step 11/11] I0324 12:21:04.618314 1835 slave.cpp:588] Slave
resources: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000]
[12:21:04]W: [Step 11/11] I0324 12:21:04.618369 1835 slave.cpp:596] Slave
attributes: [ ]
[12:21:04]W: [Step 11/11] I0324 12:21:04.618378 1835 slave.cpp:601] Slave
hostname: ip-172-30-2-102.mesosphere.io
[12:21:04]W: [Step 11/11] I0324 12:21:04.619313 1833 state.cpp:58]
Recovering state from '/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta'
[12:21:04]W: [Step 11/11] I0324 12:21:04.619479 1828
status_update_manager.cpp:200] Recovering status update manager
[12:21:04]W: [Step 11/11] I0324 12:21:04.619710 1832
containerizer.cpp:407] Recovering containerizer
[12:21:04]W: [Step 11/11] I0324 12:21:04.621534 1831 provisioner.cpp:245]
Provisioner recovery complete
[12:21:04]W: [Step 11/11] I0324 12:21:04.621827 1830 slave.cpp:4700]
Finished recovery
[12:21:04]W: [Step 11/11] I0324 12:21:04.622120 1830 slave.cpp:4872]
Querying resource estimator for oversubscribable resources
[12:21:04]W: [Step 11/11] I0324 12:21:04.622316 1831
status_update_manager.cpp:174] Pausing sending status updates
[12:21:04]W: [Step 11/11] I0324 12:21:04.622315 1830 slave.cpp:927] New
master detected at [email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.622382 1830 slave.cpp:990]
Authenticating with master [email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.622397 1830 slave.cpp:995] Using
default CRAM-MD5 authenticatee
[12:21:04]W: [Step 11/11] I0324 12:21:04.622514 1830 slave.cpp:963]
Detecting new master
[12:21:04]W: [Step 11/11] I0324 12:21:04.622555 1834
authenticatee.cpp:121] Creating new client SASL connection
[12:21:04]W: [Step 11/11] I0324 12:21:04.622681 1830 slave.cpp:4886]
Received oversubscribable resources from the resource estimator
[12:21:04]W: [Step 11/11] I0324 12:21:04.622889 1830 master.cpp:5679]
Authenticating slave(46)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.622972 1831
authenticator.cpp:413] Starting authentication session for
crammd5_authenticatee(137)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.623136 1834 authenticator.cpp:98]
Creating new server SASL connection
[12:21:04]W: [Step 11/11] I0324 12:21:04.623353 1830
authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[12:21:04]W: [Step 11/11] I0324 12:21:04.623373 1830
authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[12:21:04]W: [Step 11/11] I0324 12:21:04.623450 1830
authenticator.cpp:203] Received SASL authentication start
[12:21:04]W: [Step 11/11] I0324 12:21:04.623492 1830
authenticator.cpp:325] Authentication requires more steps
[12:21:04]W: [Step 11/11] I0324 12:21:04.623566 1830
authenticatee.cpp:258] Received SASL authentication step
[12:21:04]W: [Step 11/11] I0324 12:21:04.623667 1830
authenticator.cpp:231] Received SASL authentication step
[12:21:04]W: [Step 11/11] I0324 12:21:04.623693 1830 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-102.mesosphere.io' server FQDN: 'ip-172-30-2-102.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[12:21:04]W: [Step 11/11] I0324 12:21:04.623703 1830 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[12:21:04]W: [Step 11/11] I0324 12:21:04.623729 1830 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[12:21:04]W: [Step 11/11] I0324 12:21:04.623749 1830 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-102.mesosphere.io' server FQDN: 'ip-172-30-2-102.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[12:21:04]W: [Step 11/11] I0324 12:21:04.623757 1830 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[12:21:04]W: [Step 11/11] I0324 12:21:04.623762 1830 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[12:21:04]W: [Step 11/11] I0324 12:21:04.623774 1830
authenticator.cpp:317] Authentication success
[12:21:04]W: [Step 11/11] I0324 12:21:04.623845 1833
authenticatee.cpp:298] Authentication success
[12:21:04]W: [Step 11/11] I0324 12:21:04.623888 1828 master.cpp:5709]
Successfully authenticated principal 'test-principal' at
slave(46)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.623942 1829
authenticator.cpp:431] Authentication session cleanup for
crammd5_authenticatee(137)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.624183 1832 slave.cpp:1060]
Successfully authenticated with master [email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.624276 1832 slave.cpp:1456] Will
retry registration in 4.413456ms if necessary
[12:21:04]W: [Step 11/11] I0324 12:21:04.624439 1834 master.cpp:4390]
Registering slave at slave(46)@172.30.2.102:40940
(ip-172-30-2-102.mesosphere.io) with id bc02c3e1-1349-4721-827f-b111f17ad00d-S0
[12:21:04]W: [Step 11/11] I0324 12:21:04.624773 1833 registrar.cpp:439]
Applied 1 operations in 45733ns; attempting to update the 'registry'
[12:21:04]W: [Step 11/11] I0324 12:21:04.625387 1831 log.cpp:683]
Attempting to append 396 bytes to the log
[12:21:04]W: [Step 11/11] I0324 12:21:04.625485 1829 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 3
[12:21:04]W: [Step 11/11] I0324 12:21:04.626085 1835 replica.cpp:537]
Replica received write request for position 3 from (1913)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.627172 1835 leveldb.cpp:341]
Persisting action (415 bytes) to leveldb took 1.049909ms
[12:21:04]W: [Step 11/11] I0324 12:21:04.627197 1835 replica.cpp:712]
Persisted action at 3
[12:21:04]W: [Step 11/11] I0324 12:21:04.627661 1830 replica.cpp:691]
Replica received learned notice for position 3 from @0.0.0.0:0
[12:21:04]W: [Step 11/11] I0324 12:21:04.628654 1830 leveldb.cpp:341]
Persisting action (417 bytes) to leveldb took 965890ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.628672 1830 replica.cpp:712]
Persisted action at 3
[12:21:04]W: [Step 11/11] I0324 12:21:04.628687 1830 replica.cpp:697]
Replica learned APPEND action at position 3
[12:21:04]W: [Step 11/11] I0324 12:21:04.629813 1829 registrar.cpp:484]
Successfully updated the 'registry' in 4.983296ms
[12:21:04]W: [Step 11/11] I0324 12:21:04.629850 1833 slave.cpp:1456] Will
retry registration in 25.88132ms if necessary
[12:21:04]W: [Step 11/11] I0324 12:21:04.629941 1832 master.cpp:4378]
Ignoring register slave message from slave(46)@172.30.2.102:40940
(ip-172-30-2-102.mesosphere.io) as admission is already in progress
[12:21:04]W: [Step 11/11] I0324 12:21:04.629984 1830 log.cpp:702]
Attempting to truncate the log to 3
[12:21:04]W: [Step 11/11] I0324 12:21:04.630095 1833 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 4
[12:21:04]W: [Step 11/11] I0324 12:21:04.630491 1829 slave.cpp:3617]
Received ping from slave-observer(45)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.630549 1828 master.cpp:4458]
Registered slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at
slave(46)@172.30.2.102:40940 (ip-172-30-2-102.mesosphere.io) with cpus(*):1000;
mem(*):1000; disk(*):15342; ports(*):[31000-32000]
[12:21:04]W: [Step 11/11] I0324 12:21:04.630758 1829 slave.cpp:1104]
Registered with master [email protected]:40940; given slave ID
bc02c3e1-1349-4721-827f-b111f17ad00d-S0
[12:21:04]W: [Step 11/11] I0324 12:21:04.630782 1829 fetcher.cpp:81]
Clearing fetcher cache
[12:21:04]W: [Step 11/11] I0324 12:21:04.630846 1833 hierarchical.cpp:473]
Added slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0
(ip-172-30-2-102.mesosphere.io) with cpus(*):1000; mem(*):1000; disk(*):15342;
ports(*):[31000-32000] (allocated: )
[12:21:04]W: [Step 11/11] I0324 12:21:04.630884 1830
status_update_manager.cpp:181] Resuming sending status updates
[12:21:04]W: [Step 11/11] I0324 12:21:04.631034 1833
hierarchical.cpp:1466] No resources available to allocate!
[12:21:04]W: [Step 11/11] I0324 12:21:04.631054 1829 slave.cpp:1127]
Checkpointing SlaveInfo to
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/slave.info'
[12:21:04]W: [Step 11/11] I0324 12:21:04.631098 1833
hierarchical.cpp:1161] Performed allocation for slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 in 208473ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.631265 1829 slave.cpp:1164]
Forwarding total oversubscribed resources
[12:21:04]W: [Step 11/11] I0324 12:21:04.631383 1829 master.cpp:4802]
Received update of slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at
slave(46)@172.30.2.102:40940 (ip-172-30-2-102.mesosphere.io) with total
oversubscribed resources
[12:21:04]W: [Step 11/11] I0324 12:21:04.631742 1829 hierarchical.cpp:531]
Slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0 (ip-172-30-2-102.mesosphere.io)
updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000;
disk(*):15342; ports(*):[31000-32000], allocated: )
[12:21:04]W: [Step 11/11] I0324 12:21:04.631842 1829
hierarchical.cpp:1466] No resources available to allocate!
[12:21:04]W: [Step 11/11] I0324 12:21:04.631886 1829
hierarchical.cpp:1161] Performed allocation for slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 in 114128ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.632283 1831 replica.cpp:537]
Replica received write request for position 4 from (1914)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.632951 1814 sched.cpp:222]
Version: 0.29.0
[12:21:04]W: [Step 11/11] I0324 12:21:04.633296 1831 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 976640ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.633316 1831 replica.cpp:712]
Persisted action at 4
[12:21:04]W: [Step 11/11] I0324 12:21:04.633411 1833 sched.cpp:326] New
master detected at [email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.633487 1833 sched.cpp:382]
Authenticating with master [email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.633502 1833 sched.cpp:389] Using
default CRAM-MD5 authenticatee
[12:21:04]W: [Step 11/11] I0324 12:21:04.633780 1830
authenticatee.cpp:121] Creating new client SASL connection
[12:21:04]W: [Step 11/11] I0324 12:21:04.633889 1833 replica.cpp:691]
Replica received learned notice for position 4 from @0.0.0.0:0
[12:21:04]W: [Step 11/11] I0324 12:21:04.634055 1834 master.cpp:5679]
Authenticating [email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.634155 1829
authenticator.cpp:413] Starting authentication session for
crammd5_authenticatee(138)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.634340 1835 authenticator.cpp:98]
Creating new server SASL connection
[12:21:04]W: [Step 11/11] I0324 12:21:04.634572 1830
authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
[12:21:04]W: [Step 11/11] I0324 12:21:04.634593 1830
authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
[12:21:04]W: [Step 11/11] I0324 12:21:04.634670 1830
authenticator.cpp:203] Received SASL authentication start
[12:21:04]W: [Step 11/11] I0324 12:21:04.634707 1830
authenticator.cpp:325] Authentication requires more steps
[12:21:04]W: [Step 11/11] I0324 12:21:04.634778 1830
authenticatee.cpp:258] Received SASL authentication step
[12:21:04]W: [Step 11/11] I0324 12:21:04.634822 1833 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 901985ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.634884 1828
authenticator.cpp:231] Received SASL authentication step
[12:21:04]W: [Step 11/11] I0324 12:21:04.634887 1833 leveldb.cpp:399]
Deleting ~2 keys from leveldb took 39949ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.634909 1833 replica.cpp:712]
Persisted action at 4
[12:21:04]W: [Step 11/11] I0324 12:21:04.634908 1828 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-102.mesosphere.io' server FQDN: 'ip-172-30-2-102.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[12:21:04]W: [Step 11/11] I0324 12:21:04.634920 1828 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[12:21:04]W: [Step 11/11] I0324 12:21:04.634927 1833 replica.cpp:697]
Replica learned TRUNCATE action at position 4
[12:21:04]W: [Step 11/11] I0324 12:21:04.634944 1828 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[12:21:04]W: [Step 11/11] I0324 12:21:04.634963 1828 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-102.mesosphere.io' server FQDN: 'ip-172-30-2-102.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[12:21:04]W: [Step 11/11] I0324 12:21:04.634973 1828 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[12:21:04]W: [Step 11/11] I0324 12:21:04.634977 1828 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[12:21:04]W: [Step 11/11] I0324 12:21:04.634987 1828
authenticator.cpp:317] Authentication success
[12:21:04]W: [Step 11/11] I0324 12:21:04.635072 1835
authenticatee.cpp:298] Authentication success
[12:21:04]W: [Step 11/11] I0324 12:21:04.635123 1829 master.cpp:5709]
Successfully authenticated principal 'test-principal' at
[email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.635221 1835
authenticator.cpp:431] Authentication session cleanup for
crammd5_authenticatee(138)@172.30.2.102:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.635397 1832 sched.cpp:472]
Successfully authenticated with master [email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.635418 1832 sched.cpp:777]
Sending SUBSCRIBE call to [email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.635510 1832 sched.cpp:810] Will
retry registration in 160.331175ms if necessary
[12:21:04]W: [Step 11/11] I0324 12:21:04.635594 1833 master.cpp:2346]
Received SUBSCRIBE call for framework 'default' at
[email protected]:40940
[12:21:04]W: [Step 11/11] W0324 12:21:04.635619 1833 master.cpp:2353]
Framework at [email protected]:40940
(authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
[12:21:04]W: [Step 11/11] I0324 12:21:04.635656 1833 master.cpp:1865]
Authorizing framework principal '' to receive offers for role '*'
[12:21:04]W: [Step 11/11] I0324 12:21:04.635871 1828 master.cpp:2417]
Subscribing framework default with checkpointing enabled and capabilities [ ]
[12:21:04]W: [Step 11/11] I0324 12:21:04.636237 1830 hierarchical.cpp:265]
Added framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:04]W: [Step 11/11] I0324 12:21:04.636337 1829 sched.cpp:704]
Framework registered with bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:04]W: [Step 11/11] I0324 12:21:04.636379 1829 sched.cpp:718]
Scheduler::registered took 19088ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.636812 1830
hierarchical.cpp:1561] No inverse offers to send out!
[12:21:04]W: [Step 11/11] I0324 12:21:04.636881 1830
hierarchical.cpp:1138] Performed allocation for 1 slaves in 623607ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.637100 1828 master.cpp:5508]
Sending 1 offers to framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
(default) at [email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.637449 1828 sched.cpp:874]
Scheduler::resourceOffers took 95352ns
[12:21:04]W: [Step 11/11] I0324 12:21:04.637784 1814 resources.cpp:572]
Parsing resources as JSON failed: cpus:1;mem:1
[12:21:04]W: [Step 11/11] Trying semicolon-delimited string format instead
[12:21:04]W: [Step 11/11] I0324 12:21:04.638835 1831 master.cpp:3288]
Processing ACCEPT call for offers: [ bc02c3e1-1349-4721-827f-b111f17ad00d-O0 ]
on slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at
slave(46)@172.30.2.102:40940 (ip-172-30-2-102.mesosphere.io) for framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at
[email protected]:40940
[12:21:04]W: [Step 11/11] I0324 12:21:04.638870 1831 master.cpp:2891]
Authorizing framework principal '' to launch task 0 as user 'root'
[12:21:04]W: [Step 11/11] I0324 12:21:04.639928 1831 master.hpp:177]
Adding task 0 with resources cpus(*):1; mem(*):1 on slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 (ip-172-30-2-102.mesosphere.io)
[12:21:04]W: [Step 11/11] I0324 12:21:04.640027 1831 master.cpp:3773]
Launching task 0 of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
(default) at [email protected]:40940
with resources cpus(*):1; mem(*):1 on slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at slave(46)@172.30.2.102:40940
(ip-172-30-2-102.mesosphere.io)
[12:21:04]W: [Step 11/11] I0324 12:21:04.640288 1828 slave.cpp:1496] Got
assigned task 0 for framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:04]W: [Step 11/11] I0324 12:21:04.640427 1828 slave.cpp:5422]
Checkpointing FrameworkInfo to
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/framework.info'
[12:21:04]W: [Step 11/11] I0324 12:21:04.640698 1828 slave.cpp:5433]
Checkpointing framework pid
'[email protected]:40940' to
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/framework.pid'
[12:21:04]W: [Step 11/11] I0324 12:21:04.640852 1830 hierarchical.cpp:890]
Recovered cpus(*):999; mem(*):999; disk(*):15342; ports(*):[31000-32000]
(total: cpus(*):1000; mem(*):1000; disk(*):15342; ports(*):[31000-32000],
allocated: cpus(*):1; mem(*):1) on slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 from framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:04]W: [Step 11/11] I0324 12:21:04.640918 1828 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[12:21:04]W: [Step 11/11] Trying semicolon-delimited string format instead
[12:21:04]W: [Step 11/11] I0324 12:21:04.640920 1830 hierarchical.cpp:927]
Framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 filtered slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 for 5secs
[12:21:04]W: [Step 11/11] I0324 12:21:04.641340 1828 slave.cpp:1615]
Launching task 0 for framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:04]W: [Step 11/11] I0324 12:21:04.641399 1828 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[12:21:04]W: [Step 11/11] Trying semicolon-delimited string format instead
[12:21:04]W: [Step 11/11] I0324 12:21:04.641849 1828 paths.cpp:528] Trying
to chown
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
to user 'root'
[12:21:04]W: [Step 11/11] I0324 12:21:04.645509 1828 slave.cpp:5874]
Checkpointing ExecutorInfo to
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/executor.info'
[12:21:04]W: [Step 11/11] I0324 12:21:04.645871 1828 slave.cpp:5502]
Launching executor 0 of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
with resources cpus(*):0.1; mem(*):32 in work directory
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
[12:21:04]W: [Step 11/11] I0324 12:21:04.646260 1831
containerizer.cpp:666] Starting container
'379d8df6-a66d-4b37-990b-8295d2f9fe51' for executor '0' of framework
'bc02c3e1-1349-4721-827f-b111f17ad00d-0000'
[12:21:04]W: [Step 11/11] I0324 12:21:04.646313 1828 slave.cpp:5897]
Checkpointing TaskInfo to
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51/tasks/0/task.info'
[12:21:04]W: [Step 11/11] I0324 12:21:04.646567 1828 slave.cpp:1833]
Queuing task '0' for executor '0' of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:04]W: [Step 11/11] I0324 12:21:04.646651 1828 slave.cpp:880]
Successfully attached file
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
[12:21:04]W: [Step 11/11] I0324 12:21:04.650753 1831
linux_launcher.cpp:304] Cloning child process with flags =
[12:21:04]W: [Step 11/11] I0324 12:21:04.652362 1831
containerizer.cpp:1147] Checkpointing executor's forked pid 3810 to
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51/pids/forked.pid'
[12:21:04]W: [Step 11/11] I0324 12:21:04.653764 1830 fetcher.cpp:323]
Starting to fetch URIs for container: 379d8df6-a66d-4b37-990b-8295d2f9fe51,
directory:
/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51
[12:21:04]W: [Step 11/11] I0324 12:21:04.663184 1830 fetcher.cpp:785]
Fetching URIs using command
'/mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-fetcher'
[12:21:05]W: [Step 11/11] I0324 12:21:05.578089 1832
hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 for framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:05]W: [Step 11/11] I0324 12:21:05.578176 1832
hierarchical.cpp:1466] No resources available to allocate!
[12:21:05]W: [Step 11/11] I0324 12:21:05.578214 1832
hierarchical.cpp:1561] No inverse offers to send out!
[12:21:05]W: [Step 11/11] I0324 12:21:05.578284 1832
hierarchical.cpp:1138] Performed allocation for 1 slaves in 815775ns
[12:21:06]W: [Step 11/11] I0324 12:21:06.579536 1831
hierarchical.cpp:1652] Filtered offer with cpus(*):999; mem(*):999;
disk(*):15342; ports(*):[31000-32000] on slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 for framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.579607 1831
hierarchical.cpp:1466] No resources available to allocate!
[12:21:06]W: [Step 11/11] I0324 12:21:06.579643 1831
hierarchical.cpp:1561] No inverse offers to send out!
[12:21:06]W: [Step 11/11] I0324 12:21:06.579723 1831
hierarchical.cpp:1138] Performed allocation for 1 slaves in 724631ns
[12:21:06]W: [Step 11/11] I0324 12:21:06.760300 3775 exec.cpp:98]
Committing suicide by killing the process group
[12:21:06]W: [Step 11/11] I0324 12:21:06.764399 3768 exec.cpp:98]
Committing suicide by killing the process group
[12:21:06]W: [Step 11/11] I0324 12:21:06.764401 3774 exec.cpp:98]
Committing suicide by killing the process group
[12:21:06]W: [Step 11/11] WARNING: Logging before InitGoogleLogging() is
written to STDERR
[12:21:06]W: [Step 11/11] I0324 12:21:06.835119 3810 process.cpp:986]
libprocess is initialized on 172.30.2.102:37168 for 8 cpus
[12:21:06]W: [Step 11/11] I0324 12:21:06.835714 3810 logging.cpp:195]
Logging to STDERR
[12:21:06]W: [Step 11/11] I0324 12:21:06.837157 3810 exec.cpp:150]
Version: 0.29.0
[12:21:06]W: [Step 11/11] I0324 12:21:06.842833 3865 exec.cpp:200]
Executor started at: executor(1)@172.30.2.102:37168 with pid 3810
[12:21:06]W: [Step 11/11] I0324 12:21:06.844568 1835 slave.cpp:2778] Got
registration for executor '0' of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from executor(1)@172.30.2.102:37168
[12:21:06]W: [Step 11/11] I0324 12:21:06.844990 1835 slave.cpp:2864]
Checkpointing executor pid 'executor(1)@172.30.2.102:37168' to
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51/pids/libprocess.pid'
[12:21:06]W: [Step 11/11] I0324 12:21:06.846287 3867 exec.cpp:225]
Executor registered on slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0
[12:21:06]W: [Step 11/11] I0324 12:21:06.846424 1828 slave.cpp:1998]
Sending queued task '0' to executor '0' of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 at executor(1)@172.30.2.102:37168
[12:21:06]W: [Step 11/11] I0324 12:21:06.847616 3867 exec.cpp:237]
Executor::registered took 221040ns
[12:21:06] : [Step 11/11] Registered executor on
ip-172-30-2-102.mesosphere.io
[12:21:06] : [Step 11/11] Starting task 0
[12:21:06] : [Step 11/11] Forked command at 3869
[12:21:06] : [Step 11/11] sh -c './mesos-fetcher-test-cmd 0'
[12:21:06]W: [Step 11/11] I0324 12:21:06.847834 3867 exec.cpp:312]
Executor asked to run task '0'
[12:21:06]W: [Step 11/11] I0324 12:21:06.847920 3867 exec.cpp:321]
Executor::launchTask took 67647ns
[12:21:06]W: [Step 11/11] I0324 12:21:06.850314 3860 exec.cpp:535]
Executor sending status update TASK_RUNNING (UUID:
edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.851021 1832 slave.cpp:3137]
Handling status update TASK_RUNNING (UUID:
edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from executor(1)@172.30.2.102:37168
[12:21:06]W: [Step 11/11] I0324 12:21:06.852288 1830
status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.852325 1830
status_update_manager.cpp:497] Creating StatusUpdate stream for task 0 of
framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.852639 1830
status_update_manager.cpp:824] Checkpointing UPDATE for status update
TASK_RUNNING (UUID: edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of
framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.855361 1830
status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to the slave
[12:21:06]W: [Step 11/11] I0324 12:21:06.855587 1829 slave.cpp:3535]
Forwarding the update TASK_RUNNING (UUID: edf46287-7b64-4e88-acba-b13d0df48d76)
for task 0 of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to
[email protected]:40940
[12:21:06]W: [Step 11/11] I0324 12:21:06.855747 1829 slave.cpp:3429]
Status update manager successfully handled status update TASK_RUNNING (UUID:
edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.855793 1829 slave.cpp:3445]
Sending acknowledgement for status update TASK_RUNNING (UUID:
edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to executor(1)@172.30.2.102:37168
[12:21:06]W: [Step 11/11] I0324 12:21:06.855891 1831 master.cpp:4947]
Status update TASK_RUNNING (UUID: edf46287-7b64-4e88-acba-b13d0df48d76) for
task 0 of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at slave(46)@172.30.2.102:40940
(ip-172-30-2-102.mesosphere.io)
[12:21:06]W: [Step 11/11] I0324 12:21:06.855934 1831 master.cpp:4995]
Forwarding status update TASK_RUNNING (UUID:
edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.856156 1831 master.cpp:6608]
Updating the state of task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
[12:21:06]W: [Step 11/11] I0324 12:21:06.856299 3862 exec.cpp:358]
Executor received status update acknowledgement
edf46287-7b64-4e88-acba-b13d0df48d76 for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.856359 1833 sched.cpp:982]
Scheduler::statusUpdate took 128769ns
[12:21:06]W: [Step 11/11] I0324 12:21:06.856580 1835 master.cpp:4102]
Processing ACKNOWLEDGE call edf46287-7b64-4e88-acba-b13d0df48d76 for task 0 of
framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at
[email protected]:40940 on slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0
[12:21:06]W: [Step 11/11] I0324 12:21:06.856812 1835
status_update_manager.cpp:392] Received status update acknowledgement (UUID:
edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.856919 1835
status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING
(UUID: edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.859555 1834 slave.cpp:2547]
Status update manager successfully handled status update acknowledgement (UUID:
edf46287-7b64-4e88-acba-b13d0df48d76) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06] : [Step 11/11] Command exited with status 0 (pid: 3869)
[12:21:06]W: [Step 11/11] I0324 12:21:06.951278 3866 exec.cpp:535]
Executor sending status update TASK_FINISHED (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.951813 1833 slave.cpp:3137]
Handling status update TASK_FINISHED (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from executor(1)@172.30.2.102:37168
[12:21:06]W: [Step 11/11] I0324 12:21:06.952723 1829 slave.cpp:5812]
Terminating task 0
[12:21:06]W: [Step 11/11] I0324 12:21:06.953763 1832
status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.953805 1832
status_update_manager.cpp:824] Checkpointing UPDATE for status update
TASK_FINISHED (UUID: eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of
framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.955874 1832
status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to the slave
[12:21:06]W: [Step 11/11] I0324 12:21:06.956120 1828 slave.cpp:3535]
Forwarding the update TASK_FINISHED (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to [email protected]:40940
[12:21:06]W: [Step 11/11] I0324 12:21:06.956321 1828 slave.cpp:3429]
Status update manager successfully handled status update TASK_FINISHED (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.956365 1828 slave.cpp:3445]
Sending acknowledgement for status update TASK_FINISHED (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 to executor(1)@172.30.2.102:37168
[12:21:06]W: [Step 11/11] I0324 12:21:06.956405 1830 master.cpp:4947]
Status update TASK_FINISHED (UUID: eec13fa8-9db6-4140-97b2-150a4a5f7e02) for
task 0 of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 from slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at slave(46)@172.30.2.102:40940
(ip-172-30-2-102.mesosphere.io)
[12:21:06]W: [Step 11/11] I0324 12:21:06.956439 1830 master.cpp:4995]
Forwarding status update TASK_FINISHED (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.956568 1830 master.cpp:6608]
Updating the state of task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (latest state: TASK_FINISHED, status
update state: TASK_FINISHED)
[12:21:06]W: [Step 11/11] I0324 12:21:06.956862 3864 exec.cpp:358]
Executor received status update acknowledgement
eec13fa8-9db6-4140-97b2-150a4a5f7e02 for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.956899 1828 sched.cpp:982]
Scheduler::statusUpdate took 217593ns
[12:21:06]W: [Step 11/11] I0324 12:21:06.957033 1835 hierarchical.cpp:890]
Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):15342;
ports(*):[31000-32000], allocated: ) on slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 from framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.957149 1833 master.cpp:4102]
Processing ACKNOWLEDGE call eec13fa8-9db6-4140-97b2-150a4a5f7e02 for task 0 of
framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at
[email protected]:40940 on slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0
[12:21:06]W: [Step 11/11] I0324 12:21:06.957195 1833 master.cpp:6674]
Removing task 0 with resources cpus(*):1; mem(*):1 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 on slave
bc02c3e1-1349-4721-827f-b111f17ad00d-S0 at slave(46)@172.30.2.102:40940
(ip-172-30-2-102.mesosphere.io)
[12:21:06]W: [Step 11/11] I0324 12:21:06.957273 1814 sched.cpp:1904] Asked
to stop the driver
[12:21:06]W: [Step 11/11] I0324 12:21:06.957351 1828 sched.cpp:1144]
Stopping framework 'bc02c3e1-1349-4721-827f-b111f17ad00d-0000'
[12:21:06]W: [Step 11/11] I0324 12:21:06.957505 1831
status_update_manager.cpp:392] Received status update acknowledgement (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.957535 1833 master.cpp:6081]
Processing TEARDOWN call for framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at
[email protected]:40940
[12:21:06]W: [Step 11/11] I0324 12:21:06.957566 1833 master.cpp:6093]
Removing framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 (default) at
[email protected]:40940
[12:21:06]W: [Step 11/11] I0324 12:21:06.957608 1831
status_update_manager.cpp:824] Checkpointing ACK for status update
TASK_FINISHED (UUID: eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of
framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.957799 1829 hierarchical.cpp:375]
Deactivated framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.957862 1830 slave.cpp:2214] Asked
to shut down framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 by
[email protected]:40940
[12:21:06]W: [Step 11/11] I0324 12:21:06.957890 1830 slave.cpp:2239]
Shutting down framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.957936 1830 slave.cpp:4333]
Shutting down executor '0' of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000 at executor(1)@172.30.2.102:37168
[12:21:06]W: [Step 11/11] I0324 12:21:06.958137 1833 master.cpp:1083]
Master terminating
[12:21:06]W: [Step 11/11] I0324 12:21:06.958210 1835 hierarchical.cpp:326]
Removed framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.958403 3865 exec.cpp:399]
Executor asked to shutdown
[12:21:06]W: [Step 11/11] I0324 12:21:06.958534 3865 exec.cpp:414]
Executor::shutdown took 17709ns
[12:21:06]W: [Step 11/11] I0324 12:21:06.958570 3865 exec.cpp:91]
Scheduling shutdown of the executor in 5secs
[12:21:06]W: [Step 11/11] I0324 12:21:06.958643 1835 hierarchical.cpp:505]
Removed slave bc02c3e1-1349-4721-827f-b111f17ad00d-S0
[12:21:06]W: [Step 11/11] I0324 12:21:06.958860 1835 slave.cpp:3663]
[email protected]:40940 exited
[12:21:06]W: [Step 11/11] W0324 12:21:06.958878 1835 slave.cpp:3666]
Master disconnected! Waiting for a new master to be elected
[12:21:06]W: [Step 11/11] I0324 12:21:06.959537 1831
status_update_manager.cpp:528] Cleaning up status update stream for task 0 of
framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.959825 1830 slave.cpp:2547]
Status update manager successfully handled status update acknowledgement (UUID:
eec13fa8-9db6-4140-97b2-150a4a5f7e02) for task 0 of framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.959870 1830 slave.cpp:5853]
Completing task 0
[12:21:06]W: [Step 11/11] I0324 12:21:06.962960 1833
containerizer.cpp:1421] Destroying container
'379d8df6-a66d-4b37-990b-8295d2f9fe51'
[12:21:06]W: [Step 11/11] I0324 12:21:06.965121 1829 cgroups.cpp:2427]
Freezing cgroup
/sys/fs/cgroup/freezer/mesos/379d8df6-a66d-4b37-990b-8295d2f9fe51
[12:21:06]W: [Step 11/11] I0324 12:21:06.967097 1830 cgroups.cpp:1409]
Successfully froze cgroup
/sys/fs/cgroup/freezer/mesos/379d8df6-a66d-4b37-990b-8295d2f9fe51 after
1.923072ms
[12:21:06]W: [Step 11/11] I0324 12:21:06.969279 1828 cgroups.cpp:2445]
Thawing cgroup /sys/fs/cgroup/freezer/mesos/379d8df6-a66d-4b37-990b-8295d2f9fe51
[12:21:06]W: [Step 11/11] I0324 12:21:06.971179 1828 cgroups.cpp:1438]
Successfullly thawed cgroup
/sys/fs/cgroup/freezer/mesos/379d8df6-a66d-4b37-990b-8295d2f9fe51 after
1.859072ms
[12:21:06]W: [Step 11/11] I0324 12:21:06.972476 1831 slave.cpp:3663]
executor(1)@172.30.2.102:37168 exited
[12:21:06]W: [Step 11/11] I0324 12:21:06.989403 1829
containerizer.cpp:1656] Executor for container
'379d8df6-a66d-4b37-990b-8295d2f9fe51' has exited
[12:21:06]W: [Step 11/11] I0324 12:21:06.991936 1834 provisioner.cpp:306]
Ignoring destroy request for unknown container
379d8df6-a66d-4b37-990b-8295d2f9fe51
[12:21:06]W: [Step 11/11] I0324 12:21:06.992169 1830 slave.cpp:4021]
Executor '0' of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000 terminated
with signal Killed
[12:21:06]W: [Step 11/11] I0324 12:21:06.992208 1830 slave.cpp:4125]
Cleaning up executor '0' of framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
at executor(1)@172.30.2.102:37168
[12:21:06]W: [Step 11/11] I0324 12:21:06.992606 1835 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
for gc 6.99998851291556days in the future
[12:21:06]W: [Step 11/11] I0324 12:21:06.992734 1835 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0'
for gc 6.99998851076444days in the future
[12:21:06]W: [Step 11/11] I0324 12:21:06.992883 1835 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0/runs/379d8df6-a66d-4b37-990b-8295d2f9fe51'
for gc 6.99998850980148days in the future
[12:21:06]W: [Step 11/11] I0324 12:21:06.992899 1830 slave.cpp:4213]
Cleaning up framework bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.992959 1835 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000/executors/0'
for gc 6.99998850917926days in the future
[12:21:06]W: [Step 11/11] I0324 12:21:06.992996 1833
status_update_manager.cpp:282] Closing status update streams for framework
bc02c3e1-1349-4721-827f-b111f17ad00d-0000
[12:21:06]W: [Step 11/11] I0324 12:21:06.993069 1835 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000'
for gc 6.9999885072563days in the future
[12:21:06]W: [Step 11/11] I0324 12:21:06.993089 1830 slave.cpp:799] Slave
terminating
[12:21:06]W: [Step 11/11] I0324 12:21:06.993139 1835 gc.cpp:55] Scheduling
'/tmp/FetcherCacheTest_LocalUncached_GCYrPs/meta/slaves/bc02c3e1-1349-4721-827f-b111f17ad00d-S0/frameworks/bc02c3e1-1349-4721-827f-b111f17ad00d-0000'
for gc 6.99998850644741days in the future
[12:21:06] : [Step 11/11] [ OK ] FetcherCacheTest.LocalUncached (2438
ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
