Anand Mazumdar created MESOS-4661:
-------------------------------------
Summary: SlaveRecoveryTest/0.ReconnectHTTPExecutor is flaky
Key: MESOS-4661
URL: https://issues.apache.org/jira/browse/MESOS-4661
Project: Mesos
Issue Type: Bug
Reporter: Anand Mazumdar
Showed up on ASF CI:
https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu:14.04,label_exp=docker%7C%7CHadoop/1660/consoleFull
{code}
[ RUN ] SlaveRecoveryTest/0.ReconnectHTTPExecutor
I0212 00:23:08.177824 702 leveldb.cpp:174] Opened db in 2.499462ms
I0212 00:23:08.179204 702 leveldb.cpp:181] Compacted db in 1.206514ms
I0212 00:23:08.179400 702 leveldb.cpp:196] Created db iterator in 36168ns
I0212 00:23:08.179538 702 leveldb.cpp:202] Seeked to beginning of db in 2343ns
I0212 00:23:08.179651 702 leveldb.cpp:271] Iterated through 0 keys in the db
in 471ns
I0212 00:23:08.179816 702 replica.cpp:779] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0212 00:23:08.180547 736 recover.cpp:447] Starting replica recovery
I0212 00:23:08.181025 736 recover.cpp:473] Replica is in EMPTY status
I0212 00:23:08.182406 722 replica.cpp:673] Replica in EMPTY status received a
broadcasted recover request from (9452)@172.17.0.2:57200
I0212 00:23:08.182624 724 recover.cpp:193] Received a recover response from a
replica in EMPTY status
I0212 00:23:08.183368 736 recover.cpp:564] Updating replica status to STARTING
I0212 00:23:08.184329 730 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 726589ns
I0212 00:23:08.184361 730 replica.cpp:320] Persisted replica status to
STARTING
I0212 00:23:08.184501 722 recover.cpp:473] Replica is in STARTING status
I0212 00:23:08.186000 733 replica.cpp:673] Replica in STARTING status
received a broadcasted recover request from (9453)@172.17.0.2:57200
I0212 00:23:08.186311 735 recover.cpp:193] Received a recover response from a
replica in STARTING status
I0212 00:23:08.186650 724 recover.cpp:564] Updating replica status to VOTING
I0212 00:23:08.186785 727 master.cpp:376] Master
6508f198-e145-4d76-844f-0460dc5d7d39 (ca60addecc0b) started on 172.17.0.2:57200
I0212 00:23:08.186808 727 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/9KHFn8/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="/mesos/mesos-0.28.0/_inst/share/mesos/webui"
--work_dir="/tmp/9KHFn8/master" --zk_session_timeout="10secs"
I0212 00:23:08.187353 727 master.cpp:423] Master only allowing authenticated
frameworks to register
I0212 00:23:08.187366 727 master.cpp:428] Master only allowing authenticated
slaves to register
I0212 00:23:08.187376 727 credentials.hpp:35] Loading credentials for
authentication from '/tmp/9KHFn8/credentials'
I0212 00:23:08.187533 724 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 460382ns
I0212 00:23:08.187676 724 replica.cpp:320] Persisted replica status to VOTING
I0212 00:23:08.187770 727 master.cpp:468] Using default 'crammd5'
authenticator
I0212 00:23:08.188096 727 master.cpp:537] Using default 'basic' HTTP
authenticator
I0212 00:23:08.188344 727 master.cpp:571] Authorization enabled
I0212 00:23:08.188544 728 recover.cpp:578] Successfully joined the Paxos group
I0212 00:23:08.189209 722 hierarchical.cpp:144] Initialized hierarchical
allocator process
I0212 00:23:08.189337 731 whitelist_watcher.cpp:77] No whitelist given
I0212 00:23:08.189357 728 recover.cpp:462] Recover process terminated
I0212 00:23:08.192903 733 master.cpp:1712] The newly elected leader is
[email protected]:57200 with id 6508f198-e145-4d76-844f-0460dc5d7d39
I0212 00:23:08.192940 733 master.cpp:1725] Elected as the leading master!
I0212 00:23:08.193133 733 master.cpp:1470] Recovering from registrar
I0212 00:23:08.193269 734 registrar.cpp:307] Recovering registrar
I0212 00:23:08.194031 734 log.cpp:659] Attempting to start the writer
I0212 00:23:08.195296 730 replica.cpp:493] Replica received implicit promise
request from (9455)@172.17.0.2:57200 with proposal 1
I0212 00:23:08.196018 730 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 674634ns
I0212 00:23:08.196050 730 replica.cpp:342] Persisted promised to 1
I0212 00:23:08.196997 732 coordinator.cpp:238] Coordinator attempting to fill
missing positions
I0212 00:23:08.198523 723 replica.cpp:388] Replica received explicit promise
request from (9456)@172.17.0.2:57200 for position 0 with proposal 2
I0212 00:23:08.199019 723 leveldb.cpp:341] Persisting action (8 bytes) to
leveldb took 434171ns
I0212 00:23:08.199137 723 replica.cpp:712] Persisted action at 0
I0212 00:23:08.200501 736 replica.cpp:537] Replica received write request for
position 0 from (9457)@172.17.0.2:57200
I0212 00:23:08.200671 736 leveldb.cpp:436] Reading position from leveldb took
46392ns
I0212 00:23:08.201197 736 leveldb.cpp:341] Persisting action (14 bytes) to
leveldb took 383148ns
I0212 00:23:08.201302 736 replica.cpp:712] Persisted action at 0
I0212 00:23:08.202224 722 replica.cpp:691] Replica received learned notice
for position 0 from @0.0.0.0:0
I0212 00:23:08.202652 722 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 391276ns
I0212 00:23:08.202682 722 replica.cpp:712] Persisted action at 0
I0212 00:23:08.202709 722 replica.cpp:697] Replica learned NOP action at
position 0
I0212 00:23:08.203299 724 log.cpp:675] Writer started with ending position 0
I0212 00:23:08.204588 732 leveldb.cpp:436] Reading position from leveldb took
30157ns
I0212 00:23:08.205791 730 registrar.cpp:340] Successfully fetched the
registry (0B) in 12.461056ms
I0212 00:23:08.205942 730 registrar.cpp:439] Applied 1 operations in 43255ns;
attempting to update the 'registry'
I0212 00:23:08.206743 724 log.cpp:683] Attempting to append 170 bytes to the
log
I0212 00:23:08.206871 730 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 1
I0212 00:23:08.207784 725 replica.cpp:537] Replica received write request for
position 1 from (9458)@172.17.0.2:57200
I0212 00:23:08.208200 725 leveldb.cpp:341] Persisting action (189 bytes) to
leveldb took 374150ns
I0212 00:23:08.208232 725 replica.cpp:712] Persisted action at 1
I0212 00:23:08.209386 725 replica.cpp:691] Replica received learned notice
for position 1 from @0.0.0.0:0
I0212 00:23:08.209978 725 leveldb.cpp:341] Persisting action (191 bytes) to
leveldb took 556897ns
I0212 00:23:08.210010 725 replica.cpp:712] Persisted action at 1
I0212 00:23:08.210031 725 replica.cpp:697] Replica learned APPEND action at
position 1
I0212 00:23:08.211006 735 registrar.cpp:484] Successfully updated the
'registry' in 4.942848ms
I0212 00:23:08.211163 735 registrar.cpp:370] Successfully recovered registrar
I0212 00:23:08.211262 724 log.cpp:702] Attempting to truncate the log to 1
I0212 00:23:08.211907 724 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 2
I0212 00:23:08.211697 725 master.cpp:1522] Recovered 0 slaves from the
Registry (131B) ; allowing 10mins for slaves to re-register
I0212 00:23:08.211725 730 hierarchical.cpp:171] Skipping recovery of
hierarchical allocator: nothing to recover
I0212 00:23:08.212816 726 replica.cpp:537] Replica received write request for
position 2 from (9459)@172.17.0.2:57200
I0212 00:23:08.213194 726 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 339806ns
I0212 00:23:08.213299 726 replica.cpp:712] Persisted action at 2
I0212 00:23:08.213943 726 replica.cpp:691] Replica received learned notice
for position 2 from @0.0.0.0:0
I0212 00:23:08.214470 726 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 318618ns
I0212 00:23:08.214593 726 leveldb.cpp:399] Deleting ~1 keys from leveldb took
32071ns
I0212 00:23:08.214700 726 replica.cpp:712] Persisted action at 2
I0212 00:23:08.214804 726 replica.cpp:697] Replica learned TRUNCATE action at
position 2
I0212 00:23:08.224455 702 containerizer.cpp:149] Using isolation:
posix/cpu,posix/mem,filesystem/posix
W0212 00:23:08.224927 702 backend.cpp:48] Failed to create 'bind' backend:
BindBackend requires root privileges
I0212 00:23:08.229086 735 slave.cpp:193] Slave started on 172.17.0.2:57200
I0212 00:23:08.229187 735 slave.cpp:194] 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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
--docker_puller_timeout="60" --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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/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="/mesos/mesos-0.28.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
--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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ"
I0212 00:23:08.229606 735 credentials.hpp:83] Loading credential for
authentication from
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/credential'
I0212 00:23:08.229796 735 slave.cpp:324] Slave using credential for:
test-principal
I0212 00:23:08.230057 735 resources.cpp:564] Parsing resources as JSON
failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0212 00:23:08.230463 735 slave.cpp:464] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0212 00:23:08.230525 735 slave.cpp:472] Slave attributes: [ ]
I0212 00:23:08.230540 735 slave.cpp:477] Slave hostname: ca60addecc0b
I0212 00:23:08.231462 702 sched.cpp:222] Version: 0.28.0
I0212 00:23:08.231681 727 state.cpp:58] Recovering state from
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta'
I0212 00:23:08.232105 722 sched.cpp:326] New master detected at
[email protected]:57200
I0212 00:23:08.232179 736 status_update_manager.cpp:200] Recovering status
update manager
I0212 00:23:08.232193 722 sched.cpp:382] Authenticating with master
[email protected]:57200
I0212 00:23:08.232389 722 sched.cpp:389] Using default CRAM-MD5 authenticatee
I0212 00:23:08.232497 736 containerizer.cpp:407] Recovering containerizer
I0212 00:23:08.232764 722 authenticatee.cpp:121] Creating new client SASL
connection
I0212 00:23:08.233146 722 master.cpp:5523] Authenticating
[email protected]:57200
I0212 00:23:08.233239 733 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(654)@172.17.0.2:57200
I0212 00:23:08.233537 729 authenticator.cpp:98] Creating new server SASL
connection
I0212 00:23:08.233816 728 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0212 00:23:08.233849 728 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0212 00:23:08.234035 728 authenticator.cpp:203] Received SASL authentication
start
I0212 00:23:08.234179 728 authenticator.cpp:325] Authentication requires more
steps
I0212 00:23:08.234376 728 authenticatee.cpp:258] Received SASL authentication
step
I0212 00:23:08.234611 725 authenticator.cpp:231] Received SASL authentication
step
I0212 00:23:08.234648 725 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'ca60addecc0b' server FQDN: 'ca60addecc0b'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0212 00:23:08.234666 725 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0212 00:23:08.234716 725 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0212 00:23:08.234714 728 provisioner.cpp:245] Provisioner recovery complete
I0212 00:23:08.234750 725 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'ca60addecc0b' server FQDN: 'ca60addecc0b'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0212 00:23:08.234762 725 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0212 00:23:08.234772 725 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0212 00:23:08.234792 725 authenticator.cpp:317] Authentication success
I0212 00:23:08.235038 734 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(654)@172.17.0.2:57200
I0212 00:23:08.235272 731 master.cpp:5553] Successfully authenticated
principal 'test-principal' at
[email protected]:57200
I0212 00:23:08.235343 730 slave.cpp:4565] Finished recovery
I0212 00:23:08.235601 724 authenticatee.cpp:298] Authentication success
I0212 00:23:08.235915 730 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0212 00:23:08.235918 731 sched.cpp:471] Successfully authenticated with
master [email protected]:57200
I0212 00:23:08.235970 731 sched.cpp:776] Sending SUBSCRIBE call to
[email protected]:57200
I0212 00:23:08.236078 731 sched.cpp:809] Will retry registration in
404.045727ms if necessary
I0212 00:23:08.236256 726 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0212 00:23:08.236318 721 master.cpp:2280] Received SUBSCRIBE call for
framework 'default' at
[email protected]:57200
I0212 00:23:08.236399 721 master.cpp:1751] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0212 00:23:08.236405 726 slave.cpp:796] New master detected at
[email protected]:57200
I0212 00:23:08.236501 726 slave.cpp:859] Authenticating with master
[email protected]:57200
I0212 00:23:08.236528 726 slave.cpp:864] Using default CRAM-MD5 authenticatee
I0212 00:23:08.236665 726 slave.cpp:832] Detecting new master
I0212 00:23:08.236723 721 authenticatee.cpp:121] Creating new client SASL
connection
I0212 00:23:08.236866 730 status_update_manager.cpp:174] Pausing sending
status updates
I0212 00:23:08.236886 726 master.cpp:2351] Subscribing framework default with
checkpointing enabled and capabilities [ ]
I0212 00:23:08.237319 726 master.cpp:5523] Authenticating
[email protected]:57200
I0212 00:23:08.237365 731 hierarchical.cpp:265] Added framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:08.237462 726 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(655)@172.17.0.2:57200
I0212 00:23:08.237426 721 sched.cpp:703] Framework registered with
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:08.237542 721 sched.cpp:717] Scheduler::registered took 28318ns
I0212 00:23:08.237630 731 hierarchical.cpp:1403] No resources available to
allocate!
I0212 00:23:08.237660 733 authenticator.cpp:98] Creating new server SASL
connection
I0212 00:23:08.237776 731 hierarchical.cpp:1498] No inverse offers to send
out!
I0212 00:23:08.237807 731 hierarchical.cpp:1096] Performed allocation for 0
slaves in 325262ns
I0212 00:23:08.237957 730 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0212 00:23:08.237980 730 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0212 00:23:08.238064 731 authenticator.cpp:203] Received SASL authentication
start
I0212 00:23:08.238278 731 authenticator.cpp:325] Authentication requires more
steps
I0212 00:23:08.238450 731 authenticatee.cpp:258] Received SASL authentication
step
I0212 00:23:08.238646 726 authenticator.cpp:231] Received SASL authentication
step
I0212 00:23:08.238674 726 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'ca60addecc0b' server FQDN: 'ca60addecc0b'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0212 00:23:08.238683 726 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0212 00:23:08.238723 726 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0212 00:23:08.238762 726 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'ca60addecc0b' server FQDN: 'ca60addecc0b'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0212 00:23:08.238780 726 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0212 00:23:08.238790 726 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0212 00:23:08.238809 726 authenticator.cpp:317] Authentication success
I0212 00:23:08.238901 721 authenticatee.cpp:298] Authentication success
I0212 00:23:08.238956 728 master.cpp:5553] Successfully authenticated
principal 'test-principal' at [email protected]:57200
I0212 00:23:08.239148 728 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(655)@172.17.0.2:57200
I0212 00:23:08.239542 723 slave.cpp:927] Successfully authenticated with
master [email protected]:57200
I0212 00:23:08.239792 723 slave.cpp:1321] Will retry registration in
1.349492ms if necessary
I0212 00:23:08.239976 727 master.cpp:4237] Registering slave at
[email protected]:57200 (ca60addecc0b) with id
6508f198-e145-4d76-844f-0460dc5d7d39-S0
I0212 00:23:08.240497 723 registrar.cpp:439] Applied 1 operations in 75509ns;
attempting to update the 'registry'
I0212 00:23:08.241351 735 log.cpp:683] Attempting to append 339 bytes to the
log
I0212 00:23:08.241459 725 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 3
I0212 00:23:08.242326 729 replica.cpp:537] Replica received write request for
position 3 from (9473)@172.17.0.2:57200
I0212 00:23:08.242533 729 leveldb.cpp:341] Persisting action (358 bytes) to
leveldb took 165261ns
I0212 00:23:08.242503 736 slave.cpp:1321] Will retry registration in
39.261658ms if necessary
I0212 00:23:08.242561 729 replica.cpp:712] Persisted action at 3
I0212 00:23:08.242738 736 master.cpp:4225] Ignoring register slave message
from [email protected]:57200 (ca60addecc0b) as admission is already in progress
I0212 00:23:08.243294 729 replica.cpp:691] Replica received learned notice
for position 3 from @0.0.0.0:0
I0212 00:23:08.244000 729 leveldb.cpp:341] Persisting action (360 bytes) to
leveldb took 609006ns
I0212 00:23:08.244027 729 replica.cpp:712] Persisted action at 3
I0212 00:23:08.244048 729 replica.cpp:697] Replica learned APPEND action at
position 3
I0212 00:23:08.245573 732 registrar.cpp:484] Successfully updated the
'registry' in 4.942848ms
I0212 00:23:08.245805 735 log.cpp:702] Attempting to truncate the log to 3
I0212 00:23:08.246033 732 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 4
I0212 00:23:08.246318 735 slave.cpp:3482] Received ping from
slave-observer(286)@172.17.0.2:57200
I0212 00:23:08.246422 729 master.cpp:4305] Registered slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200
(ca60addecc0b) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0212 00:23:08.246541 724 slave.cpp:971] Registered with master
[email protected]:57200; given slave ID 6508f198-e145-4d76-844f-0460dc5d7d39-S0
I0212 00:23:08.246569 724 fetcher.cpp:81] Clearing fetcher cache
I0212 00:23:08.246753 729 status_update_manager.cpp:181] Resuming sending
status updates
I0212 00:23:08.246755 735 hierarchical.cpp:473] Added slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 (ca60addecc0b) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0212 00:23:08.246899 724 slave.cpp:994] Checkpointing SlaveInfo to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/slave.info'
I0212 00:23:08.247195 733 replica.cpp:537] Replica received write request for
position 4 from (9474)@172.17.0.2:57200
I0212 00:23:08.247467 724 slave.cpp:1030] Forwarding total oversubscribed
resources
I0212 00:23:08.247604 724 master.cpp:4646] Received update of slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200
(ca60addecc0b) with total oversubscribed resources
I0212 00:23:08.247725 733 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 426871ns
I0212 00:23:08.248337 733 replica.cpp:712] Persisted action at 4
I0212 00:23:08.248267 734 master.cpp:5352] Sending 1 offers to framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200
I0212 00:23:08.247841 735 hierarchical.cpp:1498] No inverse offers to send
out!
I0212 00:23:08.249011 735 hierarchical.cpp:1116] Performed allocation for
slave 6508f198-e145-4d76-844f-0460dc5d7d39-S0 in 2.212824ms
I0212 00:23:08.249294 733 replica.cpp:691] Replica received learned notice
for position 4 from @0.0.0.0:0
I0212 00:23:08.249460 735 hierarchical.cpp:531] Slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 (ca60addecc0b) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0212 00:23:08.249600 735 hierarchical.cpp:1403] No resources available to
allocate!
I0212 00:23:08.249640 735 hierarchical.cpp:1498] No inverse offers to send
out!
I0212 00:23:08.249661 735 hierarchical.cpp:1116] Performed allocation for
slave 6508f198-e145-4d76-844f-0460dc5d7d39-S0 in 151833ns
I0212 00:23:08.249689 733 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 364080ns
I0212 00:23:08.249749 733 leveldb.cpp:399] Deleting ~2 keys from leveldb took
37314ns
I0212 00:23:08.249769 733 replica.cpp:712] Persisted action at 4
I0212 00:23:08.249791 733 replica.cpp:697] Replica learned TRUNCATE action at
position 4
I0212 00:23:08.250519 734 sched.cpp:873] Scheduler::resourceOffers took
131511ns
I0212 00:23:08.252310 730 master.cpp:3138] Processing ACCEPT call for offers:
[ 6508f198-e145-4d76-844f-0460dc5d7d39-O0 ] on slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200
(ca60addecc0b) for framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
(default) at [email protected]:57200
I0212 00:23:08.252357 730 master.cpp:2825] Authorizing framework principal
'test-principal' to launch task 1 as user 'mesos'
W0212 00:23:08.253898 730 validation.cpp:404] Executor http for task 1 uses
less CPUs (None) than the minimum required (0.01). Please update your executor,
as this will be mandatory in future releases.
W0212 00:23:08.253940 730 validation.cpp:416] Executor http for task 1 uses
less memory (None) than the minimum required (32MB). Please update your
executor, as this will be mandatory in future releases.
I0212 00:23:08.254369 730 master.hpp:176] Adding task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 (ca60addecc0b)
I0212 00:23:08.254614 730 master.cpp:3623] Launching task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200 (ca60addecc0b)
I0212 00:23:08.255058 731 slave.cpp:1361] Got assigned task 1 for framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:08.255224 731 slave.cpp:5271] Checkpointing FrameworkInfo to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/framework.info'
I0212 00:23:08.255635 731 slave.cpp:5282] Checkpointing framework pid
'[email protected]:57200' to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/framework.pid'
I0212 00:23:08.256270 731 slave.cpp:1480] Launching task 1 for framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:08.256856 731 paths.cpp:474] Trying to chown
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b'
to user 'mesos'
I0212 00:23:08.262581 731 slave.cpp:5723] Checkpointing ExecutorInfo to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/executor.info'
I0212 00:23:08.263450 731 slave.cpp:5351] Launching executor http of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 with resources in work
directory
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b'
I0212 00:23:08.263888 722 containerizer.cpp:666] Starting container
'f8801ac8-ee83-4184-b4b4-2b984319a80b' for executor 'http' of framework
'6508f198-e145-4d76-844f-0460dc5d7d39-0000'
I0212 00:23:08.264026 731 slave.cpp:5746] Checkpointing TaskInfo to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b/tasks/1/task.info'
I0212 00:23:08.264550 731 slave.cpp:1698] Queuing task '1' for executor
'http' of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:08.264680 731 slave.cpp:749] Successfully attached file
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b'
I0212 00:23:08.270336 722 launcher.cpp:147] Forked child with pid '7435' for
container 'f8801ac8-ee83-4184-b4b4-2b984319a80b'
I0212 00:23:08.270587 722 containerizer.cpp:1104] Checkpointing executor's
forked pid 7435 to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b/pids/forked.pid'
I0212 00:23:09.191407 733 hierarchical.cpp:1403] No resources available to
allocate!
I0212 00:23:09.191504 733 hierarchical.cpp:1498] No inverse offers to send
out!
I0212 00:23:09.191545 733 hierarchical.cpp:1096] Performed allocation for 1
slaves in 433612ns
2016-02-12
00:23:10,106:702(0x2b104d40e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket
[127.0.0.1:33395] zk retcode=-4, errno=111(Connection refused): server refused
to accept the client
I0212 00:23:10.192740 732 hierarchical.cpp:1403] No resources available to
allocate!
I0212 00:23:10.192936 732 hierarchical.cpp:1498] No inverse offers to send
out!
I0212 00:23:10.193123 732 hierarchical.cpp:1096] Performed allocation for 1
slaves in 675800ns
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0212 00:23:10.628480 7449 process.cpp:991] libprocess is initialized on
172.17.0.2:36401 for 16 cpus
I0212 00:23:10.630352 7478 logging.cpp:193] Logging to STDERR
I0212 00:23:10.630378 7478 executor.cpp:172] Version: 0.28.0
I0212 00:23:10.633038 7474 executor.cpp:316] Connected with the agent
I0212 00:23:10.634546 7472 executor.cpp:247] Sending SUBSCRIBE call to
http://172.17.0.2:57200/slave/api/v1/executor
I0212 00:23:10.644304 726 process.cpp:3141] Handling HTTP event for process
'slave' with path: '/slave/api/v1/executor'
I0212 00:23:10.645184 725 http.cpp:190] HTTP POST for /slave/api/v1/executor
from 172.17.0.2:43654
I0212 00:23:10.646143 725 slave.cpp:2476] Received Subscribe request for HTTP
executor 'http' of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:10.646690 725 slave.cpp:2539] Creating a marker file for HTTP
based executor 'http' of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
(via HTTP) at path
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b/http.marker'
I0212 00:23:10.649456 727 slave.cpp:1863] Sending queued task '1' to executor
'http' of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 (via HTTP)
I0212 00:23:10.653252 7477 executor.cpp:588] Enqueuing event SUBSCRIBED
received from http://172.17.0.2:57200/slave/api/v1/executor
I0212 00:23:10.654537 7477 executor.cpp:588] Enqueuing event LAUNCH received
from http://172.17.0.2:57200/slave/api/v1/executor
Received a SUBSCRIBED event
Starting task 1
Finishing task 1
I0212 00:23:10.658287 7479 executor.cpp:247] Sending UPDATE call to
http://172.17.0.2:57200/slave/api/v1/executor
I0212 00:23:10.658638 7479 executor.cpp:247] Sending UPDATE call to
http://172.17.0.2:57200/slave/api/v1/executor
I0212 00:23:10.660832 702 slave.cpp:668] Slave terminating
I0212 00:23:10.661602 734 master.cpp:1174] Slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200
(ca60addecc0b) disconnected
I0212 00:23:10.661725 734 master.cpp:2635] Disconnecting slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200 (ca60addecc0b)
I0212 00:23:10.661787 7483 executor.cpp:586] Enqueuing locally injected event
ERROR
I0212 00:23:10.661918 734 master.cpp:2654] Deactivating slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200 (ca60addecc0b)
Received an ERROR event
I0212 00:23:10.662329 724 hierarchical.cpp:560] Slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 deactivated
I0212 00:23:10.662463 7473 executor.cpp:586] Enqueuing locally injected event
ERROR
Received an ERROR event
E0212 00:23:10.663862 7480 executor.cpp:553] End-Of-File received from agent.
The agent closed the event stream
I0212 00:23:10.663905 7480 executor.cpp:357] Disconnected from agent:
End-Of-File received from agent. The agent closed the event stream
I0212 00:23:10.664577 7480 executor.cpp:411] Will retry connecting with the
agent again in 1.548772469secs
I0212 00:23:10.666635 7474 executor.cpp:316] Connected with the agent
I0212 00:23:10.667372 702 containerizer.cpp:149] Using isolation:
posix/cpu,posix/mem,filesystem/posix
W0212 00:23:10.668131 702 backend.cpp:48] Failed to create 'bind' backend:
BindBackend requires root privileges
I0212 00:23:10.668349 7479 executor.cpp:247] Sending SUBSCRIBE call to
http://172.17.0.2:57200/slave/api/v1/executor
I0212 00:23:10.672874 734 slave.cpp:193] Slave started on 172.17.0.2:57200
I0212 00:23:10.672900 734 slave.cpp:194] 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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
--docker_puller_timeout="60" --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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/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="/mesos/mesos-0.28.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
--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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ"
I0212 00:23:10.673413 734 credentials.hpp:83] Loading credential for
authentication from
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/credential'
I0212 00:23:10.673645 734 slave.cpp:324] Slave using credential for:
test-principal
I0212 00:23:10.673836 734 resources.cpp:564] Parsing resources as JSON
failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0212 00:23:10.674453 734 slave.cpp:464] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0212 00:23:10.674517 734 slave.cpp:472] Slave attributes: [ ]
I0212 00:23:10.674535 734 slave.cpp:477] Slave hostname: ca60addecc0b
I0212 00:23:10.676246 734 process.cpp:3141] Handling HTTP event for process
'slave' with path: '/slave/api/v1/executor'
I0212 00:23:10.676748 732 http.cpp:190] HTTP POST for /slave/api/v1/executor
from 172.17.0.2:43656
I0212 00:23:10.676822 725 state.cpp:58] Recovering state from
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta'
I0212 00:23:10.676888 725 state.cpp:698] No checkpointed resources found at
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/resources/resources.info'
W0212 00:23:10.678992 725 state.cpp:607] Failed to find status updates file
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b/tasks/1/task.updates'
I0212 00:23:10.680610 7475 executor.cpp:586] Enqueuing locally injected event
ERROR
Received an ERROR event
I0212 00:23:10.681663 736 fetcher.cpp:81] Clearing fetcher cache
I0212 00:23:10.681802 736 slave.cpp:4653] Recovering framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:10.681982 736 slave.cpp:5460] Recovering executor 'http' of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:10.683346 724 status_update_manager.cpp:200] Recovering status
update manager
I0212 00:23:10.683668 724 status_update_manager.cpp:208] Recovering executor
'http' of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
W0212 00:23:10.683811 724 status_update_manager.cpp:247] No updates found for
task 1 of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:10.684528 736 slave.cpp:749] Successfully attached file
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b'
I0212 00:23:10.685027 731 containerizer.cpp:407] Recovering containerizer
I0212 00:23:10.685163 731 containerizer.cpp:462] Recovering container
'f8801ac8-ee83-4184-b4b4-2b984319a80b' for executor 'http' of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:10.687144 721 provisioner.cpp:245] Provisioner recovery complete
I0212 00:23:10.688256 721 slave.cpp:4512] Waiting for executor 'http' of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 (via HTTP) to subscribe
I0212 00:23:11.194169 721 hierarchical.cpp:1403] No resources available to
allocate!
I0212 00:23:11.194253 721 hierarchical.cpp:1498] No inverse offers to send
out!
I0212 00:23:11.194303 721 hierarchical.cpp:1096] Performed allocation for 1
slaves in 353879ns
I0212 00:23:11.635766 7475 executor.cpp:247] Sending SUBSCRIBE call to
http://172.17.0.2:57200/slave/api/v1/executor
I0212 00:23:11.637467 731 process.cpp:3141] Handling HTTP event for process
'slave' with path: '/slave/api/v1/executor'
I0212 00:23:11.638025 731 http.cpp:190] HTTP POST for /slave/api/v1/executor
from 172.17.0.2:43656
I0212 00:23:11.638577 731 slave.cpp:2476] Received Subscribe request for HTTP
executor 'http' of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 (via
HTTP)
I0212 00:23:11.638675 731 slave.cpp:2539] Creating a marker file for HTTP
based executor 'http' of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
(via HTTP) at path
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b/http.marker'
I0212 00:23:11.639288 731 slave.cpp:3002] Handling status update TASK_RUNNING
(UUID: b0810058-a1c0-4918-b699-61c16eb0f46a) for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:11.639622 731 slave.cpp:3002] Handling status update
TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:11.641832 729 slave.cpp:5661] Terminating task 1
I0212 00:23:11.643185 721 status_update_manager.cpp:320] Received status
update TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:11.643405 7480 executor.cpp:588] Enqueuing event SUBSCRIBED
received from http://172.17.0.2:57200/slave/api/v1/executor
I0212 00:23:11.643427 721 status_update_manager.cpp:497] Creating
StatusUpdate stream for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:11.644057 721 status_update_manager.cpp:824] Checkpointing UPDATE
for status update TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5)
for task 1 of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
Received a SUBSCRIBED event
I0212 00:23:11.650759 721 status_update_manager.cpp:374] Forwarding update
TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 to the slave
W0212 00:23:11.651098 733 slave.cpp:3346] Dropping status update
TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 sent by status update
manager because the slave is in RECOVERING state
I0212 00:23:11.651199 721 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: b0810058-a1c0-4918-b699-61c16eb0f46a) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:11.651268 721 status_update_manager.cpp:824] Checkpointing UPDATE
for status update TASK_RUNNING (UUID: b0810058-a1c0-4918-b699-61c16eb0f46a) for
task 1 of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:11.651361 733 slave.cpp:3294] Status update manager successfully
handled status update TASK_FINISHED (UUID:
4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
II0212 00:23:11.652582 7474 executor.cpp:588] Enqueuing event ACKNOWLEDGED
received from http://172.17.0.2:57200/slave/api/v1/executor
0212 00:23:11.652552 733 slave.cpp:3294] Status update manager successfully
handled status update TASK_RUNNING (UUID: b0810058-a1c0-4918-b699-61c16eb0f46a)
for task 1 of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
Received an ACKNOWLEDGED event
I0212 00:23:11.653772 7479 executor.cpp:588] Enqueuing event ACKNOWLEDGED
received from http://172.17.0.2:57200/slave/api/v1/executor
Received an ACKNOWLEDGED event
I0212 00:23:12.194978 732 hierarchical.cpp:1403] No resources available to
allocate!
I0212 00:23:12.195066 732 hierarchical.cpp:1498] No inverse offers to send
out!
I0212 00:23:12.195116 732 hierarchical.cpp:1096] Performed allocation for 1
slaves in 376845ns
I0212 00:23:12.689191 732 slave.cpp:2942] Cleaning up un-reregistered
executors
I0212 00:23:12.689342 732 slave.cpp:4565] Finished recovery
I0212 00:23:12.690191 732 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0212 00:23:12.690508 732 status_update_manager.cpp:174] Pausing sending
status updates
I0212 00:23:12.690551 735 slave.cpp:796] New master detected at
[email protected]:57200
I0212 00:23:12.690683 735 slave.cpp:859] Authenticating with master
[email protected]:57200
I0212 00:23:12.690709 735 slave.cpp:864] Using default CRAM-MD5 authenticatee
I0212 00:23:12.690920 735 slave.cpp:832] Detecting new master
I0212 00:23:12.691071 735 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0212 00:23:12.691187 730 authenticatee.cpp:121] Creating new client SASL
connection
I0212 00:23:12.691465 735 master.cpp:5523] Authenticating
[email protected]:57200
I0212 00:23:12.691567 730 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(656)@172.17.0.2:57200
I0212 00:23:12.691818 727 authenticator.cpp:98] Creating new server SASL
connection
I0212 00:23:12.692021 735 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0212 00:23:12.692049 735 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0212 00:23:12.692140 735 authenticator.cpp:203] Received SASL authentication
start
I0212 00:23:12.692198 735 authenticator.cpp:325] Authentication requires more
steps
I0212 00:23:12.692276 735 authenticatee.cpp:258] Received SASL authentication
step
I0212 00:23:12.692363 735 authenticator.cpp:231] Received SASL authentication
step
I0212 00:23:12.692395 735 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'ca60addecc0b' server FQDN: 'ca60addecc0b'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0212 00:23:12.692409 735 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0212 00:23:12.692461 735 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0212 00:23:12.692489 735 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: 'ca60addecc0b' server FQDN: 'ca60addecc0b'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0212 00:23:12.692502 735 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0212 00:23:12.692510 735 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0212 00:23:12.692529 735 authenticator.cpp:317] Authentication success
I0212 00:23:12.692620 727 authenticatee.cpp:298] Authentication success
I0212 00:23:12.692713 735 master.cpp:5553] Successfully authenticated
principal 'test-principal' at [email protected]:57200
I0212 00:23:12.692744 727 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(656)@172.17.0.2:57200
I0212 00:23:12.693045 722 slave.cpp:927] Successfully authenticated with
master [email protected]:57200
I0212 00:23:12.693542 722 slave.cpp:1321] Will retry registration in
7.824819ms if necessary
I0212 00:23:12.694125 722 master.cpp:4397] Re-registering slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200 (ca60addecc0b)
I0212 00:23:12.694430 728 slave.cpp:1071] Re-registered with master
[email protected]:57200
I0212 00:23:12.694520 728 slave.cpp:1107] Forwarding total oversubscribed
resources
I0212 00:23:12.694645 730 hierarchical.cpp:548] Slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 reactivated
I0212 00:23:12.694563 731 status_update_manager.cpp:181] Resuming sending
status updates
I0212 00:23:12.694710 722 master.cpp:4584] Sending updated checkpointed
resources to slave 6508f198-e145-4d76-844f-0460dc5d7d39-S0 at
[email protected]:57200 (ca60addecc0b)
W0212 00:23:12.694721 731 status_update_manager.cpp:188] Resending status
update TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.694771 731 status_update_manager.cpp:374] Forwarding update
TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 to the slave
I0212 00:23:12.694808 736 slave.cpp:2248] Updating framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 pid to
[email protected]:57200
I0212 00:23:12.694856 736 slave.cpp:2264] Checkpointing framework pid
'[email protected]:57200' to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/framework.pid'
I0212 00:23:12.694876 722 master.cpp:4646] Received update of slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200
(ca60addecc0b) with total oversubscribed resources
I0212 00:23:12.695252 732 status_update_manager.cpp:181] Resuming sending
status updates
W0212 00:23:12.695286 732 status_update_manager.cpp:188] Resending status
update TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.695314 732 status_update_manager.cpp:374] Forwarding update
TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 to the slave
I0212 00:23:12.695497 736 slave.cpp:2341] Updated checkpointed resources from
to
I0212 00:23:12.695591 736 slave.cpp:3400] Forwarding the update TASK_FINISHED
(UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 to [email protected]:57200
I0212 00:23:12.695616 722 hierarchical.cpp:531] Slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 (ca60addecc0b) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0212 00:23:12.696008 722 hierarchical.cpp:1403] No resources available to
allocate!
I0212 00:23:12.696061 722 hierarchical.cpp:1498] No inverse offers to send
out!
I0212 00:23:12.696094 722 hierarchical.cpp:1116] Performed allocation for
slave 6508f198-e145-4d76-844f-0460dc5d7d39-S0 in 290636ns
I0212 00:23:12.696115 728 master.cpp:4791] Status update TASK_FINISHED (UUID:
4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 from slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200 (ca60addecc0b)
I0212 00:23:12.696157 728 master.cpp:4839] Forwarding status update
TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.696342 728 master.cpp:6447] Updating the state of task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 (latest state:
TASK_FINISHED, status update state: TASK_FINISHED)
I0212 00:23:12.696535 732 sched.cpp:981] Scheduler::statusUpdate took 115209ns
I0212 00:23:12.696918 728 master.cpp:3949] Processing ACKNOWLEDGE call
4674114a-c022-4945-ac98-52c0fae325e5 for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200 on slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0
I0212 00:23:12.696991 736 slave.cpp:3400] Forwarding the update TASK_FINISHED
(UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 to [email protected]:57200
I0212 00:23:12.696982 728 master.cpp:6513] Removing task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 on slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200 (ca60addecc0b)
I0212 00:23:12.697381 728 master.cpp:4791] Status update TASK_FINISHED (UUID:
4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 from slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200 (ca60addecc0b)
I0212 00:23:12.697407 733 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1
of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.697418 728 master.cpp:4839] Forwarding status update
TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
W0212 00:23:12.697511 728 master.cpp:4808] Could not lookup task for status
update TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 from slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200 (ca60addecc0b)
I0212 00:23:12.697561 733 status_update_manager.cpp:824] Checkpointing ACK
for status update TASK_FINISHED (UUID: 4674114a-c022-4945-ac98-52c0fae325e5)
for task 1 of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.697607 732 hierarchical.cpp:892] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 from framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.697649 728 sched.cpp:981] Scheduler::statusUpdate took 11929ns
I0212 00:23:12.697883 723 master.cpp:3949] Processing ACKNOWLEDGE call
4674114a-c022-4945-ac98-52c0fae325e5 for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200 on slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0
../../src/tests/slave_recovery_tests.cpp:514: Failure
Value of: status.get().state()
Actual: TASK_FINISHED
Expected: TASK_RUNNING
I0212 00:23:12.698258 728 master.cpp:1213] Framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200 disconnected
I0212 00:23:12.698298 728 master.cpp:2576] Disconnecting framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200
I0212 00:23:12.698328 728 master.cpp:2600] Deactivating framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200
I0212 00:23:12.698400 728 master.cpp:1237] Giving framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200 0ns to failover
I0212 00:23:12.698432 722 hierarchical.cpp:375] Deactivated framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.700028 731 master.cpp:5204] Framework failover timeout,
removing framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200
I0212 00:23:12.700059 731 master.cpp:5935] Removing framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at
[email protected]:57200
I0212 00:23:12.700173 724 slave.cpp:2079] Asked to shut down framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 by [email protected]:57200
I0212 00:23:12.700209 724 slave.cpp:2104] Shutting down framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.700268 731 master.cpp:6542] Removing executor 'http' with
resources of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 on slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at [email protected]:57200 (ca60addecc0b)
I0212 00:23:12.700280 724 slave.cpp:4198] Shutting down executor 'http' of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 (via HTTP)
I0212 00:23:12.700736 731 hierarchical.cpp:326] Removed framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
W0212 00:23:12.701771 733 status_update_manager.cpp:446] Acknowledged a
terminal status update TASK_FINISHED (UUID:
4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 but updates are still pending
I0212 00:23:12.701815 733 status_update_manager.cpp:528] Cleaning up status
update stream for task 1 of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.701967 7483 executor.cpp:588] Enqueuing event SHUTDOWN received
from http://172.17.0.2:57200/slave/api/v1/executor
I0212 00:23:12.702188 733 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1
of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.702289 729 slave.cpp:2412] Status update manager successfully
handled status update acknowledgement (UUID:
4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.702337 729 slave.cpp:5702] Completing task 1
E0212 00:23:12.702405 729 slave.cpp:2405] Failed to handle status update
acknowledgement (UUID: 4674114a-c022-4945-ac98-52c0fae325e5) for task 1 of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000: Cannot find the status
update stream for task 1 of framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.702666 702 master.cpp:1027] Master terminating
I0212 00:23:12.703141 7469 executor.cpp:99] Scheduling shutdown of the
executor with grace period: 5secs
Received a SHUTDOWN event
I0212 00:23:12.703639 721 hierarchical.cpp:505] Removed slave
6508f198-e145-4d76-844f-0460dc5d7d39-S0
I0212 00:23:12.704190 735 slave.cpp:3528] [email protected]:57200 exited
W0212 00:23:12.704255 735 slave.cpp:3531] Master disconnected! Waiting for a
new master to be elected
I0212 00:23:12.709121 723 containerizer.cpp:1369] Destroying container
'f8801ac8-ee83-4184-b4b4-2b984319a80b'
I0212 00:23:12.794167 721 containerizer.cpp:1585] Executor for container
'f8801ac8-ee83-4184-b4b4-2b984319a80b' has exited
I0212 00:23:12.795745 730 provisioner.cpp:306] Ignoring destroy request for
unknown container f8801ac8-ee83-4184-b4b4-2b984319a80b
I0212 00:23:12.796075 736 slave.cpp:3886] Executor 'http' of framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000 terminated with signal Killed
I0212 00:23:12.796200 736 slave.cpp:3990] Cleaning up executor 'http' of
framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 (via HTTP)
I0212 00:23:12.796785 726 gc.cpp:54] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b'
for gc 6.9999907800237days in the future
I0212 00:23:12.797026 736 slave.cpp:4078] Cleaning up framework
6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.797086 726 gc.cpp:54] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http'
for gc 6.99999077820741days in the future
I0212 00:23:12.797240 724 status_update_manager.cpp:282] Closing status
update streams for framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000
I0212 00:23:12.797307 726 gc.cpp:54] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http/runs/f8801ac8-ee83-4184-b4b4-2b984319a80b'
for gc 6.99999077706074days in the future
I0212 00:23:12.797404 736 slave.cpp:668] Slave terminating
I0212 00:23:12.797508 726 gc.cpp:54] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000/executors/http'
for gc 6.99999077579852days in the future
I0212 00:23:12.797668 726 gc.cpp:54] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000'
for gc 6.99999077251259days in the future
I0212 00:23:12.797765 726 gc.cpp:54] Scheduling
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_IdJPmJ/meta/slaves/6508f198-e145-4d76-844f-0460dc5d7d39-S0/frameworks/6508f198-e145-4d76-844f-0460dc5d7d39-0000'
for gc 6.99999077156148days in the future
[ FAILED ] SlaveRecoveryTest/0.ReconnectHTTPExecutor, where TypeParam =
mesos::internal::slave::MesosContainerizer (4627 ms)
{code}
Logs from a good run:
{code}
[ RUN ] SlaveRecoveryTest/0.ReconnectHTTPExecutor
I0211 02:48:59.919847 709 leveldb.cpp:174] Opened db in 112.828708ms
I0211 02:48:59.945653 709 leveldb.cpp:181] Compacted db in 25.714139ms
I0211 02:48:59.945758 709 leveldb.cpp:196] Created db iterator in 30431ns
I0211 02:48:59.945778 709 leveldb.cpp:202] Seeked to beginning of db in 3885ns
I0211 02:48:59.945791 709 leveldb.cpp:271] Iterated through 0 keys in the db
in 416ns
I0211 02:48:59.945852 709 replica.cpp:779] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0211 02:48:59.946624 732 recover.cpp:447] Starting replica recovery
I0211 02:48:59.946967 732 recover.cpp:473] Replica is in EMPTY status
I0211 02:48:59.948472 736 replica.cpp:673] Replica in EMPTY status received a
broadcasted recover request from (9458)@172.17.0.3:35649
I0211 02:48:59.949411 732 recover.cpp:193] Received a recover response from a
replica in EMPTY status
I0211 02:48:59.949954 734 recover.cpp:564] Updating replica status to STARTING
I0211 02:48:59.954291 730 master.cpp:376] Master
975d1891-2340-491a-a815-2b79475b741e (39a4cdba96b0) started on 172.17.0.3:35649
I0211 02:48:59.954334 730 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/25xkWj/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="/mesos/mesos-0.28.0/_inst/share/mesos/webui"
--work_dir="/tmp/25xkWj/master" --zk_session_timeout="10secs"
I0211 02:48:59.954715 730 master.cpp:423] Master only allowing authenticated
frameworks to register
I0211 02:48:59.954727 730 master.cpp:428] Master only allowing authenticated
slaves to register
I0211 02:48:59.954736 730 credentials.hpp:35] Loading credentials for
authentication from '/tmp/25xkWj/credentials'
I0211 02:48:59.955116 730 master.cpp:468] Using default 'crammd5'
authenticator
I0211 02:48:59.955307 730 master.cpp:537] Using default 'basic' HTTP
authenticator
I0211 02:48:59.955500 730 master.cpp:571] Authorization enabled
I0211 02:48:59.956465 741 hierarchical.cpp:144] Initialized hierarchical
allocator process
I0211 02:48:59.956471 728 whitelist_watcher.cpp:77] No whitelist given
I0211 02:48:59.959408 730 master.cpp:1712] The newly elected leader is
[email protected]:35649 with id 975d1891-2340-491a-a815-2b79475b741e
I0211 02:48:59.959516 730 master.cpp:1725] Elected as the leading master!
I0211 02:48:59.959589 730 master.cpp:1470] Recovering from registrar
I0211 02:48:59.959756 741 registrar.cpp:307] Recovering registrar
I0211 02:48:59.970322 732 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 20.169408ms
I0211 02:48:59.970412 732 replica.cpp:320] Persisted replica status to
STARTING
I0211 02:48:59.970787 732 recover.cpp:473] Replica is in STARTING status
I0211 02:48:59.972636 740 replica.cpp:673] Replica in STARTING status
received a broadcasted recover request from (9461)@172.17.0.3:35649
I0211 02:48:59.974999 736 recover.cpp:193] Received a recover response from a
replica in STARTING status
I0211 02:48:59.975667 738 recover.cpp:564] Updating replica status to VOTING
I0211 02:48:59.995312 736 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 19.456306ms
I0211 02:48:59.995409 736 replica.cpp:320] Persisted replica status to VOTING
I0211 02:48:59.995687 736 recover.cpp:578] Successfully joined the Paxos group
I0211 02:48:59.995918 736 recover.cpp:462] Recover process terminated
I0211 02:48:59.996893 736 log.cpp:659] Attempting to start the writer
I0211 02:48:59.998999 736 replica.cpp:493] Replica received implicit promise
request from (9462)@172.17.0.3:35649 with proposal 1
I0211 02:49:00.020315 736 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 21.251768ms
I0211 02:49:00.020416 736 replica.cpp:342] Persisted promised to 1
I0211 02:49:00.022089 736 coordinator.cpp:238] Coordinator attempting to fill
missing positions
I0211 02:49:00.023986 735 replica.cpp:388] Replica received explicit promise
request from (9463)@172.17.0.3:35649 for position 0 with proposal 2
I0211 02:49:00.045333 735 leveldb.cpp:341] Persisting action (8 bytes) to
leveldb took 21.258877ms
I0211 02:49:00.045416 735 replica.cpp:712] Persisted action at 0
I0211 02:49:00.047312 735 replica.cpp:537] Replica received write request for
position 0 from (9464)@172.17.0.3:35649
I0211 02:49:00.047399 735 leveldb.cpp:436] Reading position from leveldb took
42692ns
I0211 02:49:00.071322 735 leveldb.cpp:341] Persisting action (14 bytes) to
leveldb took 23.856715ms
I0211 02:49:00.071416 735 replica.cpp:712] Persisted action at 0
I0211 02:49:00.072562 735 replica.cpp:691] Replica received learned notice
for position 0 from @0.0.0.0:0
I0211 02:49:00.096314 735 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 23.694902ms
I0211 02:49:00.096402 735 replica.cpp:712] Persisted action at 0
I0211 02:49:00.096441 735 replica.cpp:697] Replica learned NOP action at
position 0
I0211 02:49:00.097441 737 log.cpp:675] Writer started with ending position 0
I0211 02:49:00.099143 735 leveldb.cpp:436] Reading position from leveldb took
58810ns
I0211 02:49:00.100543 742 registrar.cpp:340] Successfully fetched the
registry (0B) in 140.737792ms
I0211 02:49:00.100687 742 registrar.cpp:439] Applied 1 operations in 38547ns;
attempting to update the 'registry'
I0211 02:49:00.101961 742 log.cpp:683] Attempting to append 170 bytes to the
log
I0211 02:49:00.102205 742 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 1
I0211 02:49:00.103371 742 replica.cpp:537] Replica received write request for
position 1 from (9465)@172.17.0.3:35649
I0211 02:49:00.121316 742 leveldb.cpp:341] Persisting action (189 bytes) to
leveldb took 17.876768ms
I0211 02:49:00.121404 742 replica.cpp:712] Persisted action at 1
I0211 02:49:00.123095 732 replica.cpp:691] Replica received learned notice
for position 1 from @0.0.0.0:0
I0211 02:49:00.146327 732 leveldb.cpp:341] Persisting action (191 bytes) to
leveldb took 23.147126ms
I0211 02:49:00.146430 732 replica.cpp:712] Persisted action at 1
I0211 02:49:00.146473 732 replica.cpp:697] Replica learned APPEND action at
position 1
I0211 02:49:00.149364 732 log.cpp:702] Attempting to truncate the log to 1
I0211 02:49:00.149425 738 registrar.cpp:484] Successfully updated the
'registry' in 48.641024ms
I0211 02:49:00.149791 737 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 2
I0211 02:49:00.149819 738 registrar.cpp:370] Successfully recovered registrar
I0211 02:49:00.151481 737 master.cpp:1522] Recovered 0 slaves from the
Registry (131B) ; allowing 10mins for slaves to re-register
I0211 02:49:00.151607 737 hierarchical.cpp:171] Skipping recovery of
hierarchical allocator: nothing to recover
I0211 02:49:00.152938 735 replica.cpp:537] Replica received write request for
position 2 from (9466)@172.17.0.3:35649
I0211 02:49:00.170944 735 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 17.929889ms
I0211 02:49:00.171052 735 replica.cpp:712] Persisted action at 2
I0211 02:49:00.184383 739 replica.cpp:691] Replica received learned notice
for position 2 from @0.0.0.0:0
I0211 02:49:00.208322 739 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 23.846747ms
I0211 02:49:00.208489 739 leveldb.cpp:399] Deleting ~1 keys from leveldb took
79168ns
I0211 02:49:00.208516 739 replica.cpp:712] Persisted action at 2
I0211 02:49:00.208554 739 replica.cpp:697] Replica learned TRUNCATE action at
position 2
I0211 02:49:00.217859 709 containerizer.cpp:149] Using isolation:
posix/cpu,posix/mem,filesystem/posix
W0211 02:49:00.218709 709 backend.cpp:48] Failed to create 'bind' backend:
BindBackend requires root privileges
I0211 02:49:00.223283 728 slave.cpp:193] Slave started on 172.17.0.3:35649
I0211 02:49:00.223320 728 slave.cpp:194] 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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
--docker_puller_timeout="60" --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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/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="/mesos/mesos-0.28.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
--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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR"
I0211 02:49:00.223809 728 credentials.hpp:83] Loading credential for
authentication from
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/credential'
I0211 02:49:00.224026 728 slave.cpp:324] Slave using credential for:
test-principal
I0211 02:49:00.224200 728 resources.cpp:564] Parsing resources as JSON
failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0211 02:49:00.224793 728 slave.cpp:464] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0211 02:49:00.224872 728 slave.cpp:472] Slave attributes: [ ]
I0211 02:49:00.224886 728 slave.cpp:477] Slave hostname: 39a4cdba96b0
I0211 02:49:00.226300 728 state.cpp:58] Recovering state from
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta'
I0211 02:49:00.226867 728 status_update_manager.cpp:200] Recovering status
update manager
I0211 02:49:00.227072 728 containerizer.cpp:407] Recovering containerizer
I0211 02:49:00.228734 737 provisioner.cpp:245] Provisioner recovery complete
I0211 02:49:00.229064 709 sched.cpp:222] Version: 0.28.0
I0211 02:49:00.229308 737 slave.cpp:4565] Finished recovery
I0211 02:49:00.229805 737 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0211 02:49:00.230023 737 slave.cpp:796] New master detected at
[email protected]:35649
I0211 02:49:00.230062 740 status_update_manager.cpp:174] Pausing sending
status updates
I0211 02:49:00.230098 737 slave.cpp:859] Authenticating with master
[email protected]:35649
I0211 02:49:00.230123 737 slave.cpp:864] Using default CRAM-MD5 authenticatee
I0211 02:49:00.230141 743 sched.cpp:326] New master detected at
[email protected]:35649
I0211 02:49:00.230213 743 sched.cpp:382] Authenticating with master
[email protected]:35649
I0211 02:49:00.230242 743 sched.cpp:389] Using default CRAM-MD5 authenticatee
I0211 02:49:00.230307 737 slave.cpp:832] Detecting new master
I0211 02:49:00.230435 734 authenticatee.cpp:121] Creating new client SASL
connection
I0211 02:49:00.230500 739 authenticatee.cpp:121] Creating new client SASL
connection
I0211 02:49:00.230706 737 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0211 02:49:00.230767 740 master.cpp:5523] Authenticating
[email protected]:35649
I0211 02:49:00.230892 743 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(652)@172.17.0.3:35649
I0211 02:49:00.231030 740 master.cpp:5523] Authenticating
[email protected]:35649
I0211 02:49:00.231148 743 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(653)@172.17.0.3:35649
I0211 02:49:00.231283 740 authenticator.cpp:98] Creating new server SASL
connection
I0211 02:49:00.231379 739 authenticator.cpp:98] Creating new server SASL
connection
I0211 02:49:00.231622 739 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0211 02:49:00.231640 740 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0211 02:49:00.231657 739 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0211 02:49:00.231667 740 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0211 02:49:00.231822 742 authenticator.cpp:203] Received SASL authentication
start
I0211 02:49:00.231822 729 authenticator.cpp:203] Received SASL authentication
start
I0211 02:49:00.231895 742 authenticator.cpp:325] Authentication requires more
steps
I0211 02:49:00.231907 729 authenticator.cpp:325] Authentication requires more
steps
I0211 02:49:00.231997 742 authenticatee.cpp:258] Received SASL authentication
step
I0211 02:49:00.232030 729 authenticatee.cpp:258] Received SASL authentication
step
I0211 02:49:00.232108 742 authenticator.cpp:231] Received SASL authentication
step
I0211 02:49:00.232131 729 authenticator.cpp:231] Received SASL authentication
step
I0211 02:49:00.232144 742 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '39a4cdba96b0' server FQDN: '39a4cdba96b0'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0211 02:49:00.232161 742 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0211 02:49:00.232161 729 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '39a4cdba96b0' server FQDN: '39a4cdba96b0'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0211 02:49:00.232177 729 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0211 02:49:00.232235 742 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0211 02:49:00.232276 729 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0211 02:49:00.232309 729 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '39a4cdba96b0' server FQDN: '39a4cdba96b0'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0211 02:49:00.232326 729 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0211 02:49:00.232336 729 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0211 02:49:00.232352 729 authenticator.cpp:317] Authentication success
I0211 02:49:00.232525 729 authenticatee.cpp:298] Authentication success
I0211 02:49:00.232627 729 master.cpp:5553] Successfully authenticated
principal 'test-principal' at [email protected]:35649
I0211 02:49:00.232710 729 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(652)@172.17.0.3:35649
I0211 02:49:00.233060 729 slave.cpp:927] Successfully authenticated with
master [email protected]:35649
I0211 02:49:00.233201 729 slave.cpp:1321] Will retry registration in
5.867277ms if necessary
I0211 02:49:00.233584 729 master.cpp:4237] Registering slave at
[email protected]:35649 (39a4cdba96b0) with id
975d1891-2340-491a-a815-2b79475b741e-S0
I0211 02:49:00.234133 729 registrar.cpp:439] Applied 1 operations in 77493ns;
attempting to update the 'registry'
I0211 02:49:00.234264 742 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '39a4cdba96b0' server FQDN: '39a4cdba96b0'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0211 02:49:00.234287 742 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0211 02:49:00.234297 742 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0211 02:49:00.234314 742 authenticator.cpp:317] Authentication success
I0211 02:49:00.234454 742 authenticatee.cpp:298] Authentication success
I0211 02:49:00.234537 742 master.cpp:5553] Successfully authenticated
principal 'test-principal' at
[email protected]:35649
I0211 02:49:00.234611 742 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(653)@172.17.0.3:35649
I0211 02:49:00.234897 742 sched.cpp:471] Successfully authenticated with
master [email protected]:35649
I0211 02:49:00.234920 742 sched.cpp:776] Sending SUBSCRIBE call to
[email protected]:35649
I0211 02:49:00.235009 742 sched.cpp:809] Will retry registration in
58.311857ms if necessary
I0211 02:49:00.235213 742 master.cpp:2280] Received SUBSCRIBE call for
framework 'default' at
[email protected]:35649
I0211 02:49:00.236295 742 master.cpp:1751] Authorizing framework principal
'test-principal' to receive offers for role '*'
I0211 02:49:00.236657 742 master.cpp:2351] Subscribing framework default with
checkpointing enabled and capabilities [ ]
I0211 02:49:00.237592 729 sched.cpp:703] Framework registered with
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:00.237645 729 sched.cpp:717] Scheduler::registered took 25879ns
I0211 02:49:00.237694 729 log.cpp:683] Attempting to append 339 bytes to the
log
I0211 02:49:00.237918 729 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 3
I0211 02:49:00.237213 742 hierarchical.cpp:265] Added framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:00.238464 742 hierarchical.cpp:1403] No resources available to
allocate!
I0211 02:49:00.238502 742 hierarchical.cpp:1498] No inverse offers to send
out!
I0211 02:49:00.238528 742 hierarchical.cpp:1096] Performed allocation for 0
slaves in 124740ns
I0211 02:49:00.239176 740 replica.cpp:537] Replica received write request for
position 3 from (9480)@172.17.0.3:35649
I0211 02:49:00.246572 733 slave.cpp:1321] Will retry registration in
10.141492ms if necessary
I0211 02:49:00.246978 733 master.cpp:4225] Ignoring register slave message
from [email protected]:35649 (39a4cdba96b0) as admission is already in progress
I0211 02:49:00.258558 733 slave.cpp:1321] Will retry registration in
32.05954ms if necessary
I0211 02:49:00.259063 733 master.cpp:4225] Ignoring register slave message
from [email protected]:35649 (39a4cdba96b0) as admission is already in progress
I0211 02:49:00.267107 740 leveldb.cpp:341] Persisting action (358 bytes) to
leveldb took 27.83007ms
I0211 02:49:00.267199 740 replica.cpp:712] Persisted action at 3
I0211 02:49:00.268478 740 replica.cpp:691] Replica received learned notice
for position 3 from @0.0.0.0:0
I0211 02:49:00.293551 733 slave.cpp:1321] Will retry registration in
79.72207ms if necessary
I0211 02:49:00.293953 733 master.cpp:4225] Ignoring register slave message
from [email protected]:35649 (39a4cdba96b0) as admission is already in progress
I0211 02:49:00.301318 740 leveldb.cpp:341] Persisting action (360 bytes) to
leveldb took 32.784676ms
I0211 02:49:00.301411 740 replica.cpp:712] Persisted action at 3
I0211 02:49:00.301448 740 replica.cpp:697] Replica learned APPEND action at
position 3
I0211 02:49:00.303659 733 registrar.cpp:484] Successfully updated the
'registry' in 69.43104ms
I0211 02:49:00.303882 740 log.cpp:702] Attempting to truncate the log to 3
I0211 02:49:00.304930 740 master.cpp:4305] Registered slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649
(39a4cdba96b0) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0211 02:49:00.305337 734 slave.cpp:971] Registered with master
[email protected]:35649; given slave ID 975d1891-2340-491a-a815-2b79475b741e-S0
I0211 02:49:00.305371 734 fetcher.cpp:81] Clearing fetcher cache
I0211 02:49:00.305444 740 hierarchical.cpp:473] Added slave
975d1891-2340-491a-a815-2b79475b741e-S0 (39a4cdba96b0) with cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I0211 02:49:00.305568 739 status_update_manager.cpp:181] Resuming sending
status updates
I0211 02:49:00.305836 734 slave.cpp:994] Checkpointing SlaveInfo to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/slave.info'
I0211 02:49:00.306321 734 slave.cpp:1030] Forwarding total oversubscribed
resources
I0211 02:49:00.306438 734 slave.cpp:3482] Received ping from
slave-observer(274)@172.17.0.3:35649
I0211 02:49:00.306545 739 master.cpp:4646] Received update of slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649
(39a4cdba96b0) with total oversubscribed resources
I0211 02:49:00.306915 740 hierarchical.cpp:1498] No inverse offers to send
out!
I0211 02:49:00.306960 740 hierarchical.cpp:1116] Performed allocation for
slave 975d1891-2340-491a-a815-2b79475b741e-S0 in 1.470751ms
I0211 02:49:00.307421 740 hierarchical.cpp:531] Slave
975d1891-2340-491a-a815-2b79475b741e-S0 (39a4cdba96b0) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0211 02:49:00.307567 740 hierarchical.cpp:1403] No resources available to
allocate!
I0211 02:49:00.307608 740 hierarchical.cpp:1498] No inverse offers to send
out!
I0211 02:49:00.307629 740 hierarchical.cpp:1116] Performed allocation for
slave 975d1891-2340-491a-a815-2b79475b741e-S0 in 157270ns
I0211 02:49:00.307718 734 master.cpp:5352] Sending 1 offers to framework
975d1891-2340-491a-a815-2b79475b741e-0000 (default) at
[email protected]:35649
I0211 02:49:00.307714 733 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 4
I0211 02:49:00.308233 734 sched.cpp:873] Scheduler::resourceOffers took
134366ns
I0211 02:49:00.310433 729 replica.cpp:537] Replica received write request for
position 4 from (9481)@172.17.0.3:35649
I0211 02:49:00.311758 737 master.cpp:3138] Processing ACCEPT call for offers:
[ 975d1891-2340-491a-a815-2b79475b741e-O0 ] on slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649
(39a4cdba96b0) for framework 975d1891-2340-491a-a815-2b79475b741e-0000
(default) at [email protected]:35649
I0211 02:49:00.311830 737 master.cpp:2825] Authorizing framework principal
'test-principal' to launch task 1 as user 'mesos'
W0211 02:49:00.313971 737 validation.cpp:404] Executor http for task 1 uses
less CPUs (None) than the minimum required (0.01). Please update your executor,
as this will be mandatory in future releases.
W0211 02:49:00.314024 737 validation.cpp:416] Executor http for task 1 uses
less memory (None) than the minimum required (32MB). Please update your
executor, as this will be mandatory in future releases.
I0211 02:49:00.314458 737 master.hpp:176] Adding task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
975d1891-2340-491a-a815-2b79475b741e-S0 (39a4cdba96b0)
I0211 02:49:00.314681 737 master.cpp:3623] Launching task 1 of framework
975d1891-2340-491a-a815-2b79475b741e-0000 (default) at
[email protected]:35649 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649 (39a4cdba96b0)
I0211 02:49:00.315157 737 slave.cpp:1361] Got assigned task 1 for framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:00.316402 737 slave.cpp:5271] Checkpointing FrameworkInfo to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/framework.info'
I0211 02:49:00.316907 737 slave.cpp:5282] Checkpointing framework pid
'[email protected]:35649' to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/framework.pid'
I0211 02:49:00.317662 737 slave.cpp:1480] Launching task 1 for framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:00.318334 737 paths.cpp:474] Trying to chown
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/runs/5e16045a-90c5-4ac0-84ab-d7377f39f7c3'
to user 'mesos'
I0211 02:49:00.344652 737 slave.cpp:5723] Checkpointing ExecutorInfo to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/executor.info'
I0211 02:49:00.345718 737 slave.cpp:5351] Launching executor http of
framework 975d1891-2340-491a-a815-2b79475b741e-0000 with resources in work
directory
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/runs/5e16045a-90c5-4ac0-84ab-d7377f39f7c3'
I0211 02:49:00.346544 737 slave.cpp:5746] Checkpointing TaskInfo to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/runs/5e16045a-90c5-4ac0-84ab-d7377f39f7c3/tasks/1/task.info'
I0211 02:49:00.346700 740 containerizer.cpp:666] Starting container
'5e16045a-90c5-4ac0-84ab-d7377f39f7c3' for executor 'http' of framework
'975d1891-2340-491a-a815-2b79475b741e-0000'
I0211 02:49:00.347254 737 slave.cpp:1698] Queuing task '1' for executor
'http' of framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:00.347538 737 slave.cpp:749] Successfully attached file
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/runs/5e16045a-90c5-4ac0-84ab-d7377f39f7c3'
I0211 02:49:00.351527 729 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 41.024113ms
I0211 02:49:00.351588 729 replica.cpp:712] Persisted action at 4
I0211 02:49:00.352677 729 replica.cpp:691] Replica received learned notice
for position 4 from @0.0.0.0:0
I0211 02:49:00.357081 740 launcher.cpp:147] Forked child with pid '7440' for
container '5e16045a-90c5-4ac0-84ab-d7377f39f7c3'
I0211 02:49:00.357285 740 containerizer.cpp:1104] Checkpointing executor's
forked pid 7440 to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/runs/5e16045a-90c5-4ac0-84ab-d7377f39f7c3/pids/forked.pid'
I0211 02:49:00.413347 729 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 60.609498ms
I0211 02:49:00.413528 729 leveldb.cpp:399] Deleting ~2 keys from leveldb took
93629ns
I0211 02:49:00.413563 729 replica.cpp:712] Persisted action at 4
I0211 02:49:00.413602 729 replica.cpp:697] Replica learned TRUNCATE action at
position 4
2016-02-11
02:49:00,632:709(0x2ad3ab87e700):ZOO_ERROR@handle_socket_error_msg@1697: Socket
[127.0.0.1:57394] zk retcode=-4, errno=111(Connection refused): server refused
to accept the client
I0211 02:49:00.958535 729 hierarchical.cpp:1403] No resources available to
allocate!
I0211 02:49:00.958611 729 hierarchical.cpp:1498] No inverse offers to send
out!
I0211 02:49:00.958638 729 hierarchical.cpp:1096] Performed allocation for 1
slaves in 315255ns
I0211 02:49:01.960548 742 hierarchical.cpp:1403] No resources available to
allocate!
I0211 02:49:01.960634 742 hierarchical.cpp:1498] No inverse offers to send
out!
I0211 02:49:01.960666 742 hierarchical.cpp:1096] Performed allocation for 1
slaves in 352382ns
I0211 02:49:02.962319 728 hierarchical.cpp:1403] No resources available to
allocate!
I0211 02:49:02.962409 728 hierarchical.cpp:1498] No inverse offers to send
out!
I0211 02:49:02.962442 728 hierarchical.cpp:1096] Performed allocation for 1
slaves in 385272ns
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0211 02:49:03.257328 7454 process.cpp:991] libprocess is initialized on
172.17.0.3:60854 for 16 cpus
I0211 02:49:03.262311 7454 logging.cpp:193] Logging to STDERR
I0211 02:49:03.262362 7454 executor.cpp:172] Version: 0.28.0
I0211 02:49:03.268662 7486 executor.cpp:316] Connected with the agent
I0211 02:49:03.271752 7487 executor.cpp:247] Sending SUBSCRIBE call to
http://172.17.0.3:35649/slave/api/v1/executor
I0211 02:49:03.291859 728 process.cpp:3141] Handling HTTP event for process
'slave' with path: '/slave/api/v1/executor'
I0211 02:49:03.292934 728 http.cpp:190] HTTP POST for /slave/api/v1/executor
from 172.17.0.3:45354
I0211 02:49:03.293561 728 slave.cpp:2476] Received Subscribe request for HTTP
executor 'http' of framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:03.293814 728 slave.cpp:2539] Creating a marker file for HTTP
based executor 'http' of framework 975d1891-2340-491a-a815-2b79475b741e-0000
(via HTTP) at path
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/runs/5e16045a-90c5-4ac0-84ab-d7377f39f7c3/http.marker'
I0211 02:49:03.301944 743 slave.cpp:1863] Sending queued task '1' to executor
'http' of framework 975d1891-2340-491a-a815-2b79475b741e-0000 (via HTTP)
I0211 02:49:03.312378 7478 executor.cpp:588] Enqueuing event SUBSCRIBED
received from http://172.17.0.3:35649/slave/api/v1/executor
Received a SUBSCRIBED event
I0211 02:49:03.317838 7480 executor.cpp:588] Enqueuing event LAUNCH received
from http://172.17.0.3:35649/slave/api/v1/executor
Starting task 1
Finishing task 1
I0211 02:49:03.322806 7480 executor.cpp:247] Sending UPDATE call to
http://172.17.0.3:35649/slave/api/v1/executor
I0211 02:49:03.323354 7480 executor.cpp:247] Sending UPDATE call to
http://172.17.0.3:35649/slave/api/v1/executor
I0211 02:49:03.329973 735 slave.cpp:668] Slave terminating
I0211 02:49:03.330543 735 master.cpp:1174] Slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649
(39a4cdba96b0) disconnected
I0211 02:49:03.330706 735 master.cpp:2635] Disconnecting slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649 (39a4cdba96b0)
I0211 02:49:03.330979 735 master.cpp:2654] Deactivating slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649 (39a4cdba96b0)
I0211 02:49:03.331158 729 hierarchical.cpp:560] Slave
975d1891-2340-491a-a815-2b79475b741e-S0 deactivated
E0211 02:49:03.337012 7478 executor.cpp:553] End-Of-File received from agent.
The agent closed the event stream
I0211 02:49:03.337074 7478 executor.cpp:357] Disconnected from agent:
End-Of-File received from agent. The agent closed the event stream
I0211 02:49:03.338933 7478 executor.cpp:411] Will retry connecting with the
agent again in 1.548772469secs
I0211 02:49:03.341729 7478 executor.cpp:586] Enqueuing locally injected event
ERROR
I0211 02:49:03.343289 7478 executor.cpp:586] Enqueuing locally injected event
ERROR
Received an ERROR event
Received an ERROR event
I0211 02:49:03.345559 7473 executor.cpp:316] Connected with the agent
I0211 02:49:03.347950 7479 executor.cpp:247] Sending SUBSCRIBE call to
http://172.17.0.3:35649/slave/api/v1/executor
I0211 02:49:03.356313 744 process.cpp:2409] Returning '404 Not Found' for
'/slave/api/v1/executor'
I0211 02:49:03.358492 709 containerizer.cpp:149] Using isolation:
posix/cpu,posix/mem,filesystem/posix
W0211 02:49:03.360476 709 backend.cpp:48] Failed to create 'bind' backend:
BindBackend requires root privileges
W0211 02:49:03.360517 7488 executor.cpp:509] Received '404 Not Found' () for
SUBSCRIBE
I0211 02:49:03.372517 733 slave.cpp:193] Slave started on 172.17.0.3:35649
I0211 02:49:03.372566 733 slave.cpp:194] 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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_auth_server="https://auth.docker.io"; --docker_kill_orphans="true"
--docker_puller_timeout="60" --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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/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="/mesos/mesos-0.28.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
--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/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR"
I0211 02:49:03.373114 733 credentials.hpp:83] Loading credential for
authentication from
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/credential'
I0211 02:49:03.374446 733 slave.cpp:324] Slave using credential for:
test-principal
I0211 02:49:03.374712 733 resources.cpp:564] Parsing resources as JSON
failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
Trying semicolon-delimited string format instead
I0211 02:49:03.375340 733 slave.cpp:464] Slave resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0211 02:49:03.375429 733 slave.cpp:472] Slave attributes: [ ]
I0211 02:49:03.375444 733 slave.cpp:477] Slave hostname: 39a4cdba96b0
I0211 02:49:03.377328 735 state.cpp:58] Recovering state from
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta'
I0211 02:49:03.377452 735 state.cpp:698] No checkpointed resources found at
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/resources/resources.info'
W0211 02:49:03.379395 735 state.cpp:607] Failed to find status updates file
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/runs/5e16045a-90c5-4ac0-84ab-d7377f39f7c3/tasks/1/task.updates'
I0211 02:49:03.382642 741 fetcher.cpp:81] Clearing fetcher cache
I0211 02:49:03.382860 741 slave.cpp:4653] Recovering framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:03.383074 741 slave.cpp:5460] Recovering executor 'http' of
framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:03.384511 740 status_update_manager.cpp:200] Recovering status
update manager
I0211 02:49:03.384682 740 status_update_manager.cpp:208] Recovering executor
'http' of framework 975d1891-2340-491a-a815-2b79475b741e-0000
W0211 02:49:03.384838 740 status_update_manager.cpp:247] No updates found for
task 1 of framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:03.385273 741 slave.cpp:749] Successfully attached file
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/runs/5e16045a-90c5-4ac0-84ab-d7377f39f7c3'
I0211 02:49:03.385758 740 containerizer.cpp:407] Recovering containerizer
I0211 02:49:03.385825 740 containerizer.cpp:462] Recovering container
'5e16045a-90c5-4ac0-84ab-d7377f39f7c3' for executor 'http' of framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:03.388481 740 provisioner.cpp:245] Provisioner recovery complete
I0211 02:49:03.389945 740 slave.cpp:4512] Waiting for executor 'http' of
framework 975d1891-2340-491a-a815-2b79475b741e-0000 (via HTTP) to subscribe
W0211 02:49:03.962368 729 group.cpp:503] Timed out waiting to connect to
ZooKeeper. Forcing ZooKeeper session (sessionId=0) expiration
I0211 02:49:03.963201 729 group.cpp:519] ZooKeeper session expired
2016-02-11 02:49:03,963:709(0x2ad2f808b700):ZOO_INFO@zookeeper_close@2522:
Freeing zookeeper resources for sessionId=0
2016-02-11 02:49:03,963:709(0x2ad2f7e8a700):ZOO_INFO@log_env@712: Client
environment:zookeeper.version=zookeeper C client 3.4.5
2016-02-11 02:49:03,964:709(0x2ad2f7e8a700):ZOO_INFO@log_env@716: Client
environment:host.name=39a4cdba96b0
2016-02-11 02:49:03,965:709(0x2ad2f7e8a700):ZOO_INFO@log_env@723: Client
environment:os.name=Linux
2016-02-11 02:49:03,965:709(0x2ad2f7e8a700):ZOO_INFO@log_env@724: Client
environment:os.arch=3.13.0-36-lowlatency
2016-02-11 02:49:03,965:709(0x2ad2f7e8a700):ZOO_INFO@log_env@725: Client
environment:os.version=#63-Ubuntu SMP PREEMPT Wed Sep 3 21:56:12 UTC 2014
2016-02-11 02:49:03,965:709(0x2ad2f7e8a700):ZOO_INFO@log_env@733: Client
environment:user.name=(null)
2016-02-11 02:49:03,965:709(0x2ad2f7e8a700):ZOO_INFO@log_env@741: Client
environment:user.home=/home/mesos
2016-02-11 02:49:03,965:709(0x2ad2f7e8a700):ZOO_INFO@log_env@753: Client
environment:user.dir=/tmp/25xkWj
2016-02-11 02:49:03,965:709(0x2ad2f7e8a700):ZOO_INFO@zookeeper_init@786:
Initiating client connection, host=127.0.0.1:57394 sessionTimeout=10000
watcher=0x2ad2edac4cfc sessionId=0 sessionPasswd=<null> context=0x2ad3040082c0
flags=0
2016-02-11
02:49:03,967:709(0x2ad3aac73700):ZOO_ERROR@handle_socket_error_msg@1697: Socket
[127.0.0.1:57394] zk retcode=-4, errno=111(Connection refused): server refused
to accept the client
I0211 02:49:03.969516 737 hierarchical.cpp:1403] No resources available to
allocate!
I0211 02:49:03.969596 737 hierarchical.cpp:1498] No inverse offers to send
out!
I0211 02:49:03.969636 737 hierarchical.cpp:1096] Performed allocation for 1
slaves in 364815ns
I0211 02:49:04.276640 7488 executor.cpp:247] Sending SUBSCRIBE call to
http://172.17.0.3:35649/slave/api/v1/executor
I0211 02:49:04.281744 737 process.cpp:3141] Handling HTTP event for process
'slave' with path: '/slave/api/v1/executor'
I0211 02:49:04.283172 737 http.cpp:190] HTTP POST for /slave/api/v1/executor
from 172.17.0.3:45356
I0211 02:49:04.283939 737 slave.cpp:2476] Received Subscribe request for HTTP
executor 'http' of framework 975d1891-2340-491a-a815-2b79475b741e-0000 (via
HTTP)
I0211 02:49:04.284099 737 slave.cpp:2539] Creating a marker file for HTTP
based executor 'http' of framework 975d1891-2340-491a-a815-2b79475b741e-0000
(via HTTP) at path
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/executors/http/runs/5e16045a-90c5-4ac0-84ab-d7377f39f7c3/http.marker'
I0211 02:49:04.284783 737 slave.cpp:3002] Handling status update TASK_RUNNING
(UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:04.286820 737 slave.cpp:3002] Handling status update
TASK_FINISHED (UUID: f642a18c-e980-4520-ba0d-abc2a731ed98) for task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:04.291290 729 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:04.292325 729 status_update_manager.cpp:497] Creating
StatusUpdate stream for task 1 of framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:04.293144 729 status_update_manager.cpp:824] Checkpointing UPDATE
for status update TASK_RUNNING (UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for
task 1 of framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:04.294039 737 slave.cpp:5661] Terminating task 1
I0211 02:49:04.296522 7475 executor.cpp:588] Enqueuing event SUBSCRIBED
received from http://172.17.0.3:35649/slave/api/v1/executor
Received a SUBSCRIBED event
I0211 02:49:04.369531 729 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000 to the slave
I0211 02:49:04.370110 729 status_update_manager.cpp:320] Received status
update TASK_FINISHED (UUID: f642a18c-e980-4520-ba0d-abc2a731ed98) for task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:04.370177 729 status_update_manager.cpp:824] Checkpointing UPDATE
for status update TASK_FINISHED (UUID: f642a18c-e980-4520-ba0d-abc2a731ed98)
for task 1 of framework 975d1891-2340-491a-a815-2b79475b741e-0000
W0211 02:49:04.370342 731 slave.cpp:3346] Dropping status update TASK_RUNNING
(UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of framework
975d1891-2340-491a-a815-2b79475b741e-0000 sent by status update manager because
the slave is in RECOVERING state
I0211 02:49:04.370421 731 slave.cpp:3294] Status update manager successfully
handled status update TASK_RUNNING (UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e)
for task 1 of framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:04.372791 7488 executor.cpp:588] Enqueuing event ACKNOWLEDGED
received from http://172.17.0.3:35649/slave/api/v1/executor
Received an ACKNOWLEDGED event
I0211 02:49:04.420387 729 slave.cpp:3294] Status update manager successfully
handled status update TASK_FINISHED (UUID:
f642a18c-e980-4520-ba0d-abc2a731ed98) for task 1 of framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:04.422559 7479 executor.cpp:588] Enqueuing event ACKNOWLEDGED
received from http://172.17.0.3:35649/slave/api/v1/executor
Received an ACKNOWLEDGED event
I0211 02:49:04.971330 734 hierarchical.cpp:1403] No resources available to
allocate!
I0211 02:49:04.971432 734 hierarchical.cpp:1498] No inverse offers to send
out!
I0211 02:49:04.971477 734 hierarchical.cpp:1096] Performed allocation for 1
slaves in 416309ns
I0211 02:49:05.390664 739 slave.cpp:2942] Cleaning up un-reregistered
executors
I0211 02:49:05.390830 739 slave.cpp:4565] Finished recovery
I0211 02:49:05.391569 739 slave.cpp:4737] Querying resource estimator for
oversubscribable resources
I0211 02:49:05.392241 739 slave.cpp:796] New master detected at
[email protected]:35649
I0211 02:49:05.392388 739 slave.cpp:859] Authenticating with master
[email protected]:35649
I0211 02:49:05.392415 739 slave.cpp:864] Using default CRAM-MD5 authenticatee
I0211 02:49:05.392647 739 slave.cpp:832] Detecting new master
I0211 02:49:05.392784 739 slave.cpp:4751] Received oversubscribable resources
from the resource estimator
I0211 02:49:05.392910 739 status_update_manager.cpp:174] Pausing sending
status updates
I0211 02:49:05.393281 739 authenticatee.cpp:121] Creating new client SASL
connection
I0211 02:49:05.393795 739 master.cpp:5523] Authenticating
[email protected]:35649
I0211 02:49:05.394037 739 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(654)@172.17.0.3:35649
I0211 02:49:05.394419 731 authenticator.cpp:98] Creating new server SASL
connection
I0211 02:49:05.394733 731 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0211 02:49:05.394769 731 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0211 02:49:05.394871 731 authenticator.cpp:203] Received SASL authentication
start
I0211 02:49:05.394942 731 authenticator.cpp:325] Authentication requires more
steps
I0211 02:49:05.395038 731 authenticatee.cpp:258] Received SASL authentication
step
I0211 02:49:05.395153 731 authenticator.cpp:231] Received SASL authentication
step
I0211 02:49:05.395192 731 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '39a4cdba96b0' server FQDN: '39a4cdba96b0'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0211 02:49:05.395212 731 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0211 02:49:05.395400 731 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0211 02:49:05.395452 731 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '39a4cdba96b0' server FQDN: '39a4cdba96b0'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0211 02:49:05.395469 731 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0211 02:49:05.395481 731 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0211 02:49:05.395503 731 authenticator.cpp:317] Authentication success
I0211 02:49:05.395632 731 authenticatee.cpp:298] Authentication success
I0211 02:49:05.396011 731 slave.cpp:927] Successfully authenticated with
master [email protected]:35649
I0211 02:49:05.397748 731 slave.cpp:1321] Will retry registration in
8.882289ms if necessary
I0211 02:49:05.398393 731 master.cpp:4323] Queuing up re-registration request
from [email protected]:35649 because authentication is still in progress
I0211 02:49:05.399498 739 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(654)@172.17.0.3:35649
I0211 02:49:05.399756 739 master.cpp:4323] Queuing up re-registration request
from [email protected]:35649 because authentication is still in progress
I0211 02:49:05.400610 739 master.cpp:5553] Successfully authenticated
principal 'test-principal' at [email protected]:35649
I0211 02:49:05.400863 739 master.cpp:4397] Re-registering slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649 (39a4cdba96b0)
I0211 02:49:05.401437 741 slave.cpp:1071] Re-registered with master
[email protected]:35649
I0211 02:49:05.402397 741 slave.cpp:1107] Forwarding total oversubscribed
resources
I0211 02:49:05.402470 742 status_update_manager.cpp:181] Resuming sending
status updates
W0211 02:49:05.402649 742 status_update_manager.cpp:188] Resending status
update TASK_RUNNING (UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:05.402715 742 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000 to the slave
I0211 02:49:05.403101 742 slave.cpp:3400] Forwarding the update TASK_RUNNING
(UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of framework
975d1891-2340-491a-a815-2b79475b741e-0000 to [email protected]:35649
I0211 02:49:05.403854 734 hierarchical.cpp:548] Slave
975d1891-2340-491a-a815-2b79475b741e-S0 reactivated
I0211 02:49:05.404155 742 slave.cpp:2248] Updating framework
975d1891-2340-491a-a815-2b79475b741e-0000 pid to
[email protected]:35649
I0211 02:49:05.404229 742 slave.cpp:2264] Checkpointing framework pid
'[email protected]:35649' to
'/tmp/SlaveRecoveryTest_0_ReconnectHTTPExecutor_3MqRAR/meta/slaves/975d1891-2340-491a-a815-2b79475b741e-S0/frameworks/975d1891-2340-491a-a815-2b79475b741e-0000/framework.pid'
I0211 02:49:05.404750 742 status_update_manager.cpp:181] Resuming sending
status updates
W0211 02:49:05.404788 742 status_update_manager.cpp:188] Resending status
update TASK_RUNNING (UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:05.404826 742 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000 to the slave
I0211 02:49:05.405120 742 slave.cpp:3400] Forwarding the update TASK_RUNNING
(UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of framework
975d1891-2340-491a-a815-2b79475b741e-0000 to [email protected]:35649
I0211 02:49:05.405380 739 master.cpp:4584] Sending updated checkpointed
resources to slave 975d1891-2340-491a-a815-2b79475b741e-S0 at
[email protected]:35649 (39a4cdba96b0)
I0211 02:49:05.405856 729 slave.cpp:2341] Updated checkpointed resources from
to
I0211 02:49:05.406491 739 master.cpp:4646] Received update of slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649
(39a4cdba96b0) with total oversubscribed resources
I0211 02:49:05.407289 730 hierarchical.cpp:531] Slave
975d1891-2340-491a-a815-2b79475b741e-S0 (39a4cdba96b0) updated with
oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000])
I0211 02:49:05.407670 730 hierarchical.cpp:1403] No resources available to
allocate!
I0211 02:49:05.407734 730 hierarchical.cpp:1498] No inverse offers to send
out!
I0211 02:49:05.407774 730 hierarchical.cpp:1116] Performed allocation for
slave 975d1891-2340-491a-a815-2b79475b741e-S0 in 291381ns
I0211 02:49:05.408076 739 master.cpp:4791] Status update TASK_RUNNING (UUID:
23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of framework
975d1891-2340-491a-a815-2b79475b741e-0000 from slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649 (39a4cdba96b0)
I0211 02:49:05.408277 739 master.cpp:4839] Forwarding status update
TASK_RUNNING (UUID: 23b11d87-d285-463b-8fd2-e16f90fb149e) for task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:05.408851 740 sched.cpp:981] Scheduler::statusUpdate took 121633ns
I0211 02:49:05.409807 709 sched.cpp:1903] Asked to stop the driver
I0211 02:49:05.410168 741 sched.cpp:1143] Stopping framework
'975d1891-2340-491a-a815-2b79475b741e-0000'
I0211 02:49:05.418413 739 master.cpp:6447] Updating the state of task 1 of
framework 975d1891-2340-491a-a815-2b79475b741e-0000 (latest state:
TASK_FINISHED, status update state: TASK_RUNNING)
I0211 02:49:05.420322 730 hierarchical.cpp:892] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave
975d1891-2340-491a-a815-2b79475b741e-S0 from framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:05.420853 739 master.cpp:1027] Master terminating
I0211 02:49:05.421401 732 hierarchical.cpp:505] Removed slave
975d1891-2340-491a-a815-2b79475b741e-S0
I0211 02:49:05.421582 739 master.cpp:6513] Removing task 1 with resources
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
975d1891-2340-491a-a815-2b79475b741e-0000 on slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649 (39a4cdba96b0)
I0211 02:49:05.422027 739 master.cpp:6542] Removing executor 'http' with
resources of framework 975d1891-2340-491a-a815-2b79475b741e-0000 on slave
975d1891-2340-491a-a815-2b79475b741e-S0 at [email protected]:35649 (39a4cdba96b0)
I0211 02:49:05.430738 737 hierarchical.cpp:326] Removed framework
975d1891-2340-491a-a815-2b79475b741e-0000
I0211 02:49:05.431165 728 slave.cpp:3528] [email protected]:35649 exited
W0211 02:49:05.431282 728 slave.cpp:3531] Master disconnected! Waiting for a
new master to be elected
I0211 02:49:05.439306 736 containerizer.cpp:1369] Destroying container
'5e16045a-90c5-4ac0-84ab-d7377f39f7c3'
I0211 02:49:05.495051 740 containerizer.cpp:1585] Executor for container
'5e16045a-90c5-4ac0-84ab-d7377f39f7c3' has exited
I0211 02:49:05.497618 729 provisioner.cpp:306] Ignoring destroy request for
unknown container 5e16045a-90c5-4ac0-84ab-d7377f39f7c3
I0211 02:49:05.498237 729 slave.cpp:3886] Executor 'http' of framework
975d1891-2340-491a-a815-2b79475b741e-0000 terminated with signal Killed
I0211 02:49:05.499650 731 slave.cpp:668] Slave terminating
[ OK ] SlaveRecoveryTest/0.ReconnectHTTPExecutor (5703 ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
