[jira] [Created] (MESOS-4661) SlaveRecoveryTest/0.ReconnectHTTPExecutor is flaky

[Anand Mazumdar (JIRA)]

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 
master@172.17.0.2: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 
master@172.17.0.2: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 
master@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 master@172.17.0.2:57200
I0212 00:23:08.235970   731 sched.cpp:776] Sending SUBSCRIBE call to 
master@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 
master@172.17.0.2:57200
I0212 00:23:08.236501   726 slave.cpp:859] Authenticating with master 
master@172.17.0.2: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 
slave@172.17.0.2: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 slave@172.17.0.2: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 master@172.17.0.2: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 
slave@172.17.0.2: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 slave@172.17.0.2: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 slave@172.17.0.2:57200 
(ca60addecc0b) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0212 00:23:08.246541   724 slave.cpp:971] Registered with master 
master@172.17.0.2: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 slave@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 slave@172.17.0.2:57200 
(ca60addecc0b) for framework 6508f198-e145-4d76-844f-0460dc5d7d39-0000 
(default) at scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2:57200 with resources 
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at slave@172.17.0.2: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 
'scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 slave@172.17.0.2:57200 
(ca60addecc0b) disconnected
I0212 00:23:10.661725   734 master.cpp:2635] Disconnecting slave 
6508f198-e145-4d76-844f-0460dc5d7d39-S0 at slave@172.17.0.2: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 slave@172.17.0.2: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 
master@172.17.0.2:57200
I0212 00:23:12.690683   735 slave.cpp:859] Authenticating with master 
master@172.17.0.2: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 
slave@172.17.0.2: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 slave@172.17.0.2: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 master@172.17.0.2: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 slave@172.17.0.2:57200 (ca60addecc0b)
I0212 00:23:12.694430   728 slave.cpp:1071] Re-registered with master 
master@172.17.0.2: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 
slave@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2:57200
I0212 00:23:12.694856   736 slave.cpp:2264] Checkpointing framework pid 
'scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 slave@172.17.0.2: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 master@172.17.0.2: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 slave@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 master@172.17.0.2: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 slave@172.17.0.2: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 slave@172.17.0.2: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 slave@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2:57200 disconnected
I0212 00:23:12.698298   728 master.cpp:2576] Disconnecting framework 
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2:57200
I0212 00:23:12.698328   728 master.cpp:2600] Deactivating framework 
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2:57200
I0212 00:23:12.698400   728 master.cpp:1237] Giving framework 
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2: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 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2:57200
I0212 00:23:12.700059   731 master.cpp:5935] Removing framework 
6508f198-e145-4d76-844f-0460dc5d7d39-0000 (default) at 
scheduler-48b61fae-e225-4681-a774-47bbf2aea75d@172.17.0.2:57200
I0212 00:23:12.700173   724 slave.cpp:2079] Asked to shut down framework 
6508f198-e145-4d76-844f-0460dc5d7d39-0000 by master@172.17.0.2: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 slave@172.17.0.2: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] master@172.17.0.2: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 
master@172.17.0.3: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 
master@172.17.0.3: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 
master@172.17.0.3: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 
master@172.17.0.3:35649
I0211 02:49:00.230213   743 sched.cpp:382] Authenticating with master 
master@172.17.0.3: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 
slave@172.17.0.3: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 
scheduler-6c3243e4-6d9c-4955-a097-f1476b4c2790@172.17.0.3: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 slave@172.17.0.3: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 master@172.17.0.3: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 
slave@172.17.0.3: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 
scheduler-6c3243e4-6d9c-4955-a097-f1476b4c2790@172.17.0.3: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 master@172.17.0.3:35649
I0211 02:49:00.234920   742 sched.cpp:776] Sending SUBSCRIBE call to 
master@172.17.0.3: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 
scheduler-6c3243e4-6d9c-4955-a097-f1476b4c2790@172.17.0.3: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 slave@172.17.0.3: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 slave@172.17.0.3: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 slave@172.17.0.3: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 slave@172.17.0.3:35649 
(39a4cdba96b0) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0211 02:49:00.305337   734 slave.cpp:971] Registered with master 
master@172.17.0.3: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 slave@172.17.0.3: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 
scheduler-6c3243e4-6d9c-4955-a097-f1476b4c2790@172.17.0.3: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 slave@172.17.0.3:35649 
(39a4cdba96b0) for framework 975d1891-2340-491a-a815-2b79475b741e-0000 
(default) at scheduler-6c3243e4-6d9c-4955-a097-f1476b4c2790@172.17.0.3: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 
scheduler-6c3243e4-6d9c-4955-a097-f1476b4c2790@172.17.0.3:35649 with resources 
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 
975d1891-2340-491a-a815-2b79475b741e-S0 at slave@172.17.0.3: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 
'scheduler-6c3243e4-6d9c-4955-a097-f1476b4c2790@172.17.0.3: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 slave@172.17.0.3:35649 
(39a4cdba96b0) disconnected
I0211 02:49:03.330706   735 master.cpp:2635] Disconnecting slave 
975d1891-2340-491a-a815-2b79475b741e-S0 at slave@172.17.0.3:35649 (39a4cdba96b0)
I0211 02:49:03.330979   735 master.cpp:2654] Deactivating slave 
975d1891-2340-491a-a815-2b79475b741e-S0 at slave@172.17.0.3: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 
master@172.17.0.3:35649
I0211 02:49:05.392388   739 slave.cpp:859] Authenticating with master 
master@172.17.0.3: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 
slave@172.17.0.3: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 master@172.17.0.3: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 slave@172.17.0.3: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 slave@172.17.0.3:35649 because authentication is still in progress
I0211 02:49:05.400610   739 master.cpp:5553] Successfully authenticated 
principal 'test-principal' at slave@172.17.0.3:35649
I0211 02:49:05.400863   739 master.cpp:4397] Re-registering slave 
975d1891-2340-491a-a815-2b79475b741e-S0 at slave@172.17.0.3:35649 (39a4cdba96b0)
I0211 02:49:05.401437   741 slave.cpp:1071] Re-registered with master 
master@172.17.0.3: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 master@172.17.0.3: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 
scheduler-6c3243e4-6d9c-4955-a097-f1476b4c2790@172.17.0.3:35649
I0211 02:49:05.404229   742 slave.cpp:2264] Checkpointing framework pid 
'scheduler-6c3243e4-6d9c-4955-a097-f1476b4c2790@172.17.0.3: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 master@172.17.0.3:35649
I0211 02:49:05.405380   739 master.cpp:4584] Sending updated checkpointed 
resources  to slave 975d1891-2340-491a-a815-2b79475b741e-S0 at 
slave@172.17.0.3: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 slave@172.17.0.3: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 slave@172.17.0.3: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 slave@172.17.0.3: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 slave@172.17.0.3: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] master@172.17.0.3: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)