[
https://issues.apache.org/jira/browse/MESOS-2857?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15032801#comment-15032801
]
Vinod Kone commented on MESOS-2857:
-----------------------------------
Saw this race on internal CI yesterday.
{code}
10:05:12 DEBUG: [ RUN ] FetcherCacheTest.LocalCachedExtract
10:05:12 DEBUG: I1130 10:05:13.218214 9792 leveldb.cpp:174] Opened db in
302.625107ms
10:05:12 DEBUG: I1130 10:05:13.268728 9792 leveldb.cpp:181] Compacted db in
50.458314ms
10:05:12 DEBUG: I1130 10:05:13.268771 9792 leveldb.cpp:196] Created db
iterator in 4893ns
10:05:12 DEBUG: I1130 10:05:13.268782 9792 leveldb.cpp:202] Seeked to
beginning of db in 1065ns
10:05:12 DEBUG: I1130 10:05:13.268789 9792 leveldb.cpp:271] Iterated through 0
keys in the db in 298ns
10:05:12 DEBUG: I1130 10:05:13.268808 9792 replica.cpp:778] Replica recovered
with log positions 0 -> 0 with 1 holes and 0 unlearned
10:05:12 DEBUG: I1130 10:05:13.269567 9816 recover.cpp:447] Starting replica
recovery
10:05:12 DEBUG: I1130 10:05:13.270217 9820 recover.cpp:473] Replica is in
EMPTY status
10:05:12 DEBUG: I1130 10:05:13.271378 9807 replica.cpp:674] Replica in EMPTY
status received a broadcasted recover request from (1320)@a.b.c.d:40352
10:05:12 DEBUG: I1130 10:05:13.271661 9825 recover.cpp:193] Received a recover
response from a replica in EMPTY status
10:05:12 DEBUG: I1130 10:05:13.271924 9821 master.cpp:365] Master
05e0d28f-8553-4b91-9e6a-92178b625151 (xxx) started on a.b.c.d:40352
10:05:12 DEBUG: I1130 10:05:13.271946 9821 master.cpp:367] Flags at startup:
--acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF"
--authenticate="true" --authenticate_slaves="true" --authenti
cators="crammd5" --authorizers="local" --credentials="/tmp/rxUbld/credentials"
--framework_sorter="drf" --help="false" --hostname_lookup="true"
--initialize_driver_logging="true" --log_auto_initialize="true" -
-logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5"
--quiet="false" --recovery_slave_removal_limit="100%"
--registry="replicated_log" --registry_fetch_timeout="1mins"
--registry_store_timeout=
"25secs" --registry_strict="true" --root_submissions="true"
--slave_ping_timeout="15secs" --slave_reregister_timeout="10mins"
--user_sorter="drf" --version="false"
--webui_dir="/usr/local/share/mesos/webui" --
work_dir="/tmp/rxUbld/master" --zk_session_timeout="10secs"
10:05:12 DEBUG: I1130 10:05:13.272141 9821 master.cpp:412] Master only
allowing authenticated frameworks to register
10:05:12 DEBUG: I1130 10:05:13.272152 9821 master.cpp:417] Master only
allowing authenticated slaves to register
10:05:12 DEBUG: I1130 10:05:13.272161 9821 credentials.hpp:35] Loading
credentials for authentication from '/tmp/rxUbld/credentials'
10:05:12 DEBUG: I1130 10:05:13.272320 9821 master.cpp:456] Using default
'crammd5' authenticator
10:05:12 DEBUG: I1130 10:05:13.272537 9821 master.cpp:493] Authorization
enabled
10:05:12 DEBUG: I1130 10:05:13.273155 9828 recover.cpp:564] Updating replica
status to STARTING
10:05:12 DEBUG: I1130 10:05:13.273895 9815 master.cpp:1637] The newly elected
leader is [email protected]:40352 with id 05e0d28f-8553-4b91-9e6a-92178b625151
10:05:12 DEBUG: I1130 10:05:13.273913 9815 master.cpp:1650] Elected as the
leading master!
10:05:12 DEBUG: I1130 10:05:13.273921 9815 master.cpp:1395] Recovering from
registrar
10:05:12 DEBUG: I1130 10:05:13.273975 9828 registrar.cpp:307] Recovering
registrar
10:05:12 DEBUG: I1130 10:05:13.318963 9811 leveldb.cpp:304] Persisting
metadata (8 bytes) to leveldb took 45.545497ms
10:05:12 DEBUG: I1130 10:05:13.319025 9811 replica.cpp:321] Persisted replica
status to STARTING
10:05:12 DEBUG: I1130 10:05:13.319125 9811 recover.cpp:473] Replica is in
STARTING status
10:05:12 DEBUG: I1130 10:05:13.320819 9829 replica.cpp:674] Replica in
STARTING status received a broadcasted recover request from (1321)@a.b.c.d:40352
10:05:12 DEBUG: I1130 10:05:13.320937 9829 recover.cpp:193] Received a recover
response from a replica in STARTING status
10:05:12 DEBUG: I1130 10:05:13.321111 9815 recover.cpp:564] Updating replica
status to VOTING
10:05:13 DEBUG: I1130 10:05:13.486315 9810 leveldb.cpp:304] Persisting
metadata (8 bytes) to leveldb took 165.03888ms
10:05:13 DEBUG: I1130 10:05:13.486377 9810 replica.cpp:321] Persisted replica
status to VOTING
10:05:13 DEBUG: I1130 10:05:13.486454 9810 recover.cpp:578] Successfully
joined the Paxos group
10:05:13 DEBUG: I1130 10:05:13.486513 9810 recover.cpp:462] Recover process
terminated
10:05:13 DEBUG: I1130 10:05:13.486819 9806 log.cpp:659] Attempting to start
the writer
10:05:13 DEBUG: I1130 10:05:13.488715 9812 replica.cpp:494] Replica received
implicit promise request from (1322)@a.b.c.d:40352 with proposal 1
10:05:13 DEBUG: I1130 10:05:13.561712 9812 leveldb.cpp:304] Persisting
metadata (8 bytes) to leveldb took 72.945714ms
10:05:13 DEBUG: I1130 10:05:13.561777 9812 replica.cpp:343] Persisted promised
to 1
10:05:13 DEBUG: I1130 10:05:13.562917 9815 coordinator.cpp:238] Coordinator
attempting to fill missing positions
10:05:13 DEBUG: I1130 10:05:13.564766 9812 replica.cpp:389] Replica received
explicit promise request from (1323)@a.b.c.d:40352 for position 0 with proposal
2
10:05:13 DEBUG: I1130 10:05:13.703655 9812 leveldb.cpp:341] Persisting action
(8 bytes) to leveldb took 138.842036ms
10:05:13 DEBUG: I1130 10:05:13.703718 9812 replica.cpp:713] Persisted action
at 0
10:05:13 DEBUG: I1130 10:05:13.704759 9814 replica.cpp:538] Replica received
write request for position 0 from (1324)@a.b.c.d:40352
10:05:13 DEBUG: I1130 10:05:13.704804 9814 leveldb.cpp:436] Reading position
from leveldb took 19322ns
10:05:13 DEBUG: I1130 10:05:13.853890 9814 leveldb.cpp:341] Persisting action
(14 bytes) to leveldb took 149.053698ms
10:05:13 DEBUG: I1130 10:05:13.853955 9814 replica.cpp:713] Persisted action
at 0
10:05:13 DEBUG: I1130 10:05:13.854382 9806 replica.cpp:692] Replica received
learned notice for position 0 from @0.0.0.0:0
10:05:13 DEBUG: I1130 10:05:13.921175 9806 leveldb.cpp:341] Persisting action
(16 bytes) to leveldb took 66.753701ms
10:05:13 DEBUG: I1130 10:05:13.921241 9806 replica.cpp:713] Persisted action
at 0
10:05:13 DEBUG: I1130 10:05:13.921253 9806 replica.cpp:698] Replica learned
NOP action at position 0
10:05:13 DEBUG: I1130 10:05:13.922561 9806 log.cpp:675] Writer started with
ending position 0
10:05:13 DEBUG: I1130 10:05:13.923257 9828 leveldb.cpp:436] Reading position
from leveldb took 27598ns
10:05:13 DEBUG: I1130 10:05:13.924089 9815 registrar.cpp:340] Successfully
fetched the registry (0B) in 650.08896ms
10:05:13 DEBUG: I1130 10:05:13.924152 9815 registrar.cpp:439] Applied 1
operations in 5811ns; attempting to update the 'registry'
10:05:13 DEBUG: I1130 10:05:13.924682 9819 log.cpp:683] Attempting to append
228 bytes to the log
10:05:13 DEBUG: I1130 10:05:13.924921 9817 coordinator.cpp:348] Coordinator
attempting to write APPEND action at position 1
10:05:13 DEBUG: I1130 10:05:13.925762 9816 replica.cpp:538] Replica received
write request for position 1 from (1325)@a.b.c.d:40352
10:05:13 DEBUG: I1130 10:05:13.996296 9816 leveldb.cpp:341] Persisting action
(247 bytes) to leveldb took 70.416898ms
10:05:13 DEBUG: I1130 10:05:13.996361 9816 replica.cpp:713] Persisted action
at 1
10:05:13 DEBUG: I1130 10:05:13.997047 9809 replica.cpp:692] Replica received
learned notice for position 1 from @0.0.0.0:0
10:05:13 DEBUG: I1130 10:05:14.054863 9809 leveldb.cpp:341] Persisting action
(249 bytes) to leveldb took 57.762265ms
10:05:13 DEBUG: I1130 10:05:14.054934 9809 replica.cpp:713] Persisted action
at 1
10:05:13 DEBUG: I1130 10:05:14.054945 9809 replica.cpp:698] Replica learned
APPEND action at position 1
10:05:13 DEBUG: I1130 10:05:14.055465 9818 registrar.cpp:484] Successfully
updated the 'registry' in 131.13088ms
10:05:13 DEBUG: I1130 10:05:14.055541 9818 registrar.cpp:370] Successfully
recovered registrar
10:05:13 DEBUG: I1130 10:05:14.055806 9812 hierarchical.cpp:174] Allocator
recovery is not supported yet
10:05:13 DEBUG: I1130 10:05:14.055796 9821 master.cpp:1447] Recovered 0 slaves
from the Registry (189B) ; allowing 10mins for slaves to re-register
10:05:13 DEBUG: I1130 10:05:14.055956 9822 log.cpp:702] Attempting to truncate
the log to 1
10:05:13 DEBUG: I1130 10:05:14.056046 9825 coordinator.cpp:348] Coordinator
attempting to write TRUNCATE action at position 2
10:05:13 DEBUG: I1130 10:05:14.056783 9811 replica.cpp:538] Replica received
write request for position 2 from (1326)@a.b.c.d:40352
10:05:13 DEBUG: I1130 10:05:14.213801 9811 leveldb.cpp:341] Persisting action
(16 bytes) to leveldb took 156.984638ms
10:05:13 DEBUG: I1130 10:05:14.213932 9811 replica.cpp:713] Persisted action
at 2
10:05:13 DEBUG: I1130 10:05:14.214519 9829 replica.cpp:692] Replica received
learned notice for position 2 from @0.0.0.0:0
10:05:13 DEBUG: I1130 10:05:14.280889 9829 leveldb.cpp:341] Persisting action
(18 bytes) to leveldb took 66.343706ms
10:05:13 DEBUG: I1130 10:05:14.280949 9829 leveldb.cpp:399] Deleting ~1 keys
from leveldb took 23226ns
10:05:13 DEBUG: I1130 10:05:14.280961 9829 replica.cpp:713] Persisted action
at 2
10:05:13 DEBUG: I1130 10:05:14.280969 9829 replica.cpp:698] Replica learned
TRUNCATE action at position 2
10:05:13 DEBUG: I1130 10:05:14.289913 9792 containerizer.cpp:141] Using
isolation: posix/cpu,posix/mem,filesystem/posix
10:05:13 DEBUG: W1130 10:05:14.290166 9792 backend.cpp:48] Failed to create
'bind' backend: BindBackend requires root privileges
10:05:13 DEBUG: I1130 10:05:14.292995 9815 slave.cpp:189] Slave started on
44)@a.b.c.d:40352
10:05:13 DEBUG: I1130 10:05:14.293025 9815 slave.cpp:190] Flags at startup:
--appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
--cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
--cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
--cgroups_root="mesos" --container_disk_watch_interval="15secs"
--containerizers="mesos"
--credential="/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_auth_server="auth.docker.io" --docker_auth_server_port="443"
--docker_kill_orphans="true"
--docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local"
--docker_puller_timeout="60" --docker_registry="registry-1.docker.io"
--docker_registry_port="443" --docker_remove_delay="6hrs"
--docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
--docker_store_dir="/tmp/mesos/store/docker"
--egress_unique_flow_per_container="false"
--enforce_container_disk_quota="false" --ephemeral_ports_per_container="1024"
--executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="false"
--hostname_lookup="true" --image_provisioner_backend="copy"
--initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
--launcher_dir="/builddir/build/BUILD/mesos-0.27.0/src" --logbufsecs="0"
--logging_level="INFO" --network_enable_socket_statistics_details="false"
--network_enable_socket_statistics_summary="false"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false"
--recover="reconnect" --recovery_timeout="15mins"
--registration_backoff_factor="10ms" --resources="cpus:1000;mem:1000"
--revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
--strict="true" --switch_user="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp"
10:05:13 DEBUG: I1130 10:05:14.293321 9815 credentials.hpp:83] Loading
credential for authentication from
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/credential'
10:05:13 DEBUG: I1130 10:05:14.293447 9815 slave.cpp:320] Slave using
credential for: test-principal
10:05:13 DEBUG: I1130 10:05:14.294152 9815 slave.cpp:390] Slave resources:
cpus(*):1000; mem(*):1000; disk(*):464332; ports(*):[31000-32000]
10:05:13 DEBUG: I1130 10:05:14.294184 9815 slave.cpp:398] Slave attributes: [
]
10:05:13 DEBUG: I1130 10:05:14.294190 9815 slave.cpp:403] Slave hostname: xxx
10:05:13 DEBUG: I1130 10:05:14.294195 9815 slave.cpp:408] Slave checkpoint:
true
10:05:13 DEBUG: I1130 10:05:14.294509 9807 state.cpp:52] Recovering state from
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta'
10:05:13 DEBUG: I1130 10:05:14.294713 9819 status_update_manager.cpp:200]
Recovering status update manager
10:05:13 DEBUG: I1130 10:05:14.294765 9819 containerizer.cpp:383] Recovering
containerizer
10:05:13 DEBUG: I1130 10:05:14.295860 9829 slave.cpp:4258] Finished recovery
10:05:13 DEBUG: I1130 10:05:14.296530 9828 status_update_manager.cpp:174]
Pausing sending status updates
10:05:13 DEBUG: I1130 10:05:14.296531 9829 slave.cpp:727] New master detected
at [email protected]:40352
10:05:13 DEBUG: I1130 10:05:14.296622 9829 slave.cpp:790] Authenticating with
master [email protected]:40352
10:05:13 DEBUG: I1130 10:05:14.296640 9829 slave.cpp:795] Using default
CRAM-MD5 authenticatee
10:05:13 DEBUG: I1130 10:05:14.296711 9816 authenticatee.cpp:121] Creating new
client SASL connection
10:05:13 DEBUG: I1130 10:05:14.296720 9829 slave.cpp:763] Detecting new master
10:05:13 DEBUG: I1130 10:05:14.296823 9829 master.cpp:5181] Authenticating
slave(44)@a.b.c.d:40352
10:05:13 DEBUG: I1130 10:05:14.296989 9814 authenticator.cpp:98] Creating new
server SASL connection
10:05:13 DEBUG: I1130 10:05:14.297170 9823 authenticatee.cpp:212] Received
SASL authentication mechanisms: CRAM-MD5
10:05:13 DEBUG: I1130 10:05:14.297191 9823 authenticatee.cpp:238] Attempting
to authenticate with mechanism 'CRAM-MD5'
10:05:13 DEBUG: I1130 10:05:14.297405 9815 authenticator.cpp:203] Received
SASL authentication start
10:05:13 DEBUG: I1130 10:05:14.297680 9815 authenticator.cpp:325]
Authentication requires more steps
10:05:13 DEBUG: I1130 10:05:14.297719 9815 authenticatee.cpp:258] Received
SASL authentication step
10:05:13 DEBUG: I1130 10:05:14.297756 9815 authenticator.cpp:231] Received
SASL authentication step
10:05:13 DEBUG: I1130 10:05:14.297786 9815 authenticator.cpp:317]
Authentication success
10:05:13 DEBUG: I1130 10:05:14.297842 9815 authenticatee.cpp:298]
Authentication success
10:05:13 DEBUG: I1130 10:05:14.297873 9819 master.cpp:5211] Successfully
authenticated principal 'test-principal' at slave(44)@a.b.c.d:40352
10:05:13 DEBUG: I1130 10:05:14.298018 9810 slave.cpp:858] Successfully
authenticated with master [email protected]:40352
10:05:13 DEBUG: I1130 10:05:14.298176 9814 master.cpp:3890] Registering slave
at slave(44)@a.b.c.d:40352 (xxx) with id 05e0d28f-8553-4b91-9e6a-92178b625151-S0
10:05:13 DEBUG: I1130 10:05:14.298307 9823 registrar.cpp:439] Applied 1
operations in 23784ns; attempting to update the 'registry'
10:05:13 DEBUG: I1130 10:05:14.298683 9824 log.cpp:683] Attempting to append
419 bytes to the log
10:05:13 DEBUG: I1130 10:05:14.298820 9808 coordinator.cpp:348] Coordinator
attempting to write APPEND action at position 3
10:05:13 DEBUG: I1130 10:05:14.299178 9824 replica.cpp:538] Replica received
write request for position 3 from (1339)@a.b.c.d:40352
10:05:13 DEBUG: I1130 10:05:14.300453 9811 master.cpp:3878] Ignoring register
slave message from slave(44)@a.b.c.d:40352 (xxx) as admission is already in
progress
10:05:13 DEBUG: I1130 10:05:14.303644 9823 master.cpp:3878] Ignoring register
slave message from slave(44)@a.b.c.d:40352 (xxx) as admission is already in
progress
10:05:13 DEBUG: I1130 10:05:14.307930 9816 master.cpp:3878] Ignoring register
slave message from slave(44)@a.b.c.d:40352 (xxx) as admission is already in
progress
10:05:14 DEBUG: I1130 10:05:14.404505 9823 master.cpp:3878] Ignoring register
slave message from slave(44)@a.b.c.d:40352 (xxx) as admission is already in
progress
10:05:14 DEBUG: I1130 10:05:14.456336 9824 leveldb.cpp:341] Persisting action
(438 bytes) to leveldb took 157.114451ms
10:05:14 DEBUG: I1130 10:05:14.456399 9824 replica.cpp:713] Persisted action
at 3
10:05:14 DEBUG: I1130 10:05:14.457612 9810 replica.cpp:692] Replica received
learned notice for position 3 from @0.0.0.0:0
10:05:14 DEBUG: I1130 10:05:14.506531 9810 leveldb.cpp:341] Persisting action
(440 bytes) to leveldb took 48.856977ms
10:05:14 DEBUG: I1130 10:05:14.506603 9810 replica.cpp:713] Persisted action
at 3
10:05:14 DEBUG: I1130 10:05:14.506619 9810 replica.cpp:698] Replica learned
APPEND action at position 3
10:05:14 DEBUG: I1130 10:05:14.507259 9821 registrar.cpp:484] Successfully
updated the 'registry' in 208.920064ms
10:05:14 DEBUG: I1130 10:05:14.507519 9810 log.cpp:702] Attempting to truncate
the log to 3
10:05:14 DEBUG: I1130 10:05:14.508265 9807 coordinator.cpp:348] Coordinator
attempting to write TRUNCATE action at position 4
10:05:14 DEBUG: I1130 10:05:14.508368 9816 hierarchical.cpp:380] Added slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 (xxx) with cpus(*):1000; mem(*):1000;
disk(*):464332; ports(*):[31000-32000] (allocated: )
10:05:14 DEBUG: I1130 10:05:14.508306 9808 master.cpp:3958] Registered slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx) with
cpus(*):1000; mem(*):1000; disk(*):464332; ports(*):[31000-32000]
10:05:14 DEBUG: I1130 10:05:14.508757 9828 slave.cpp:902] Registered with
master [email protected]:40352; given slave ID
05e0d28f-8553-4b91-9e6a-92178b625151-S0
10:05:14 DEBUG: I1130 10:05:14.509074 9811 status_update_manager.cpp:181]
Resuming sending status updates
10:05:14 DEBUG: I1130 10:05:14.509230 9828 slave.cpp:961] Forwarding total
oversubscribed resources
10:05:14 DEBUG: I1130 10:05:14.509289 9828 master.cpp:4300] Received update of
slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx)
with total oversubscribed resources
10:05:14 DEBUG: I1130 10:05:14.509428 9828 replica.cpp:538] Replica received
write request for position 4 from (1340)@a.b.c.d:40352
10:05:14 DEBUG: I1130 10:05:14.509513 9817 hierarchical.cpp:436] Slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 (xxx) updated with oversubscribed
resources (total: cpus(*):1000; mem(*):1000; disk(*):464332;
ports(*):[31000-32000], allocated: )
10:05:14 DEBUG: I1130 10:05:14.510191 9792 sched.cpp:164] Version: 0.27.0-rc0
10:05:14 DEBUG: I1130 10:05:14.510532 9823 sched.cpp:262] New master detected
at [email protected]:40352
10:05:14 DEBUG: I1130 10:05:14.510576 9823 sched.cpp:318] Authenticating with
master [email protected]:40352
10:05:14 DEBUG: I1130 10:05:14.510583 9823 sched.cpp:325] Using default
CRAM-MD5 authenticatee
10:05:14 DEBUG: I1130 10:05:14.510828 9806 authenticatee.cpp:121] Creating new
client SASL connection
10:05:14 DEBUG: I1130 10:05:14.510975 9816 master.cpp:5181] Authenticating
[email protected]:40352
10:05:14 DEBUG: I1130 10:05:14.511143 9806 authenticator.cpp:98] Creating new
server SASL connection
10:05:14 DEBUG: I1130 10:05:14.511289 9821 authenticatee.cpp:212] Received
SASL authentication mechanisms: CRAM-MD5
10:05:14 DEBUG: I1130 10:05:14.511307 9821 authenticatee.cpp:238] Attempting
to authenticate with mechanism 'CRAM-MD5'
10:05:14 DEBUG: I1130 10:05:14.511338 9821 authenticator.cpp:203] Received
SASL authentication start
10:05:14 DEBUG: I1130 10:05:14.511409 9821 authenticator.cpp:325]
Authentication requires more steps
10:05:14 DEBUG: I1130 10:05:14.511488 9814 authenticatee.cpp:258] Received
SASL authentication step
10:05:14 DEBUG: I1130 10:05:14.511690 9818 authenticator.cpp:231] Received
SASL authentication step
10:05:14 DEBUG: I1130 10:05:14.511735 9818 authenticator.cpp:317]
Authentication success
10:05:14 DEBUG: I1130 10:05:14.511847 9809 authenticatee.cpp:298]
Authentication success
10:05:14 DEBUG: I1130 10:05:14.511870 9815 master.cpp:5211] Successfully
authenticated principal 'test-principal' at
[email protected]:40352
10:05:14 DEBUG: I1130 10:05:14.512241 9815 sched.cpp:407] Successfully
authenticated with master [email protected]:40352
10:05:14 DEBUG: I1130 10:05:14.512375 9826 master.cpp:2207] Received SUBSCRIBE
call for framework 'default' at
[email protected]:40352
10:05:14 DEBUG: W1130 10:05:14.512449 9826 master.cpp:2214] Framework at
[email protected]:40352 (authenticated as
'test-principal') does not set 'principal' in FrameworkInfo
10:05:14 DEBUG: I1130 10:05:14.512469 9826 master.cpp:1676] Authorizing
framework principal '' to receive offers for role '*'
10:05:14 DEBUG: I1130 10:05:14.512598 9818 master.cpp:2278] Subscribing
framework default with checkpointing enabled and capabilities [ ]
10:05:14 DEBUG: I1130 10:05:14.512760 9813 hierarchical.cpp:220] Added
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:14.512938 9823 sched.cpp:641] Framework registered
with 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:14.513129 9818 master.cpp:5010] Sending 1 offers
to framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:14 DEBUG: I1130 10:05:14.513787 9815 master.cpp:2946] Processing ACCEPT
call for offers: [ 05e0d28f-8553-4b91-9e6a-92178b625151-O0 ] on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx) for
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:14 DEBUG: I1130 10:05:14.513805 9815 master.cpp:2742] Authorizing
framework principal '' to launch task 0 as user 'mockbuild'
10:05:14 DEBUG: I1130 10:05:14.514175 9815 master.hpp:176] Adding task 0 with
resources cpus(*):1; mem(*):1 on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0
(xxx)
10:05:14 DEBUG: I1130 10:05:14.514214 9815 master.cpp:3276] Launching task 0
of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 with resources
cpus(*):1; mem(*):1 on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0 at
slave(44)@a.b.c.d:40352 (xxx)
10:05:14 DEBUG: I1130 10:05:14.514379 9821 slave.cpp:1292] Got assigned task 0
for framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:14.514386 9829 hierarchical.cpp:793] Recovered
cpus(*):999; mem(*):999; disk(*):464332; ports(*):[31000-32000] (total:
cpus(*):1000; mem(*):1000; disk(*):464332; ports(*):[31000-32000], allocated:
cpus(*):1; mem(*):1) on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0 from
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:14.617213 9821 slave.cpp:1411] Launching task 0
for framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:14.617678 9821 paths.cpp:434] Trying to chown
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0/runs/4dffe5a2-2fb5-4e7e-ac1f-c1174a293596'
to user 'mockbuild'
10:05:14 DEBUG: I1130 10:05:14.629302 9821 slave.cpp:5043] Launching executor
0 of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 with resources
cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCach:
eTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0/runs/4dffe5a2-2fb5-4e7e-ac1f-c1174a293596'
10:05:14 DEBUG: I1130 10:05:14.629894 9816 containerizer.cpp:617] Starting
container '4dffe5a2-2fb5-4e7e-ac1f-c1174a293596' for executor '0' of framework
'05e0d28f-8553-4b91-9e6a-92178b625151-0000'
10:05:14 DEBUG: I1130 10:05:14.630069 9821 slave.cpp:1629] Queuing task '0'
for executor '0' of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:14.632437 9813 launcher.cpp:132] Forked child with
pid '17573' for container '4dffe5a2-2fb5-4e7e-ac1f-c1174a293596'
10:05:14 DEBUG: I1130 10:05:14.632693 9813 containerizer.cpp:850]
Checkpointing executor's forked pid 17573 to
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0/runs/4dffe5a2-2fb5-4e7e-ac1f-c1174a293596/pids/forked.pid'
10:05:14 DEBUG: I1130 10:05:14.657102 9828 leveldb.cpp:341] Persisting action
(16 bytes) to leveldb took 147.634535ms
10:05:14 DEBUG: I1130 10:05:14.657166 9828 replica.cpp:713] Persisted action
at 4
10:05:14 DEBUG: I1130 10:05:14.657961 9821 replica.cpp:692] Replica received
learned notice for position 4 from @0.0.0.0:0
10:05:14 DEBUG: I1130 10:05:14.825650 9821 leveldb.cpp:341] Persisting action
(18 bytes) to leveldb took 167.646813ms
10:05:14 DEBUG: I1130 10:05:14.825760 9821 leveldb.cpp:399] Deleting ~2 keys
from leveldb took 46598ns
10:05:14 DEBUG: I1130 10:05:14.825775 9821 replica.cpp:713] Persisted action
at 4
10:05:14 DEBUG: I1130 10:05:14.825785 9821 replica.cpp:698] Replica learned
TRUNCATE action at position 4
10:05:14 DEBUG: I1130 10:05:14.838603 17573 exec.cpp:134] Version: 0.27.0-rc0
10:05:14 DEBUG: I1130 10:05:14.840636 9809 slave.cpp:2406] Got registration
for executor '0' of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 from
executor(1)@a.b.c.d:55765
10:05:14 DEBUG: I1130 10:05:14.841717 17641 exec.cpp:208] Executor registered
on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0
10:05:14 DEBUG: I1130 10:05:14.841966 9816 slave.cpp:1794] Sending queued task
'0' to executor '0' of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 at
executor(1)@a.b.c.d:55765
10:05:14 DEBUG: Registered executor on xxx
10:05:14 DEBUG: Starting task 0
10:05:14 DEBUG: sh -c './mesos-fetcher-test-acmd 0'
10:05:14 DEBUG: Forked command at 17654
10:05:14 DEBUG: I1130 10:05:14.845973 9807 slave.cpp:2763] Handling status
update TASK_RUNNING (UUID: 7126deee-bd3f-47e0-a924-a570cc624270) for task 0 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 from
executor(1)@a.b.c.d:55765
10:05:14 DEBUG: I1130 10:05:14.846362 9808 status_update_manager.cpp:320]
Received status update TASK_RUNNING (UUID:
7126deee-bd3f-47e0-a924-a570cc624270) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:14.846649 9808 status_update_manager.cpp:824]
Checkpointing UPDATE for status update TASK_RUNNING (UUID:
7126deee-bd3f-47e0-a924-a570cc624270) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: Command exited with status 0 (pid: 17654)
10:05:14 DEBUG: I1130 10:05:14.947012 9815 slave.cpp:2763] Handling status
update TASK_FINISHED (UUID: 5298fdf2-4b82-4ccb-bdef-342678911f0c) for task 0 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 from
executor(1)@a.b.c.d:55765
10:05:14 DEBUG: I1130 10:05:15.077244 9824 slave.cpp:3115] Forwarding the
update TASK_RUNNING (UUID: 7126deee-bd3f-47e0-a924-a570cc624270) for task 0 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 to [email protected]:40352
10:05:14 DEBUG: I1130 10:05:15.077281 9808 status_update_manager.cpp:320]
Received status update TASK_FINISHED (UUID:
5298fdf2-4b82-4ccb-bdef-342678911f0c) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:15.077327 9808 status_update_manager.cpp:824]
Checkpointing UPDATE for status update TASK_FINISHED (UUID:
5298fdf2-4b82-4ccb-bdef-342678911f0c) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:15.077426 9824 slave.cpp:3025] Sending
acknowledgement for status update TASK_RUNNING (UUID:
7126deee-bd3f-47e0-a924-a570cc624270) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 to executor(1)@a.b.c.d:55765
10:05:14 DEBUG: I1130 10:05:15.077769 9821 master.cpp:4445] Status update
TASK_RUNNING (UUID: 7126deee-bd3f-47e0-a924-a570cc624270) for task 0 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 from slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx)
10:05:14 DEBUG: I1130 10:05:15.077812 9821 master.cpp:4493] Forwarding status
update TASK_RUNNING (UUID: 7126deee-bd3f-47e0-a924-a570cc624270) for task 0 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:15.077899 9821 master.cpp:6097] Updating the state
of task 0 of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (latest state:
TASK_FINISHED, status update state: TASK_RUNNING)
10:05:14 DEBUG: I1130 10:05:15.078454 9810 hierarchical.cpp:793] Recovered
cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):464332;
ports(*):[31000-32000], allocated: ) on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 from framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:15.078515 9822 master.cpp:3602] Processing
ACKNOWLEDGE call 7126deee-bd3f-47e0-a924-a570cc624270 for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0
10:05:14 DEBUG: I1130 10:05:15.244433 9808 status_update_manager.cpp:392]
Received status update acknowledgement (UUID:
7126deee-bd3f-47e0-a924-a570cc624270) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92:
178b625151-0000
10:05:14 DEBUG: I1130 10:05:15.244484 9818 slave.cpp:3025] Sending
acknowledgement for status update TASK_FINISHED (UUID:
5298fdf2-4b82-4ccb-bdef-342678911f0c) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 to executor(1)@a.b.c.d:55765
10:05:14 DEBUG: I1130 10:05:15.244501 9808 status_update_manager.cpp:824]
Checkpointing ACK for status update TASK_RUNNING (UUID:
7126deee-bd3f-47e0-a924-a570cc624270) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:14 DEBUG: I1130 10:05:15.290794 9812 master.cpp:5010] Sending 1 offers
to framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:14 DEBUG: I1130 10:05:15.291131 9822 master.cpp:3328] Processing DECLINE
call for offers: [ 05e0d28f-8553-4b91-9e6a-92178b625151-O1 ] for framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:14 DEBUG: I1130 10:05:15.291245 9812 hierarchical.cpp:793] Recovered
cpus(*):1000; mem(*):1000; disk(*):464332; ports(*):[31000-32000] (total:
cpus(*):1000; mem(*):1000; disk(*):464332; ports(*):[31000-32000], allocated: )
on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0 from framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:15 DEBUG: I1130 10:05:15.453403 9809 slave.cpp:3115] Forwarding the
update TASK_FINISHED (UUID: 5298fdf2-4b82-4ccb-bdef-342678911f0c) for task 0 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 to [email protected]:40352
10:05:15 DEBUG: I1130 10:05:15.453618 9815 master.cpp:4445] Status update
TASK_FINISHED (UUID: 5298fdf2-4b82-4ccb-bdef-342678911f0c) for task 0 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 from slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx)
10:05:15 DEBUG: I1130 10:05:15.453655 9815 master.cpp:4493] Forwarding status
update TASK_FINISHED (UUID: 5298fdf2-4b82-4ccb-bdef-342678911f0c) for task 0 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:15 DEBUG: I1130 10:05:15.453712 9815 master.cpp:6097] Updating the state
of task 0 of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (latest state:
TASK_FINISHED, status update state: TASK_FINISHED)
10:05:15 DEBUG: I1130 10:05:15.454591 9823 master.cpp:3602] Processing
ACKNOWLEDGE call 5298fdf2-4b82-4ccb-bdef-342678911f0c for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0
10:05:15 DEBUG: I1130 10:05:15.454641 9823 master.cpp:6163] Removing task 0
with resources cpus(*):1; mem(*):1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx)
10:05:15 DEBUG: I1130 10:05:15.454851 9809 status_update_manager.cpp:392]
Received status update acknowledgement (UUID:
5298fdf2-4b82-4ccb-bdef-342678911f0c) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:15 DEBUG: I1130 10:05:15.454905 9809 status_update_manager.cpp:824]
Checkpointing ACK for status update TASK_FINISHED (UUID:
5298fdf2-4b82-4ccb-bdef-342678911f0c) for task 0 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:15 DEBUG: I1130 10:05:16.002123 9823 containerizer.cpp:1256] Executor
for container '4dffe5a2-2fb5-4e7e-ac1f-c1174a293596' has exited
10:05:15 DEBUG: I1130 10:05:16.002158 9823 containerizer.cpp:1073] Destroying
container '4dffe5a2-2fb5-4e7e-ac1f-c1174a293596'
10:05:15 DEBUG: I1130 10:05:16.023737 9810 slave.cpp:3581] Executor '0' of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 exited with status 0
10:05:15 DEBUG: I1130 10:05:16.023866 9810 slave.cpp:3685] Cleaning up
executor '0' of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 at
executor(1)@a.b.c.d:55765
10:05:15 DEBUG: I1130 10:05:16.024186 9810 slave.cpp:3773] Cleaning up
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:15 DEBUG: I1130 10:05:16.024242 9825 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0/runs/4dffe5a2-2fb5-4e7e-ac1f-c1174a293596'
for gc 6.99999972117926days in the future
10:05:15 DEBUG: I1130 10:05:16.024276 9806 status_update_manager.cpp:282]
Closing status update streams for framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:15 DEBUG: I1130 10:05:16.024327 9825 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0'
for gc 6.99999972068444days in the future
10:05:15 DEBUG: I1130 10:05:16.024358 9825 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0/runs/4dffe5a2-2fb5-4e7e-ac1f-c1174a293596'
for gc 6.99999972040593days in the future
10:05:15 DEBUG: I1130 10:05:16.024379 9825 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0'
for gc 6.99999972018667days in the future
10:05:15 DEBUG: I1130 10:05:16.024397 9825 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000'
for gc 6.99999971971259days in the future
10:05:15 DEBUG: I1130 10:05:16.024420 9825 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000'
for gc 6.99999971948148days in the future
10:05:19 DEBUG: I1130 10:05:20.294055 9814 master.cpp:5010] Sending 1 offers
to framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:19 DEBUG: I1130 10:05:20.295264 9829 master.cpp:2946] Processing ACCEPT
call for offers: [ 05e0d28f-8553-4b91-9e6a-92178b625151-O2 ] on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx) for
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:19 DEBUG: I1130 10:05:20.295300 9829 master.cpp:2742] Authorizing
framework principal '' to launch task 1 as user 'mockbuild'
10:05:19 DEBUG: I1130 10:05:20.295850 9826 master.hpp:176] Adding task 1 with
resources cpus(*):1; mem(*):1 on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0
(xxx)
10:05:19 DEBUG: I1130 10:05:20.295892 9826 master.cpp:3276] Launching task 1
of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 with resources
cpus(*):1; mem(*):1 on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0 at
slave(44)@a.b.c.d:40352 (xxx)
10:05:19 DEBUG: I1130 10:05:20.296059 9810 slave.cpp:1292] Got assigned task 1
for framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:19 DEBUG: I1130 10:05:20.296097 9809 hierarchical.cpp:793] Recovered
cpus(*):999; mem(*):999; disk(*):464332; ports(*):[31000-32000] (total:
cpus(*):1000; mem(*):1000; disk(*):464332; ports(*):[31000-32000], allocated:
cpus(*):1; mem(*):1) on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0 from
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:21 DEBUG: I1130 10:05:22.140067 9810 gc.cpp:82] Unscheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000'
from gc
10:05:21 DEBUG: I1130 10:05:22.140327 9816 gc.cpp:82] Unscheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000'
from gc
10:05:21 DEBUG: I1130 10:05:22.140511 9808 slave.cpp:1411] Launching task 1
for framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:21 DEBUG: I1130 10:05:22.141100 9808 paths.cpp:434] Trying to chown
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1/runs/2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf'
to user 'mockbuild'
10:05:24 DEBUG: I1130 10:05:25.299540 9810 master.cpp:5010] Sending 1 offers
to framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:24 DEBUG: I1130 10:05:25.300464 9826 master.cpp:3328] Processing DECLINE
call for offers: [ 05e0d28f-8553-4b91-9e6a-92178b625151-O3 ] for framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:24 DEBUG: I1130 10:05:25.300729 9815 hierarchical.cpp:793] Recovered
cpus(*):999; mem(*):999; disk(*):464332; ports(*):[31000-32000] (total:
cpus(*):1000; mem(*):1000; disk(*):464332; ports(*):[31000-32000], allocated:
cpus(*):1; mem(*):1) on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0 from
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:25 DEBUG: I1130 10:05:25.482324 9808 slave.cpp:5043] Launching executor
1 of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 with resources
cpus(*):0.1; mem(*):32 in work directory
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1/runs/2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf'
10:05:25 DEBUG: I1130 10:05:25.482638 9826 containerizer.cpp:617] Starting
container '2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf' for executor '1' of framework
'05e0d28f-8553-4b91-9e6a-92178b625151-0000'
10:05:25 DEBUG: I1130 10:05:25.483031 9808 slave.cpp:1629] Queuing task '1'
for executor '1' of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:25 DEBUG: I1130 10:05:25.485033 9826 launcher.cpp:132] Forked child with
pid '17744' for container '2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf'
10:05:25 DEBUG: I1130 10:05:25.485203 9826 containerizer.cpp:850]
Checkpointing executor's forked pid 17744 to
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1/runs/2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf/pids/forked.pid'
10:05:25 DEBUG: I1130 10:05:25.705692 17744 exec.cpp:134] Version: 0.27.0-rc0
10:05:25 DEBUG: I1130 10:05:25.707963 9826 slave.cpp:2406] Got registration
for executor '1' of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 from
executor(1)@a.b.c.d:54409
10:05:27 DEBUG: I1130 10:05:27.641566 9822 slave.cpp:1794] Sending queued task
'1' to executor '1' of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 at
executor(1)@a.b.c.d:54409
10:05:27 DEBUG: I1130 10:05:27.641652 17813 exec.cpp:208] Executor registered
on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0
10:05:27 DEBUG: Registered executor on xxx
10:05:27 DEBUG: Starting task 1
10:05:27 DEBUG: sh -c './mesos-fetcher-test-acmd 1'
10:05:27 DEBUG: Forked command at 17815
10:05:27 DEBUG: I1130 10:05:27.646214 9815 slave.cpp:2763] Handling status
update TASK_RUNNING (UUID: a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 from
executor(1)@a.b.c.d:54409
10:05:27 DEBUG: I1130 10:05:27.646427 9824 status_update_manager.cpp:320]
Received status update TASK_RUNNING (UUID:
a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:29 DEBUG: I1130 10:05:30.304041 9820 master.cpp:5010] Sending 1 offers
to framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:29 DEBUG: I1130 10:05:30.304401 9820 master.cpp:3328] Processing DECLINE
call for offers: [ 05e0d28f-8553-4b91-9e6a-92178b625151-O4 ] for framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:29 DEBUG: I1130 10:05:30.304648 9819 hierarchical.cpp:793] Recovered
cpus(*):999; mem(*):999; disk(*):464332; ports(*):[31000-32000] (total:
cpus(*):1000; mem(*):1000; disk(*):464332; ports(*):[31000-32000], allocated:
cpus(*):1; mem(*):1) on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0 from
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:30 DEBUG: I1130 10:05:30.925608 9824 status_update_manager.cpp:824]
Checkpointing UPDATE for status update TASK_RUNNING (UUID:
a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:30 DEBUG: Command exited with status 0 (pid: 17815)
10:05:30 DEBUG: I1130 10:05:30.964479 9825 slave.cpp:2763] Handling status
update TASK_FINISHED (UUID: 011fa25a-c86a-4f04-bb27-6f13df8f1424) for task 1 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 f:
rom executor(1)@a.b.c.d:54409
10:05:32 DEBUG: I1130 10:05:31.993974 9810 containerizer.cpp:1256] Executor
for container '2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf' has exited
10:05:32 DEBUG: I1130 10:05:31.993996 9810 containerizer.cpp:1073] Destroying
container '2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf'
10:05:32 DEBUG: I1130 10:05:32.042230 9815 slave.cpp:3581] Executor '1' of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 exited with status 0
10:05:35 DEBUG: tests/fetcher_cache_tests.cpp:772: Failure
10:05:35 DEBUG: Failed to wait 15secs for awaitFinished(task.get())
10:05:35 DEBUG: Begin listing sandboxes
10:05:35 DEBUG: Begin listing sandbox
`/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0/runs/latest`:
10:05:35 DEBUG: Begin file contents of `mesos-fetcher-test-acmd`:
10:05:35 DEBUG: touch mesos-fetcher-test-acmd$1
10:05:35 DEBUG: End file
10:05:35 DEBUG: Begin file contents of `stderr`:
10:05:35 DEBUG: I1130 10:05:14.684726 17589 fetcher.cpp:421] Fetcher Info:
{"cache_directory":"\/tmp\/FetcherCacheTest_LocalCachedExtract_Fm3aTp\/fetch\/slaves\/05e0d28f-8553-4b91-9e6a-92178b625151-S0\/mockbuild","items":[{"action":"DOWNLOAD_AND_CACHE","cache_filename":"c1-mesos-fetc_rchive.tgz","uri":{"cache":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_LocalCachedExtract_Fm3aTp\/mesos-fetcher-test-assets\/mesos-fetcher-test-archive.tgz"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_LocalCachedExtract_Fm3aTp\/slaves\/05e0d28f-8553-4b91-9e6a-92178b625151-S0\/frameworks\/05e0d28f-8553-4b91-9e6a-92178b625151-0000\/executors\/0\/runs\/4dffe5a2-2fb5-4e7e-ac1f-c1174a293596","user":"mockbuild"}
10:05:35 DEBUG: I1130 10:05:14.777077 17589 fetcher.cpp:376] Fetching URI
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz'
10:05:35 DEBUG: I1130 10:05:14.777096 17589 fetcher.cpp:346] Downloading into
cache
10:05:35 DEBUG: I1130 10:05:14.777335 17589 fetcher.cpp:184] Fetching URI
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz'
10:05:35 DEBUG: I1130 10:05:14.777361 17589 fetcher.cpp:164] Copying resource
with command:cp
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz'
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/fetch/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/mockbuild/c1-mesos-fetc_rchive.tgz'
10:05:35 DEBUG: I1130 10:05:14.780762 17589 fetcher.cpp:286] Fetching from cache
10:05:35 DEBUG: I1130 10:05:14.780829 17589 fetcher.cpp:84] Extracting with
command: tar -C
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0/runs/4dffe5a2-2fb5-4e7e-ac1f-c1174a293596'
-xf
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/fetch/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/mockbuild/c1-mesos-fetc_rchive.tgz'
10:05:35 DEBUG: I1130 10:05:14.785956 17589 fetcher.cpp:92] Extracted
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/fetch/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/mockbuild/c1-mesos-fetc_rchive.tgz'
into
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0/runs/4dffe5a2-2fb5-4e7e-ac1f-c1174a293596'
10:05:35 DEBUG: I1130 10:05:14.786003 17589 fetcher.cpp:453] Fetched
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz'
to
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/0/runs/4dffe5a2-2fb5-4e7e-ac1f-c1174a293596'
10:05:35 DEBUG: End file
10:05:35 DEBUG: Begin file contents of `stdout`:
10:05:35 DEBUG: End file
10:05:35 DEBUG: I1130 10:05:35.307865 9818 master.cpp:5010] Sending 1 offers
to framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:35 DEBUG: I1130 10:05:35.308136 9818 master.cpp:3328] Processing DECLINE
call for offers: [ 05e0d28f-8553-4b91-9e6a-92178b625151-O5 ] for framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:35 DEBUG: I1130 10:05:35.308248 9820 hierarchical.cpp:793] Recovered
cpus(*):999; mem(*):999; disk(*):464332; ports(*):[31000-32000] (total:
cpus(*):1000; mem(*):1000; disk(*):464332; ports(*):[31000-32000], allocated:
cpus(*):1; mem(*):1) on slave 05e0d28f-8553-4b91-9e6a-92178b625151-S0 from
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:36 DEBUG: I1130 10:05:36.479372 9824 status_update_manager.cpp:320]
Received status update TASK_FINISHED (UUID:
011fa25a-c86a-4f04-bb27-6f13df8f1424) for task 1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:37 DEBUG: I1130 10:05:36.479424 9824 status_update_manager.cpp:824]
Checkpointing UPDATE for status update TASK_FINISHED (UUID:
011fa25a-c86a-4f04-bb27-6f13df8f1424) for task 1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:37 DEBUG: Begin file contents of `mesos-fetcher-test-acmd0`:
10:05:39 DEBUG: End file
10:05:39 DEBUG: End sandbox
10:05:39 DEBUG: Begin listing sandbox
`/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1/runs/latest`:
10:05:39 DEBUG: Begin file contents of `mesos-fetcher-test-acmd`:
10:05:39 DEBUG: touch mesos-fetcher-test-acmd$1
10:05:39 DEBUG: End file
10:05:39 DEBUG: Begin file contents of `stderr`:
10:05:39 DEBUG: I1130 10:05:25.579206 17748 fetcher.cpp:421] Fetcher Info:
{"cache_directory":"\/tmp\/FetcherCacheTest_LocalCachedExtract_Fm3aTp\/fetch\/slaves\/05e0d28f-8553-4b91-9e6a-92178b625151-S0\/mockbuild","items":[{"action":"RETRIEVE_FROM_CACHE","cache_filename":"c1-mesos-fetc_rchive.tgz","uri":{"cache":true,"extract":true,"value":"\/tmp\/FetcherCacheTest_LocalCachedExtract_Fm3aTp\/mesos-fetcher-test-assets\/mesos-fetcher-test-archive.tgz"}}],"sandbox_directory":"\/tmp\/FetcherCacheTest_LocalCachedExtract_Fm3aTp\/slaves\/05e0d28f-8553-4b91-9e6a-92178b625151-S0\/frameworks\/05e0d28f-8553-4b91-9e6a-92178b625151-0000\/executors\/1\/runs\/2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf","user":"mockbuild"}
10:05:39 DEBUG: I1130 10:05:25.582106 17748 fetcher.cpp:376] Fetching URI
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz'
10:05:39 DEBUG: I1130 10:05:25.582132 17748 fetcher.cpp:286] Fetching from cache
10:05:39 DEBUG: I1130 10:05:25.582170 17748 fetcher.cpp:84] Extracting with
command: tar -C
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1/runs/2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf'
-xf
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/fetch/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/mockbuild/c1-mesos-fetc_rchive.tgz'
10:05:39 DEBUG: I1130 10:05:25.587821 17748 fetcher.cpp:92] Extracted
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/fetch/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/mockbuild/c1-mesos-fetc_rchive.tgz'
into
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1/runs/2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf'
10:05:39 DEBUG: I1130 10:05:25.587888 17748 fetcher.cpp:453] Fetched
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/mesos-fetcher-test-assets/mesos-fetcher-test-archive.tgz'
to
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1/runs/2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf'
10:05:39 DEBUG: End file
10:05:39 DEBUG: Begin file contents of `mesos-fetcher-test-acmd1`:
10:05:39 DEBUG: End file
10:05:39 DEBUG: Begin file contents of `stdout`:
10:05:39 DEBUG: End file
10:05:39 DEBUG: End sandbox
10:05:39 DEBUG: End sandboxes
10:05:39 DEBUG: I1130 10:05:36.479509 9817 slave.cpp:3115] Forwarding the
update TASK_RUNNING (UUID: a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 to [email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.479652 9817 slave.cpp:3025] Sending
acknowledgement for status update TASK_RUNNING (UUID:
a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 to executor(1)@a.b.c.d:54409
10:05:39 DEBUG: I1130 10:05:36.479770 9818 master.cpp:4445] Status update
TASK_RUNNING (UUID: a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 from slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx)
10:05:39 DEBUG: I1130 10:05:36.479800 9818 master.cpp:4493] Forwarding status
update TASK_RUNNING (UUID: a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:39 DEBUG: I1130 10:05:36.479874 9818 master.cpp:6097] Updating the state
of task 1 of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (latest state:
TASK_FINISHED, status update state: TASK_RUNNING)
10:05:39 DEBUG: I1130 10:05:36.480193 9820 master.cpp:3602] Processing
ACKNOWLEDGE call a54d19d5-ebd6-4d4e-9310-0c25f39148b2 for task 1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0
10:05:39 DEBUG: E1130 10:05:36.480433 9830 process.cpp:1893] Failed to
shutdown socket with fd 12: Transport endpoint is not connected
10:05:39 DEBUG: I1130 10:05:36.480490 9807 hierarchical.cpp:793] Recovered
cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):464332;
ports(*):[31000-32000], allocated: ) on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 from framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:39 DEBUG: I1130 10:05:36.745237 9792 sched.cpp:1803] Asked to stop the
driver
10:05:39 DEBUG: I1130 10:05:36.745429 9813 master.cpp:1138] Framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 disconnected
10:05:39 DEBUG: I1130 10:05:36.745458 9813 master.cpp:2503] Disconnecting
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.745476 9813 master.cpp:2527] Deactivating
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.745514 9813 master.cpp:1162] Giving framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 0ns to failover
10:05:39 DEBUG: I1130 10:05:36.745569 9811 hierarchical.cpp:303] Deactivated
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:39 DEBUG: I1130 10:05:36.746917 9814 master.cpp:4858] Framework failover
timeout, removing framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default)
at [email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.746955 9814 master.cpp:5590] Removing framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.747010 9814 master.cpp:6097] Updating the state
of task 1 of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (latest state:
TASK_FINISHED, status update state: TASK_KILLED)
[email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.479652 9817 slave.cpp:3025] Sending
acknowledgement for status update TASK_RUNNING (UUID:
a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 to executor(1)@a.b.c.d:54409
10:05:39 DEBUG: I1130 10:05:36.479770 9818 master.cpp:4445] Status update
TASK_RUNNING (UUID: a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 from slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx)
10:05:39 DEBUG: I1130 10:05:36.479800 9818 master.cpp:4493] Forwarding status
update TASK_RUNNING (UUID: a54d19d5-ebd6-4d4e-9310-0c25f39148b2) for task 1 of
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:39 DEBUG: I1130 10:05:36.479874 9818 master.cpp:6097] Updating the state
of task 1 of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (latest state:
TASK_FINISHED, status update state: TASK_RUNNING)
10:05:39 DEBUG: I1130 10:05:36.480193 9820 master.cpp:3602] Processing
ACKNOWLEDGE call a54d19d5-ebd6-4d4e-9310-0c25f39148b2 for task 1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0
10:05:39 DEBUG: E1130 10:05:36.480433 9830 process.cpp:1893] Failed to
shutdown socket with fd 12: Transport endpoint is not connected
10:05:39 DEBUG: I1130 10:05:36.480490 9807 hierarchical.cpp:793] Recovered
cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):464332;
ports(*):[31000-32000], allocated: ) on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 from framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:39 DEBUG: I1130 10:05:36.745237 9792 sched.cpp:1803] Asked to stop the
driver
10:05:39 DEBUG: I1130 10:05:36.745429 9813 master.cpp:1138] Framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 disconnected
10:05:39 DEBUG: I1130 10:05:36.745458 9813 master.cpp:2503] Disconnecting
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.745476 9813 master.cpp:2527] Deactivating
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.745514 9813 master.cpp:1162] Giving framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352 0ns to failover
10:05:39 DEBUG: I1130 10:05:36.745569 9811 hierarchical.cpp:303] Deactivated
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:39 DEBUG: I1130 10:05:36.746917 9814 master.cpp:4858] Framework failover
timeout, removing framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default)
at [email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.746955 9814 master.cpp:5590] Removing framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 (default) at
[email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.747010 9814 master.cpp:6097] Updating the state
of task 1 of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 (latest state:
TASK_FINISHED, status update state: TASK_KILLED)
10:05:39 DEBUG: I1130 10:05:36.747022 9814 master.cpp:6163] Removing task 1
with resources cpus(*):1; mem(*):1 of framework
05e0d28f-8553-4b91-9e6a-92178b625151-0000 on slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0 at slave(44)@a.b.c.d:40352 (xxx)
10:05:39 DEBUG: I1130 10:05:36.747102 9808 slave.cpp:2010] Asked to shut down
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 by [email protected]:40352
10:05:39 DEBUG: I1130 10:05:36.747126 9808 slave.cpp:2035] Shutting down
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:39 DEBUG: I1130 10:05:36.747140 9808 slave.cpp:3685] Cleaning up
executor '1' of framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000 at
executor(1)@a.b.c.d:54409
10:05:39 DEBUG: I1130 10:05:36.747206 9814 hierarchical.cpp:260] Removed
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:39 DEBUG: I1130 10:05:36.747366 9813 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1/runs/2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf'
for gc 6.99999135063704days in the future
10:05:39 DEBUG: I1130 10:05:38.067582 9792 master.cpp:938] Master terminating
10:05:39 DEBUG: I1130 10:05:38.067878 9821 hierarchical.cpp:410] Removed slave
05e0d28f-8553-4b91-9e6a-92178b625151-S0
10:05:39 DEBUG: I1130 10:05:38.068038 9822 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1'
for gc 6.99997606534519days in the future
10:05:39 DEBUG: I1130 10:05:38.068127 9822 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1/runs/2dadc4bb-edf9-49d3-96fd-c93d7dbb1edf'
for gc 6.99999921236148days in the future
10:05:39 DEBUG: I1130 10:05:38.068140 9808 slave.cpp:3773] Cleaning up
framework 05e0d28f-8553-4b91-9e6a-92178b625151-0000
10:05:39 DEBUG: I1130 10:05:38.068194 9822 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000/executors/1'
for gc 6.99999921172444days in the future
10:05:39 DEBUG: I1130 10:05:38.068269 9822 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000'
for gc 6.99999921069333days in the future
10:05:39 DEBUG: I1130 10:05:38.068353 9822 gc.cpp:54] Scheduling
'/tmp/FetcherCacheTest_LocalCachedExtract_Fm3aTp/meta/slaves/05e0d28f-8553-4b91-9e6a-92178b625151-S0/frameworks/05e0d28f-8553-4b91-9e6a-92178b625151-0000'
for gc 6.99999921027852days in the future
10:05:39 DEBUG: I1130 10:05:38.068269 9808 slave.cpp:3243]
[email protected]:40352 exited
10:05:39 DEBUG: W1130 10:05:38.068966 9808 slave.cpp:3246] Master
disconnected! Waiting for a new master to be elected
10:05:39 DEBUG: I1130 10:05:38.071414 9811 slave.cpp:599] Slave terminating
10:05:40 DEBUG: [ FAILED ] FetcherCacheTest.LocalCachedExtract (28187 ms)
{code}
> FetcherCacheTest.LocalCachedExtract is flaky.
> ---------------------------------------------
>
> Key: MESOS-2857
> URL: https://issues.apache.org/jira/browse/MESOS-2857
> Project: Mesos
> Issue Type: Bug
> Components: fetcher, test
> Reporter: Benjamin Mahler
> Assignee: Benjamin Bannier
> Labels: flaky-test, mesosphere
>
> From jenkins:
> {noformat}
> [ RUN ] FetcherCacheTest.LocalCachedExtract
> Using temporary directory '/tmp/FetcherCacheTest_LocalCachedExtract_Cwdcdj'
> I0610 20:04:48.591573 24561 leveldb.cpp:176] Opened db in 3.512525ms
> I0610 20:04:48.592456 24561 leveldb.cpp:183] Compacted db in 828630ns
> I0610 20:04:48.592512 24561 leveldb.cpp:198] Created db iterator in 32992ns
> I0610 20:04:48.592531 24561 leveldb.cpp:204] Seeked to beginning of db in
> 8967ns
> I0610 20:04:48.592545 24561 leveldb.cpp:273] Iterated through 0 keys in the
> db in 7762ns
> I0610 20:04:48.592604 24561 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0610 20:04:48.593438 24587 recover.cpp:449] Starting replica recovery
> I0610 20:04:48.593698 24587 recover.cpp:475] Replica is in EMPTY status
> I0610 20:04:48.595641 24580 replica.cpp:641] Replica in EMPTY status received
> a broadcasted recover request
> I0610 20:04:48.596086 24590 recover.cpp:195] Received a recover response from
> a replica in EMPTY status
> I0610 20:04:48.596607 24590 recover.cpp:566] Updating replica status to
> STARTING
> I0610 20:04:48.597507 24590 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 717888ns
> I0610 20:04:48.597535 24590 replica.cpp:323] Persisted replica status to
> STARTING
> I0610 20:04:48.597697 24590 recover.cpp:475] Replica is in STARTING status
> I0610 20:04:48.599165 24584 replica.cpp:641] Replica in STARTING status
> received a broadcasted recover request
> I0610 20:04:48.599434 24584 recover.cpp:195] Received a recover response from
> a replica in STARTING status
> I0610 20:04:48.599915 24590 recover.cpp:566] Updating replica status to VOTING
> I0610 20:04:48.600545 24590 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 432335ns
> I0610 20:04:48.600574 24590 replica.cpp:323] Persisted replica status to
> VOTING
> I0610 20:04:48.600659 24590 recover.cpp:580] Successfully joined the Paxos
> group
> I0610 20:04:48.600797 24590 recover.cpp:464] Recover process terminated
> I0610 20:04:48.602905 24594 master.cpp:363] Master
> 20150610-200448-3875541420-32907-24561 (dbade881e927) started on
> 172.17.0.231:32907
> I0610 20:04:48.602957 24594 master.cpp:365] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5"
> --credentials="/tmp/FetcherCacheTest_LocalCachedExtract_Cwdcdj/credentials"
> --framework_sorter="drf" --help="false" --initialize_driver_logging="true"
> --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
> --quiet="false" --recovery_slave_removal_limit="100%"
> --registry="replicated_log" --registry_fetch_timeout="1mins"
> --registry_store_timeout="25secs" --registry_strict="true"
> --root_submissions="true" --slave_reregister_timeout="10mins"
> --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-0.23.0/_inst/share/mesos/webui"
> --work_dir="/tmp/FetcherCacheTest_LocalCachedExtract_Cwdcdj/master"
> --zk_session_timeout="10secs"
> I0610 20:04:48.603374 24594 master.cpp:410] Master only allowing
> authenticated frameworks to register
> I0610 20:04:48.603392 24594 master.cpp:415] Master only allowing
> authenticated slaves to register
> I0610 20:04:48.603404 24594 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/FetcherCacheTest_LocalCachedExtract_Cwdcdj/credentials'
> I0610 20:04:48.603751 24594 master.cpp:454] Using default 'crammd5'
> authenticator
> I0610 20:04:48.604928 24594 master.cpp:491] Authorization enabled
> I0610 20:04:48.606034 24593 hierarchical.hpp:309] Initialized hierarchical
> allocator process
> I0610 20:04:48.606106 24593 whitelist_watcher.cpp:79] No whitelist given
> I0610 20:04:48.607430 24594 master.cpp:1476] The newly elected leader is
> [email protected]:32907 with id 20150610-200448-3875541420-32907-24561
> I0610 20:04:48.607466 24594 master.cpp:1489] Elected as the leading master!
> I0610 20:04:48.607481 24594 master.cpp:1259] Recovering from registrar
> I0610 20:04:48.607712 24594 registrar.cpp:313] Recovering registrar
> I0610 20:04:48.608543 24588 log.cpp:661] Attempting to start the writer
> I0610 20:04:48.610231 24588 replica.cpp:477] Replica received implicit
> promise request with proposal 1
> I0610 20:04:48.611335 24588 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 1.086439ms
> I0610 20:04:48.611382 24588 replica.cpp:345] Persisted promised to 1
> I0610 20:04:48.612303 24588 coordinator.cpp:230] Coordinator attemping to
> fill missing position
> I0610 20:04:48.613883 24593 replica.cpp:378] Replica received explicit
> promise request for position 0 with proposal 2
> I0610 20:04:48.619205 24593 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 5.228235ms
> I0610 20:04:48.619257 24593 replica.cpp:679] Persisted action at 0
> I0610 20:04:48.621919 24593 replica.cpp:511] Replica received write request
> for position 0
> I0610 20:04:48.621987 24593 leveldb.cpp:438] Reading position from leveldb
> took 49394ns
> I0610 20:04:48.622689 24593 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 668412ns
> I0610 20:04:48.622716 24593 replica.cpp:679] Persisted action at 0
> I0610 20:04:48.623507 24584 replica.cpp:658] Replica received learned notice
> for position 0
> I0610 20:04:48.624155 24584 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 612283ns
> I0610 20:04:48.624186 24584 replica.cpp:679] Persisted action at 0
> I0610 20:04:48.624215 24584 replica.cpp:664] Replica learned NOP action at
> position 0
> I0610 20:04:48.625144 24593 log.cpp:677] Writer started with ending position 0
> I0610 20:04:48.626724 24589 leveldb.cpp:438] Reading position from leveldb
> took 72013ns
> I0610 20:04:48.629276 24591 registrar.cpp:346] Successfully fetched the
> registry (0B) in 21.520128ms
> I0610 20:04:48.629663 24591 registrar.cpp:445] Applied 1 operations in
> 129587ns; attempting to update the 'registry'
> I0610 20:04:48.632237 24579 log.cpp:685] Attempting to append 131 bytes to
> the log
> I0610 20:04:48.632624 24579 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 1
> I0610 20:04:48.633739 24579 replica.cpp:511] Replica received write request
> for position 1
> I0610 20:04:48.634351 24579 leveldb.cpp:343] Persisting action (150 bytes) to
> leveldb took 583937ns
> I0610 20:04:48.634382 24579 replica.cpp:679] Persisted action at 1
> I0610 20:04:48.635073 24583 replica.cpp:658] Replica received learned notice
> for position 1
> I0610 20:04:48.635442 24583 leveldb.cpp:343] Persisting action (152 bytes) to
> leveldb took 357122ns
> I0610 20:04:48.635469 24583 replica.cpp:679] Persisted action at 1
> I0610 20:04:48.635494 24583 replica.cpp:664] Replica learned APPEND action at
> position 1
> I0610 20:04:48.636337 24583 registrar.cpp:490] Successfully updated the
> 'registry' in 6.534144ms
> I0610 20:04:48.636725 24594 log.cpp:704] Attempting to truncate the log to 1
> I0610 20:04:48.636858 24583 registrar.cpp:376] Successfully recovered
> registrar
> I0610 20:04:48.637073 24594 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 2
> I0610 20:04:48.637789 24594 master.cpp:1286] Recovered 0 slaves from the
> Registry (95B) ; allowing 10mins for slaves to re-register
> I0610 20:04:48.638630 24583 replica.cpp:511] Replica received write request
> for position 2
> I0610 20:04:48.639127 24583 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 396272ns
> I0610 20:04:48.639153 24583 replica.cpp:679] Persisted action at 2
> I0610 20:04:48.639804 24583 replica.cpp:658] Replica received learned notice
> for position 2
> I0610 20:04:48.640965 24583 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 1.147322ms
> I0610 20:04:48.641054 24583 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 72395ns
> I0610 20:04:48.641197 24583 replica.cpp:679] Persisted action at 2
> I0610 20:04:48.641345 24583 replica.cpp:664] Replica learned TRUNCATE action
> at position 2
> I0610 20:04:48.652274 24561 containerizer.cpp:111] Using isolation:
> posix/cpu,posix/mem
> I0610 20:04:48.658994 24590 slave.cpp:188] Slave started on
> 42)@172.17.0.231:32907
> I0610 20:04:48.659049 24590 slave.cpp:189] Flags at startup:
> --authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false"
> --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup"
> --cgroups_limit_swap="false" --cgroups_root="mesos"
> --container_disk_watch_interval="15secs" --containerizers="mesos"
> --credential="/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_kill_orphans="true" --docker_remove_delay="6hrs"
> --docker_sandbox_directory="/mnt/mesos/sandbox"
> --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-0.23.0/_build/src" --logbufsecs="0"
> --logging_level="INFO" --oversubscribed_resources_interval="15secs"
> --perf_duration="10secs" --perf_interval="1mins" --quiet="false"
> --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ms" --resource_monitoring_interval="1secs"
> --resources="cpus(*):1000; mem(*):1000" --revocable_cpu_low_priority="true"
> --strict="true" --switch_user="true" --version="false"
> --work_dir="/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM"
> I0610 20:04:48.659570 24590 credentials.hpp:85] Loading credential for
> authentication from
> '/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM/credential'
> I0610 20:04:48.659803 24590 slave.cpp:319] Slave using credential for:
> test-principal
> I0610 20:04:48.660441 24590 slave.cpp:352] Slave resources: cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0610 20:04:48.660555 24590 slave.cpp:382] Slave hostname: dbade881e927
> I0610 20:04:48.660578 24590 slave.cpp:387] Slave checkpoint: true
> I0610 20:04:48.661550 24588 state.cpp:35] Recovering state from
> '/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM/meta'
> I0610 20:04:48.661913 24590 status_update_manager.cpp:201] Recovering status
> update manager
> I0610 20:04:48.662253 24590 containerizer.cpp:312] Recovering containerizer
> I0610 20:04:48.663207 24581 slave.cpp:3950] Finished recovery
> I0610 20:04:48.663761 24581 slave.cpp:4104] Querying resource estimator for
> oversubscribable resources
> I0610 20:04:48.664077 24581 slave.cpp:678] New master detected at
> [email protected]:32907
> I0610 20:04:48.664088 24586 status_update_manager.cpp:175] Pausing sending
> status updates
> I0610 20:04:48.664245 24581 slave.cpp:741] Authenticating with master
> [email protected]:32907
> I0610 20:04:48.664388 24581 slave.cpp:746] Using default CRAM-MD5
> authenticatee
> I0610 20:04:48.664611 24581 slave.cpp:714] Detecting new master
> I0610 20:04:48.664647 24594 authenticatee.hpp:139] Creating new client SASL
> connection
> I0610 20:04:48.664813 24581 slave.cpp:4125] Received oversubscribable
> resources from the resource estimator
> I0610 20:04:48.665060 24581 slave.cpp:4129] No master detected. Re-querying
> resource estimator after 15secs
> I0610 20:04:48.665096 24594 master.cpp:4181] Authenticating
> slave(42)@172.17.0.231:32907
> I0610 20:04:48.665247 24581 authenticator.cpp:406] Starting authentication
> session for crammd5_authenticatee(130)@172.17.0.231:32907
> I0610 20:04:48.665657 24581 authenticator.cpp:92] Creating new server SASL
> connection
> I0610 20:04:48.666013 24581 authenticatee.hpp:230] Received SASL
> authentication mechanisms: CRAM-MD5
> I0610 20:04:48.666159 24581 authenticatee.hpp:256] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0610 20:04:48.666443 24592 authenticator.cpp:197] Received SASL
> authentication start
> I0610 20:04:48.666591 24592 authenticator.cpp:319] Authentication requires
> more steps
> I0610 20:04:48.666779 24592 authenticatee.hpp:276] Received SASL
> authentication step
> I0610 20:04:48.667007 24585 authenticator.cpp:225] Received SASL
> authentication step
> I0610 20:04:48.667043 24585 auxprop.cpp:101] Request to lookup properties for
> user: 'test-principal' realm: 'dbade881e927' server FQDN: 'dbade881e927'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0610 20:04:48.667058 24585 auxprop.cpp:173] Looking up auxiliary property
> '*userPassword'
> I0610 20:04:48.667110 24585 auxprop.cpp:173] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0610 20:04:48.667142 24585 auxprop.cpp:101] Request to lookup properties for
> user: 'test-principal' realm: 'dbade881e927' server FQDN: 'dbade881e927'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0610 20:04:48.667155 24585 auxprop.cpp:123] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0610 20:04:48.667163 24585 auxprop.cpp:123] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0610 20:04:48.667181 24585 authenticator.cpp:311] Authentication success
> I0610 20:04:48.667331 24585 authenticatee.hpp:316] Authentication success
> I0610 20:04:48.667414 24585 master.cpp:4211] Successfully authenticated
> principal 'test-principal' at slave(42)@172.17.0.231:32907
> I0610 20:04:48.667505 24585 authenticator.cpp:424] Authentication session
> cleanup for crammd5_authenticatee(130)@172.17.0.231:32907
> I0610 20:04:48.667809 24585 slave.cpp:812] Successfully authenticated with
> master [email protected]:32907
> I0610 20:04:48.667982 24585 slave.cpp:1146] Will retry registration in
> 7.257154ms if necessary
> I0610 20:04:48.668226 24585 master.cpp:3157] Registering slave at
> slave(42)@172.17.0.231:32907 (dbade881e927) with id
> 20150610-200448-3875541420-32907-24561-S0
> I0610 20:04:48.668737 24585 registrar.cpp:445] Applied 1 operations in
> 90255ns; attempting to update the 'registry'
> I0610 20:04:48.672297 24585 log.cpp:685] Attempting to append 305 bytes to
> the log
> I0610 20:04:48.672541 24585 coordinator.cpp:340] Coordinator attempting to
> write APPEND action at position 3
> I0610 20:04:48.673528 24593 replica.cpp:511] Replica received write request
> for position 3
> I0610 20:04:48.674321 24593 leveldb.cpp:343] Persisting action (324 bytes) to
> leveldb took 766804ns
> I0610 20:04:48.674355 24593 replica.cpp:679] Persisted action at 3
> I0610 20:04:48.675138 24587 replica.cpp:658] Replica received learned notice
> for position 3
> I0610 20:04:48.675866 24587 leveldb.cpp:343] Persisting action (326 bytes) to
> leveldb took 714643ns
> I0610 20:04:48.675897 24587 replica.cpp:679] Persisted action at 3
> I0610 20:04:48.675922 24587 replica.cpp:664] Replica learned APPEND action at
> position 3
> I0610 20:04:48.677471 24587 registrar.cpp:490] Successfully updated the
> 'registry' in 8.656128ms
> I0610 20:04:48.677759 24587 log.cpp:704] Attempting to truncate the log to 3
> I0610 20:04:48.678423 24593 coordinator.cpp:340] Coordinator attempting to
> write TRUNCATE action at position 4
> I0610 20:04:48.678621 24587 master.cpp:3214] Registered slave
> 20150610-200448-3875541420-32907-24561-S0 at slave(42)@172.17.0.231:32907
> (dbade881e927) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06;
> ports(*):[31000-32000]
> I0610 20:04:48.678959 24593 hierarchical.hpp:496] Added slave
> 20150610-200448-3875541420-32907-24561-S0 (dbade881e927) with cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (and cpus(*):1000;
> mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] available)
> I0610 20:04:48.679157 24593 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:48.679183 24593 hierarchical.hpp:852] Performed allocation for
> slave 20150610-200448-3875541420-32907-24561-S0 in 175519ns
> I0610 20:04:48.679805 24593 replica.cpp:511] Replica received write request
> for position 4
> I0610 20:04:48.684160 24587 slave.cpp:846] Registered with master
> [email protected]:32907; given slave ID
> 20150610-200448-3875541420-32907-24561-S0
> I0610 20:04:48.684229 24587 fetcher.cpp:77] Clearing fetcher cache
> I0610 20:04:48.684666 24587 slave.cpp:869] Checkpointing SlaveInfo to
> '/tmp/FetcherCacheTest_LocalCachedExtract_LCHuuM/meta/slaves/20150610-200448-3875541420-32907-24561-S0/slave.info'
> I0610 20:04:48.687366 24587 slave.cpp:2895] Received ping from
> slave-observer(42)@172.17.0.231:32907
> I0610 20:04:48.687453 24584 status_update_manager.cpp:182] Resuming sending
> status updates
> I0610 20:04:48.690901 24593 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 3.385583ms
> I0610 20:04:48.690975 24593 replica.cpp:679] Persisted action at 4
> I0610 20:04:48.692137 24593 replica.cpp:658] Replica received learned notice
> for position 4
> I0610 20:04:48.692603 24593 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 449838ns
> I0610 20:04:48.692674 24593 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 52471ns
> I0610 20:04:48.692699 24593 replica.cpp:679] Persisted action at 4
> I0610 20:04:48.692726 24593 replica.cpp:664] Replica learned TRUNCATE action
> at position 4
> I0610 20:04:48.693544 24561 sched.cpp:157] Version: 0.23.0
> I0610 20:04:48.695550 24590 sched.cpp:254] New master detected at
> [email protected]:32907
> I0610 20:04:48.697090 24590 sched.cpp:310] Authenticating with master
> [email protected]:32907
> I0610 20:04:48.697136 24590 sched.cpp:317] Using default CRAM-MD5
> authenticatee
> I0610 20:04:48.697511 24586 authenticatee.hpp:139] Creating new client SASL
> connection
> I0610 20:04:48.697937 24586 master.cpp:4181] Authenticating
> [email protected]:32907
> I0610 20:04:48.698185 24584 authenticator.cpp:406] Starting authentication
> session for crammd5_authenticatee(131)@172.17.0.231:32907
> I0610 20:04:48.698575 24584 authenticator.cpp:92] Creating new server SASL
> connection
> I0610 20:04:48.698807 24584 authenticatee.hpp:230] Received SASL
> authentication mechanisms: CRAM-MD5
> I0610 20:04:48.699898 24584 authenticatee.hpp:256] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0610 20:04:48.700040 24584 authenticator.cpp:197] Received SASL
> authentication start
> I0610 20:04:48.700119 24584 authenticator.cpp:319] Authentication requires
> more steps
> I0610 20:04:48.700193 24584 authenticatee.hpp:276] Received SASL
> authentication step
> I0610 20:04:48.700287 24584 authenticator.cpp:225] Received SASL
> authentication step
> I0610 20:04:48.700320 24584 auxprop.cpp:101] Request to lookup properties for
> user: 'test-principal' realm: 'dbade881e927' server FQDN: 'dbade881e927'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0610 20:04:48.700333 24584 auxprop.cpp:173] Looking up auxiliary property
> '*userPassword'
> I0610 20:04:48.700392 24584 auxprop.cpp:173] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0610 20:04:48.700425 24584 auxprop.cpp:101] Request to lookup properties for
> user: 'test-principal' realm: 'dbade881e927' server FQDN: 'dbade881e927'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0610 20:04:48.700439 24584 auxprop.cpp:123] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0610 20:04:48.700448 24584 auxprop.cpp:123] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0610 20:04:48.700467 24584 authenticator.cpp:311] Authentication success
> I0610 20:04:48.700640 24584 authenticatee.hpp:316] Authentication success
> I0610 20:04:48.700742 24584 authenticator.cpp:424] Authentication session
> cleanup for crammd5_authenticatee(131)@172.17.0.231:32907
> I0610 20:04:48.701282 24590 sched.cpp:398] Successfully authenticated with
> master [email protected]:32907
> I0610 20:04:48.701315 24590 sched.cpp:521] Sending registration request to
> [email protected]:32907
> I0610 20:04:48.701386 24590 sched.cpp:554] Will retry registration in
> 1.128089605secs if necessary
> I0610 20:04:48.701676 24586 master.cpp:4211] Successfully authenticated
> principal 'test-principal' at
> [email protected]:32907
> I0610 20:04:48.702863 24586 master.cpp:1716] Received registration request
> for framework 'default' at
> [email protected]:32907
> W0610 20:04:48.702924 24586 master.cpp:1539] Framework at
> [email protected]:32907
> (authenticated as 'test-principal') does not specify principal in its
> FrameworkInfo
> I0610 20:04:48.702957 24586 master.cpp:1555] Authorizing framework principal
> '' to receive offers for role '*'
> I0610 20:04:48.703580 24586 master.cpp:1783] Registering framework
> 20150610-200448-3875541420-32907-24561-0000 (default) at
> [email protected]:32907 with
> checkpointing enabled and capabilities [ ]
> I0610 20:04:48.705044 24590 hierarchical.hpp:354] Added framework
> 20150610-200448-3875541420-32907-24561-0000
> I0610 20:04:48.705657 24590 hierarchical.hpp:834] Performed allocation for 1
> slaves in 583520ns
> I0610 20:04:48.707613 24586 master.cpp:4100] Sending 1 offers to framework
> 20150610-200448-3875541420-32907-24561-0000 (default) at
> [email protected]:32907
> I0610 20:04:48.709035 24590 sched.cpp:448] Framework registered with
> 20150610-200448-3875541420-32907-24561-0000
> I0610 20:04:48.709113 24590 sched.cpp:462] Scheduler::registered took 33214ns
> GMOCK WARNING:
> Uninteresting mock function call - returning directly.
> Function call: resourceOffers(0x3bd7fb0, @0x7fe5bb7af898 { 128-byte
> object <90-8D 30-CD E5-7F 00-00 00-00 00-00 00-00 00-00 30-E8 00-80 E5-7F
> 00-00 D0-E8 00-80 E5-7F 00-00 70-E9 00-80 E5-7F 00-00 10-EA 00-80 E5-7F 00-00
> F0-58 00-80 E5-7F 00-00 04-00 00-00 04-00 00-00 04-00 00-00 65-45 76-65 00-00
> 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 E5-7F 00-00 00-00 00-00
> 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 0F-00
> 00-00> })
> Stack trace:
> I0610 20:04:48.709631 24590 sched.cpp:611] Scheduler::resourceOffers took
> 189034ns
> I0610 20:04:49.607378 24589 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:49.607435 24589 hierarchical.hpp:834] Performed allocation for 1
> slaves in 474600ns
> I0610 20:04:50.608489 24582 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:50.608551 24582 hierarchical.hpp:834] Performed allocation for 1
> slaves in 517133ns
> I0610 20:04:51.609849 24589 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:51.609908 24589 hierarchical.hpp:834] Performed allocation for 1
> slaves in 440523ns
> I0610 20:04:52.611188 24584 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:52.611250 24584 hierarchical.hpp:834] Performed allocation for 1
> slaves in 471882ns
> I0610 20:04:53.612911 24581 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:53.612962 24581 hierarchical.hpp:834] Performed allocation for 1
> slaves in 411941ns
> I0610 20:04:54.614280 24582 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:54.614336 24582 hierarchical.hpp:834] Performed allocation for 1
> slaves in 448103ns
> I0610 20:04:55.615985 24583 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:55.616046 24583 hierarchical.hpp:834] Performed allocation for 1
> slaves in 494677ns
> I0610 20:04:56.616896 24580 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:56.616952 24580 hierarchical.hpp:834] Performed allocation for 1
> slaves in 461555ns
> I0610 20:04:57.618814 24587 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:57.618885 24587 hierarchical.hpp:834] Performed allocation for 1
> slaves in 491478ns
> I0610 20:04:58.620564 24589 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:58.620621 24589 hierarchical.hpp:834] Performed allocation for 1
> slaves in 434384ns
> I0610 20:04:59.621649 24584 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:04:59.621706 24584 hierarchical.hpp:834] Performed allocation for 1
> slaves in 453279ns
> I0610 20:05:00.623241 24593 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:05:00.623299 24593 hierarchical.hpp:834] Performed allocation for 1
> slaves in 423551ns
> I0610 20:05:01.624984 24590 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:05:01.625041 24590 hierarchical.hpp:834] Performed allocation for 1
> slaves in 458545ns
> I0610 20:05:02.626266 24591 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:05:02.626327 24591 hierarchical.hpp:834] Performed allocation for 1
> slaves in 490068ns
> I0610 20:05:03.627702 24593 hierarchical.hpp:933] No resources available to
> allocate!
> I0610 20:05:03.627766 24593 hierarchical.hpp:834] Performed allocation for 1
> slaves in 473279ns
> I0610 20:05:03.666060 24581 slave.cpp:4104] Querying resource estimator for
> oversubscribable resources
> I0610 20:05:03.666353 24581 slave.cpp:4125] Received oversubscribable
> resources from the resource estimator
> I0610 20:05:03.680258 24588 slave.cpp:2895] Received ping from
> slave-observer(42)@172.17.0.231:32907
> F0610 20:05:03.725155 24561 fetcher_cache_tests.cpp:354] CHECK_READY(offers):
> is PENDING Failed to wait for resource offers
> *** Check failure stack trace: ***
> @ 0x7fe5cc5a2a0d google::LogMessage::Fail()
> @ 0x7fe5cc5a1dee google::LogMessage::SendToLog()
> @ 0x7fe5cc5a26cd google::LogMessage::Flush()
> @ 0x7fe5cc5a5b38 google::LogMessageFatal::~LogMessageFatal()
> @ 0x8947c7 _CheckFatal::~_CheckFatal()
> @ 0xadf458
> mesos::internal::tests::FetcherCacheTest::launchTask()
> @ 0xae5ea4
> mesos::internal::tests::FetcherCacheTest_LocalCachedExtract_Test::TestBody()
> @ 0x128fb83
> testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x127a7e7
> testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x1261c45 testing::Test::Run()
> @ 0x126287b testing::TestInfo::Run()
> @ 0x1262ec7 testing::TestCase::Run()
> @ 0x126854a testing::internal::UnitTestImpl::RunAllTests()
> @ 0x128c163
> testing::internal::HandleSehExceptionsInMethodIfSupported<>()
> @ 0x127c817
> testing::internal::HandleExceptionsInMethodIfSupported<>()
> @ 0x1268247 testing::UnitTest::Run()
> @ 0xca398e main
> @ 0x7fe5c8436ec5 (unknown)
> @ 0x749e8c (unknown)
> {noformat}
> [~bernd-mesos] not sure if there's a ticket capturing this already, sorry if
> this is a duplicate.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
