You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "haosdent (JIRA)" <ji...@apache.org> on 2016/03/08 04:24:40 UTC
[jira] [Commented] (MESOS-4800)
SlaveRecoveryTest/0.RecoverTerminatedExecutor is flaky
[ https://issues.apache.org/jira/browse/MESOS-4800?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15184318#comment-15184318 ]
haosdent commented on MESOS-4800:
---------------------------------
The problem here in fail case is it receive {{TASK_LOST}} before {{StatusUpdateManagerProcess::pause()}}. Then after resume, it resend {{TAKS_LOST}} twice.
{code}
// First time
I0229 02:11:02.602648 2154 status_update_manager.cpp:181] Resuming sending status updates
W0229 02:11:02.602721 2154 status_update_manager.cpp:188] Resending status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
I0229 02:11:02.602764 2154 status_update_manager.cpp:374] Forwarding update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 to the slave
// Second time.
I0229 02:11:02.602999 2154 status_update_manager.cpp:181] Resuming sending status updates
W0229 02:11:02.603032 2154 status_update_manager.cpp:188] Resending status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
I0229 02:11:02.603058 2154 status_update_manager.cpp:374] Forwarding update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 to the slave
{code}
> SlaveRecoveryTest/0.RecoverTerminatedExecutor is flaky
> ------------------------------------------------------
>
> Key: MESOS-4800
> URL: https://issues.apache.org/jira/browse/MESOS-4800
> Project: Mesos
> Issue Type: Task
> Reporter: Anand Mazumdar
> Labels: flaky, flaky-test, mesosphere
>
> Showed up on ASF CI:
> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(docker%7C%7CHadoop)&&(!ubuntu-us1)/1743/changes
> {code}
> [ RUN ] SlaveRecoveryTest/0.RecoverTerminatedExecutor
> I0229 02:11:01.321990 2124 leveldb.cpp:174] Opened db in 121.848194ms
> I0229 02:11:01.363880 2124 leveldb.cpp:181] Compacted db in 41.823665ms
> I0229 02:11:01.363965 2124 leveldb.cpp:196] Created db iterator in 27127ns
> I0229 02:11:01.363984 2124 leveldb.cpp:202] Seeked to beginning of db in 3446ns
> I0229 02:11:01.363996 2124 leveldb.cpp:271] Iterated through 0 keys in the db in 332ns
> I0229 02:11:01.364050 2124 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0229 02:11:01.365196 2158 recover.cpp:447] Starting replica recovery
> I0229 02:11:01.365492 2158 recover.cpp:473] Replica is in EMPTY status
> I0229 02:11:01.366982 2151 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (9830)@172.17.0.3:36786
> I0229 02:11:01.367451 2149 recover.cpp:193] Received a recover response from a replica in EMPTY status
> I0229 02:11:01.368335 2149 recover.cpp:564] Updating replica status to STARTING
> I0229 02:11:01.372730 2158 master.cpp:375] Master d551df7b-0c69-4bc9-b113-eca605384c49 (3036a6611147) started on 172.17.0.3:36786
> I0229 02:11:01.372764 2158 master.cpp:377] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_http="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/e9RAjp/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/e9RAjp/master" --zk_session_timeout="10secs"
> I0229 02:11:01.373164 2158 master.cpp:422] Master only allowing authenticated frameworks to register
> I0229 02:11:01.373178 2158 master.cpp:427] Master only allowing authenticated slaves to register
> I0229 02:11:01.373188 2158 credentials.hpp:35] Loading credentials for authentication from '/tmp/e9RAjp/credentials'
> I0229 02:11:01.373612 2158 master.cpp:467] Using default 'crammd5' authenticator
> I0229 02:11:01.373793 2158 master.cpp:536] Using default 'basic' HTTP authenticator
> I0229 02:11:01.373919 2158 master.cpp:570] Authorization enabled
> I0229 02:11:01.376322 2153 whitelist_watcher.cpp:77] No whitelist given
> I0229 02:11:01.376456 2158 hierarchical.cpp:144] Initialized hierarchical allocator process
> I0229 02:11:01.378609 2144 master.cpp:1711] The newly elected leader is master@172.17.0.3:36786 with id d551df7b-0c69-4bc9-b113-eca605384c49
> I0229 02:11:01.378674 2144 master.cpp:1724] Elected as the leading master!
> I0229 02:11:01.378700 2144 master.cpp:1469] Recovering from registrar
> I0229 02:11:01.378880 2154 registrar.cpp:307] Recovering registrar
> I0229 02:11:01.413949 2149 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 45.305096ms
> I0229 02:11:01.414049 2149 replica.cpp:320] Persisted replica status to STARTING
> I0229 02:11:01.414481 2154 recover.cpp:473] Replica is in STARTING status
> I0229 02:11:01.416136 2154 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (9832)@172.17.0.3:36786
> I0229 02:11:01.416656 2149 recover.cpp:193] Received a recover response from a replica in STARTING status
> I0229 02:11:01.417251 2154 recover.cpp:564] Updating replica status to VOTING
> I0229 02:11:01.455773 2149 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 38.225441ms
> I0229 02:11:01.455874 2149 replica.cpp:320] Persisted replica status to VOTING
> I0229 02:11:01.456140 2154 recover.cpp:578] Successfully joined the Paxos group
> I0229 02:11:01.456480 2154 recover.cpp:462] Recover process terminated
> I0229 02:11:01.457126 2154 log.cpp:659] Attempting to start the writer
> I0229 02:11:01.458848 2154 replica.cpp:493] Replica received implicit promise request from (9833)@172.17.0.3:36786 with proposal 1
> I0229 02:11:01.505862 2154 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 46.955874ms
> I0229 02:11:01.505939 2154 replica.cpp:342] Persisted promised to 1
> I0229 02:11:01.507206 2154 coordinator.cpp:238] Coordinator attempting to fill missing positions
> I0229 02:11:01.508864 2154 replica.cpp:388] Replica received explicit promise request from (9834)@172.17.0.3:36786 for position 0 with proposal 2
> I0229 02:11:01.547888 2154 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 38.963144ms
> I0229 02:11:01.547976 2154 replica.cpp:712] Persisted action at 0
> I0229 02:11:01.555917 2151 replica.cpp:537] Replica received write request for position 0 from (9835)@172.17.0.3:36786
> I0229 02:11:01.556046 2151 leveldb.cpp:436] Reading position from leveldb took 50257ns
> I0229 02:11:01.607380 2151 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 51.266122ms
> I0229 02:11:01.607462 2151 replica.cpp:712] Persisted action at 0
> I0229 02:11:01.608386 2151 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
> I0229 02:11:01.632486 2151 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 24.042093ms
> I0229 02:11:01.632580 2151 replica.cpp:712] Persisted action at 0
> I0229 02:11:01.632617 2151 replica.cpp:697] Replica learned NOP action at position 0
> I0229 02:11:01.633894 2144 log.cpp:675] Writer started with ending position 0
> I0229 02:11:01.635556 2144 leveldb.cpp:436] Reading position from leveldb took 69987ns
> I0229 02:11:01.637047 2151 registrar.cpp:340] Successfully fetched the registry (0B) in 258.103808ms
> I0229 02:11:01.637236 2151 registrar.cpp:439] Applied 1 operations in 51391ns; attempting to update the 'registry'
> I0229 02:11:01.638100 2151 log.cpp:683] Attempting to append 170 bytes to the log
> I0229 02:11:01.638252 2144 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> I0229 02:11:01.639575 2144 replica.cpp:537] Replica received write request for position 1 from (9836)@172.17.0.3:36786
> I0229 02:11:01.699651 2144 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 60.010063ms
> I0229 02:11:01.699744 2144 replica.cpp:712] Persisted action at 1
> I0229 02:11:01.700882 2147 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
> I0229 02:11:01.716353 2147 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 15.402602ms
> I0229 02:11:01.716436 2147 replica.cpp:712] Persisted action at 1
> I0229 02:11:01.716471 2147 replica.cpp:697] Replica learned APPEND action at position 1
> I0229 02:11:01.718617 2147 registrar.cpp:484] Successfully updated the 'registry' in 81.308928ms
> I0229 02:11:01.718768 2147 registrar.cpp:370] Successfully recovered registrar
> I0229 02:11:01.719029 2147 log.cpp:702] Attempting to truncate the log to 1
> I0229 02:11:01.719519 2147 master.cpp:1521] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
> I0229 02:11:01.719611 2147 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> I0229 02:11:01.720069 2147 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
> I0229 02:11:01.721388 2146 replica.cpp:537] Replica received write request for position 2 from (9837)@172.17.0.3:36786
> I0229 02:11:01.741520 2146 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 20.003102ms
> I0229 02:11:01.741608 2146 replica.cpp:712] Persisted action at 2
> I0229 02:11:01.743144 2146 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
> I0229 02:11:01.758337 2146 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 15.137488ms
> I0229 02:11:01.758491 2146 leveldb.cpp:399] Deleting ~1 keys from leveldb took 70829ns
> I0229 02:11:01.758518 2146 replica.cpp:712] Persisted action at 2
> I0229 02:11:01.758554 2146 replica.cpp:697] Replica learned TRUNCATE action at position 2
> I0229 02:11:01.763465 2124 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W0229 02:11:01.764482 2124 backend.cpp:60] Failed to create 'bind' backend: BindBackend requires root privileges
> I0229 02:11:01.770373 2146 slave.cpp:193] Slave started on 307)@172.17.0.3:36786
> I0229 02:11:01.770422 2146 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --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_RecoverTerminatedExecutor_eVw0V2/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/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_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2"
> I0229 02:11:01.770978 2146 credentials.hpp:83] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/credential'
> I0229 02:11:01.771260 2146 slave.cpp:324] Slave using credential for: test-principal
> I0229 02:11:01.771451 2146 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0229 02:11:01.772428 2146 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0229 02:11:01.772511 2146 slave.cpp:472] Slave attributes: [ ]
> I0229 02:11:01.772524 2146 slave.cpp:477] Slave hostname: 3036a6611147
> I0229 02:11:01.772857 2124 sched.cpp:222] Version: 0.28.0
> I0229 02:11:01.773782 2147 sched.cpp:326] New master detected at master@172.17.0.3:36786
> I0229 02:11:01.773887 2147 sched.cpp:382] Authenticating with master master@172.17.0.3:36786
> I0229 02:11:01.773910 2147 sched.cpp:389] Using default CRAM-MD5 authenticatee
> I0229 02:11:01.774356 2155 authenticatee.cpp:121] Creating new client SASL connection
> I0229 02:11:01.774932 2145 master.cpp:5540] Authenticating scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786
> I0229 02:11:01.775259 2146 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(671)@172.17.0.3:36786
> I0229 02:11:01.775461 2155 state.cpp:58] Recovering state from '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta'
> I0229 02:11:01.775607 2146 authenticator.cpp:98] Creating new server SASL connection
> I0229 02:11:01.775869 2155 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0229 02:11:01.775900 2155 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0229 02:11:01.775974 2155 status_update_manager.cpp:200] Recovering status update manager
> I0229 02:11:01.776168 2155 containerizer.cpp:407] Recovering containerizer
> I0229 02:11:01.776391 2146 authenticator.cpp:203] Received SASL authentication start
> I0229 02:11:01.776458 2146 authenticator.cpp:325] Authentication requires more steps
> I0229 02:11:01.776551 2146 authenticatee.cpp:258] Received SASL authentication step
> I0229 02:11:01.776650 2146 authenticator.cpp:231] Received SASL authentication step
> I0229 02:11:01.776679 2146 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '3036a6611147' server FQDN: '3036a6611147' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0229 02:11:01.776695 2146 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0229 02:11:01.776746 2146 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0229 02:11:01.776778 2146 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '3036a6611147' server FQDN: '3036a6611147' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0229 02:11:01.776792 2146 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0229 02:11:01.776799 2146 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0229 02:11:01.776818 2146 authenticator.cpp:317] Authentication success
> I0229 02:11:01.777274 2157 master.cpp:5570] Successfully authenticated principal 'test-principal' at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786
> I0229 02:11:01.777344 2155 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(671)@172.17.0.3:36786
> I0229 02:11:01.778318 2143 provisioner.cpp:245] Provisioner recovery complete
> I0229 02:11:01.778482 2145 authenticatee.cpp:298] Authentication success
> I0229 02:11:01.778733 2157 slave.cpp:4565] Finished recovery
> I0229 02:11:01.778982 2145 sched.cpp:471] Successfully authenticated with master master@172.17.0.3:36786
> I0229 02:11:01.779011 2145 sched.cpp:776] Sending SUBSCRIBE call to master@172.17.0.3:36786
> I0229 02:11:01.779112 2145 sched.cpp:809] Will retry registration in 50.191666ms if necessary
> I0229 02:11:01.779342 2157 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0229 02:11:01.779464 2143 master.cpp:2279] Received SUBSCRIBE call for framework 'default' at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786
> I0229 02:11:01.779628 2143 master.cpp:1750] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0229 02:11:01.779932 2145 master.cpp:2350] Subscribing framework default with checkpointing enabled and capabilities [ ]
> I0229 02:11:01.779630 2157 slave.cpp:4751] Received oversubscribable resources from the resource estimator
> I0229 02:11:01.780273 2149 status_update_manager.cpp:174] Pausing sending status updates
> I0229 02:11:01.780609 2143 hierarchical.cpp:265] Added framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:01.780705 2143 hierarchical.cpp:1437] No resources available to allocate!
> I0229 02:11:01.780805 2157 slave.cpp:796] New master detected at master@172.17.0.3:36786
> I0229 02:11:01.780865 2143 hierarchical.cpp:1532] No inverse offers to send out!
> I0229 02:11:01.780905 2143 hierarchical.cpp:1130] Performed allocation for 0 slaves in 264499ns
> I0229 02:11:01.780969 2157 slave.cpp:859] Authenticating with master master@172.17.0.3:36786
> I0229 02:11:01.780995 2157 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0229 02:11:01.781420 2145 sched.cpp:703] Framework registered with d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:01.781472 2154 authenticatee.cpp:121] Creating new client SASL connection
> I0229 02:11:01.781528 2157 slave.cpp:832] Detecting new master
> I0229 02:11:01.782263 2145 sched.cpp:717] Scheduler::registered took 811379ns
> I0229 02:11:01.782476 2157 master.cpp:5540] Authenticating slave(307)@172.17.0.3:36786
> I0229 02:11:01.782693 2155 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(672)@172.17.0.3:36786
> I0229 02:11:01.783180 2157 authenticator.cpp:98] Creating new server SASL connection
> I0229 02:11:01.783509 2157 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0229 02:11:01.783546 2157 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0229 02:11:01.783716 2157 authenticator.cpp:203] Received SASL authentication start
> I0229 02:11:01.783787 2157 authenticator.cpp:325] Authentication requires more steps
> I0229 02:11:01.783885 2157 authenticatee.cpp:258] Received SASL authentication step
> I0229 02:11:01.783990 2157 authenticator.cpp:231] Received SASL authentication step
> I0229 02:11:01.784028 2157 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '3036a6611147' server FQDN: '3036a6611147' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0229 02:11:01.784044 2157 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0229 02:11:01.784104 2157 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0229 02:11:01.784148 2157 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '3036a6611147' server FQDN: '3036a6611147' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0229 02:11:01.784170 2157 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0229 02:11:01.784183 2157 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0229 02:11:01.784204 2157 authenticator.cpp:317] Authentication success
> I0229 02:11:01.784432 2155 authenticatee.cpp:298] Authentication success
> I0229 02:11:01.784505 2147 master.cpp:5570] Successfully authenticated principal 'test-principal' at slave(307)@172.17.0.3:36786
> I0229 02:11:01.784543 2155 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(672)@172.17.0.3:36786
> I0229 02:11:01.784847 2147 slave.cpp:927] Successfully authenticated with master master@172.17.0.3:36786
> I0229 02:11:01.784998 2147 slave.cpp:1321] Will retry registration in 19.336028ms if necessary
> I0229 02:11:01.785260 2153 master.cpp:4254] Registering slave at slave(307)@172.17.0.3:36786 (3036a6611147) with id d551df7b-0c69-4bc9-b113-eca605384c49-S0
> I0229 02:11:01.785962 2153 registrar.cpp:439] Applied 1 operations in 88866ns; attempting to update the 'registry'
> I0229 02:11:01.786845 2149 log.cpp:683] Attempting to append 339 bytes to the log
> I0229 02:11:01.787030 2155 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> I0229 02:11:01.787911 2143 replica.cpp:537] Replica received write request for position 3 from (9851)@172.17.0.3:36786
> I0229 02:11:01.810534 2152 slave.cpp:1321] Will retry registration in 32.384396ms if necessary
> I0229 02:11:01.810886 2152 master.cpp:4242] Ignoring register slave message from slave(307)@172.17.0.3:36786 (3036a6611147) as admission is already in progress
> I0229 02:11:01.844094 2152 slave.cpp:1321] Will retry registration in 67.410991ms if necessary
> I0229 02:11:01.844470 2152 master.cpp:4242] Ignoring register slave message from slave(307)@172.17.0.3:36786 (3036a6611147) as admission is already in progress
> I0229 02:11:01.847918 2143 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 59.936978ms
> I0229 02:11:01.848011 2143 replica.cpp:712] Persisted action at 3
> I0229 02:11:01.849517 2143 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
> I0229 02:11:01.889813 2143 leveldb.cpp:341] Persisting action (360 bytes) to leveldb took 40.235882ms
> I0229 02:11:01.889906 2143 replica.cpp:712] Persisted action at 3
> I0229 02:11:01.889942 2143 replica.cpp:697] Replica learned APPEND action at position 3
> I0229 02:11:01.892735 2143 registrar.cpp:484] Successfully updated the 'registry' in 106.683136ms
> I0229 02:11:01.893092 2143 log.cpp:702] Attempting to truncate the log to 3
> I0229 02:11:01.894322 2153 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> I0229 02:11:01.894155 2143 master.cpp:4322] Registered slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(307)@172.17.0.3:36786 (3036a6611147) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0229 02:11:01.894906 2143 hierarchical.cpp:473] Added slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 (3036a6611147) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0229 02:11:01.895301 2153 slave.cpp:971] Registered with master master@172.17.0.3:36786; given slave ID d551df7b-0c69-4bc9-b113-eca605384c49-S0
> I0229 02:11:01.895328 2153 fetcher.cpp:81] Clearing fetcher cache
> I0229 02:11:01.895566 2151 status_update_manager.cpp:181] Resuming sending status updates
> I0229 02:11:01.896095 2151 replica.cpp:537] Replica received write request for position 4 from (9852)@172.17.0.3:36786
> I0229 02:11:01.896533 2153 slave.cpp:994] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/slave.info'
> I0229 02:11:01.896968 2153 slave.cpp:1030] Forwarding total oversubscribed resources
> I0229 02:11:01.897076 2153 slave.cpp:3482] Received ping from slave-observer(285)@172.17.0.3:36786
> I0229 02:11:01.897423 2143 hierarchical.cpp:1532] No inverse offers to send out!
> I0229 02:11:01.897423 2149 master.cpp:4663] Received update of slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(307)@172.17.0.3:36786 (3036a6611147) with total oversubscribed resources
> I0229 02:11:01.897579 2143 hierarchical.cpp:1150] Performed allocation for slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 in 2.629289ms
> I0229 02:11:01.898231 2149 master.cpp:5369] Sending 1 offers to framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (default) at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786
> I0229 02:11:01.898207 2153 hierarchical.cpp:531] Slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 (3036a6611147) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I0229 02:11:01.898370 2153 hierarchical.cpp:1437] No resources available to allocate!
> I0229 02:11:01.898407 2153 hierarchical.cpp:1532] No inverse offers to send out!
> I0229 02:11:01.898427 2153 hierarchical.cpp:1150] Performed allocation for slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 in 157330ns
> I0229 02:11:01.898775 2149 sched.cpp:873] Scheduler::resourceOffers took 146787ns
> I0229 02:11:01.901530 2157 master.cpp:3152] Processing ACCEPT call for offers: [ d551df7b-0c69-4bc9-b113-eca605384c49-O0 ] on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(307)@172.17.0.3:36786 (3036a6611147) for framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (default) at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786
> I0229 02:11:01.901593 2157 master.cpp:2824] Authorizing framework principal 'test-principal' to launch task 6f4f1f8c-2649-4c70-9767-2ea122a79101 as user 'mesos'
> I0229 02:11:01.903717 2157 master.hpp:176] Adding task 6f4f1f8c-2649-4c70-9767-2ea122a79101 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 (3036a6611147)
> I0229 02:11:01.903962 2157 master.cpp:3637] Launching task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (default) at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(307)@172.17.0.3:36786 (3036a6611147)
> I0229 02:11:01.904513 2149 slave.cpp:1361] Got assigned task 6f4f1f8c-2649-4c70-9767-2ea122a79101 for framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:01.904767 2149 slave.cpp:5287] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/framework.info'
> I0229 02:11:01.905364 2149 slave.cpp:5298] Checkpointing framework pid 'scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786' to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/framework.pid'
> I0229 02:11:01.905747 2149 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0229 02:11:01.906740 2149 slave.cpp:1480] Launching task 6f4f1f8c-2649-4c70-9767-2ea122a79101 for framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:01.906847 2149 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0229 02:11:01.932838 2149 paths.cpp:474] Trying to chown '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/runs/7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868' to user 'mesos'
> I0229 02:11:01.940505 2151 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 44.339091ms
> I0229 02:11:01.940579 2151 replica.cpp:712] Persisted action at 4
> I0229 02:11:01.941965 2151 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
> I0229 02:11:01.944691 2149 slave.cpp:5739] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/executor.info'
> I0229 02:11:01.945770 2149 slave.cpp:5367] Launching executor 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/runs/7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868'
> I0229 02:11:01.946591 2145 containerizer.cpp:666] Starting container '7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868' for executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework 'd551df7b-0c69-4bc9-b113-eca605384c49-0000'
> I0229 02:11:01.946722 2149 slave.cpp:5762] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/runs/7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868/tasks/6f4f1f8c-2649-4c70-9767-2ea122a79101/task.info'
> I0229 02:11:01.947401 2149 slave.cpp:1698] Queuing task '6f4f1f8c-2649-4c70-9767-2ea122a79101' for executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:01.947626 2149 slave.cpp:749] Successfully attached file '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/runs/7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868'
> I0229 02:11:01.956595 2148 launcher.cpp:147] Forked child with pid '8435' for container '7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868'
> I0229 02:11:01.956969 2148 containerizer.cpp:1104] Checkpointing executor's forked pid 8435 to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/runs/7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868/pids/forked.pid'
> I0229 02:11:01.992234 2151 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 50.196989ms
> I0229 02:11:01.992405 2151 leveldb.cpp:399] Deleting ~2 keys from leveldb took 90627ns
> I0229 02:11:01.992439 2151 replica.cpp:712] Persisted action at 4
> I0229 02:11:01.992478 2151 replica.cpp:697] Replica learned TRUNCATE action at position 4
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0229 02:11:02.186645 8449 process.cpp:991] libprocess is initialized on 172.17.0.3:43632 for 16 cpus
> I0229 02:11:02.187955 8449 logging.cpp:193] Logging to STDERR
> I0229 02:11:02.191845 8449 exec.cpp:143] Version: 0.28.0
> I0229 02:11:02.202843 8468 exec.cpp:193] Executor started at: executor(1)@172.17.0.3:43632 with pid 8449
> I0229 02:11:02.205981 2145 slave.cpp:2643] Got registration for executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 from executor(1)@172.17.0.3:43632
> I0229 02:11:02.206452 2145 slave.cpp:2729] Checkpointing executor pid 'executor(1)@172.17.0.3:43632' to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/runs/7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868/pids/libprocess.pid'
> I0229 02:11:02.209555 8465 exec.cpp:217] Executor registered on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0
> I0229 02:11:02.209779 2143 slave.cpp:1863] Sending queued task '6f4f1f8c-2649-4c70-9767-2ea122a79101' to executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 at executor(1)@172.17.0.3:43632
> I0229 02:11:02.213541 8465 exec.cpp:229] Executor::registered took 1.628703ms
> I0229 02:11:02.214021 8465 exec.cpp:304] Executor asked to run task '6f4f1f8c-2649-4c70-9767-2ea122a79101'
> I0229 02:11:02.214145 8465 exec.cpp:313] Executor::launchTask took 92955ns
> Registered executor on 3036a6611147
> Starting task 6f4f1f8c-2649-4c70-9767-2ea122a79101
> Forked command at 8480
> I0229 02:11:02.216815 8465 exec.cpp:526] Executor sending status update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> sh -c 'sleep 1000'
> I0229 02:11:02.219005 2150 slave.cpp:3002] Handling status update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 from executor(1)@172.17.0.3:43632
> I0229 02:11:02.221480 2150 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.221535 2150 status_update_manager.cpp:497] Creating StatusUpdate stream for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.222338 2150 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.300974 2150 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 to the slave
> I0229 02:11:02.301527 2154 slave.cpp:3400] Forwarding the update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 to master@172.17.0.3:36786
> I0229 02:11:02.301810 2154 slave.cpp:3294] Status update manager successfully handled status update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.301862 2154 slave.cpp:3310] Sending acknowledgement for status update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 to executor(1)@172.17.0.3:43632
> I0229 02:11:02.302170 2150 master.cpp:4808] Status update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 from slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(307)@172.17.0.3:36786 (3036a6611147)
> I0229 02:11:02.302229 2150 master.cpp:4856] Forwarding status update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.302445 2150 master.cpp:6464] Updating the state of task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0229 02:11:02.302655 2150 sched.cpp:981] Scheduler::statusUpdate took 29781ns
> I0229 02:11:02.302913 2150 master.cpp:3966] Processing ACKNOWLEDGE call 2de13aea-c019-4a1f-841c-978c03704940 for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (default) at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786 on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0
> I0229 02:11:02.303019 8467 exec.cpp:350] Executor received status update acknowledgement 2de13aea-c019-4a1f-841c-978c03704940 for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.303251 2154 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.303447 2154 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.376432 2154 slave.cpp:2412] Status update manager successfully handled status update acknowledgement (UUID: 2de13aea-c019-4a1f-841c-978c03704940) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.377727 2148 hierarchical.cpp:1437] No resources available to allocate!
> I0229 02:11:02.377792 2143 slave.cpp:668] Slave terminating
> I0229 02:11:02.377806 2148 hierarchical.cpp:1532] No inverse offers to send out!
> I0229 02:11:02.377843 2148 hierarchical.cpp:1130] Performed allocation for 1 slaves in 410214ns
> I0229 02:11:02.378212 2146 master.cpp:1173] Slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(307)@172.17.0.3:36786 (3036a6611147) disconnected
> I0229 02:11:02.378263 2146 master.cpp:2634] Disconnecting slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(307)@172.17.0.3:36786 (3036a6611147)
> I0229 02:11:02.378348 2146 master.cpp:2653] Deactivating slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(307)@172.17.0.3:36786 (3036a6611147)
> I0229 02:11:02.378558 2149 hierarchical.cpp:560] Slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 deactivated
> I0229 02:11:02.423666 2124 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> I0229 02:11:02.424350 8467 exec.cpp:390] Executor asked to shutdown
> I0229 02:11:02.424566 8467 exec.cpp:405] Executor::shutdown took 17169ns
> I0229 02:11:02.424738 8467 exec.cpp:87] Scheduling shutdown of the executor in 5secs
> W0229 02:11:02.424836 2124 backend.cpp:60] Failed to create 'bind' backend: BindBackend requires root privileges
> Shutting down
> Sending SIGTERM to process tree at pid 8480
> I0229 02:11:02.431053 2149 slave.cpp:193] Slave started on 308)@172.17.0.3:36786
> I0229 02:11:02.431102 2149 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --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_RecoverTerminatedExecutor_eVw0V2/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/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_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2"
> I0229 02:11:02.431581 2149 credentials.hpp:83] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/credential'
> I0229 02:11:02.431838 2149 slave.cpp:324] Slave using credential for: test-principal
> I0229 02:11:02.432054 2149 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0229 02:11:02.432600 2149 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0229 02:11:02.432682 2149 slave.cpp:472] Slave attributes: [ ]
> I0229 02:11:02.432695 2149 slave.cpp:477] Slave hostname: 3036a6611147
> I0229 02:11:02.434396 2149 state.cpp:58] Recovering state from '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta'
> I0229 02:11:02.434486 2149 state.cpp:698] No checkpointed resources found at '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/resources/resources.info'
> Sent SIGTERM to the following process trees:
> [
> -+- 8480 sh -c sleep 1000
> \--- 8481 sleep 1000
> ]
> I0229 02:11:02.454849 2149 fetcher.cpp:81] Clearing fetcher cache
> I0229 02:11:02.454975 2149 slave.cpp:4653] Recovering framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.455072 2149 slave.cpp:5476] Recovering executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.456887 2149 slave.cpp:749] Successfully attached file '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/runs/7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868'
> I0229 02:11:02.456956 2149 status_update_manager.cpp:200] Recovering status update manager
> I0229 02:11:02.456984 2149 status_update_manager.cpp:208] Recovering executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.457064 2149 status_update_manager.cpp:497] Creating StatusUpdate stream for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.457695 2149 status_update_manager.cpp:800] Replaying status update stream for task 6f4f1f8c-2649-4c70-9767-2ea122a79101
> I0229 02:11:02.459211 2149 containerizer.cpp:407] Recovering containerizer
> I0229 02:11:02.459395 2149 containerizer.cpp:462] Recovering container '7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868' for executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.462517 2146 provisioner.cpp:245] Provisioner recovery complete
> I0229 02:11:02.464293 2153 slave.cpp:4505] Sending reconnect request to executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 at executor(1)@172.17.0.3:43632
> I0229 02:11:02.465364 8468 exec.cpp:258] Ignoring reconnect message from slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 because the driver is aborted!
> I0229 02:11:02.485313 2150 hierarchical.cpp:1437] No resources available to allocate!
> I0229 02:11:02.485401 2150 hierarchical.cpp:1532] No inverse offers to send out!
> I0229 02:11:02.485441 2150 hierarchical.cpp:1130] Performed allocation for 1 slaves in 375179ns
> I0229 02:11:02.485551 2150 slave.cpp:2942] Cleaning up un-reregistered executors
> I0229 02:11:02.485586 2150 slave.cpp:2960] Killing un-reregistered executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 at executor(1)@172.17.0.3:43632
> I0229 02:11:02.485779 2150 slave.cpp:4565] Finished recovery
> I0229 02:11:02.486176 2157 containerizer.cpp:1378] Destroying container '7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868'
> I0229 02:11:02.498023 2154 hierarchical.cpp:1437] No resources available to allocate!
> I0229 02:11:02.498111 2154 hierarchical.cpp:1532] No inverse offers to send out!
> I0229 02:11:02.498147 2154 hierarchical.cpp:1130] Performed allocation for 1 slaves in 319161ns
> I0229 02:11:02.498203 2147 containerizer.cpp:1594] Executor for container '7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868' has exited
> I0229 02:11:02.502073 2147 provisioner.cpp:306] Ignoring destroy request for unknown container 7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868
> I0229 02:11:02.509719 2150 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0229 02:11:02.510071 2150 slave.cpp:3886] Executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 terminated with signal Killed
> I0229 02:11:02.510351 2150 slave.cpp:3002] Handling status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 from @0.0.0.0:0
> I0229 02:11:02.510887 2146 status_update_manager.cpp:174] Pausing sending status updates
> I0229 02:11:02.510893 2150 slave.cpp:796] New master detected at master@172.17.0.3:36786
> I0229 02:11:02.511204 2150 slave.cpp:859] Authenticating with master master@172.17.0.3:36786
> I0229 02:11:02.511304 2150 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0229 02:11:02.511641 2150 slave.cpp:832] Detecting new master
> I0229 02:11:02.511862 2150 slave.cpp:4751] Received oversubscribable resources from the resource estimator
> I0229 02:11:02.512126 2150 slave.cpp:5677] Terminating task 6f4f1f8c-2649-4c70-9767-2ea122a79101
> I0229 02:11:02.512384 2154 authenticatee.cpp:121] Creating new client SASL connection
> W0229 02:11:02.512861 2154 containerizer.cpp:1220] Ignoring update for unknown container: 7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868
> I0229 02:11:02.512864 2150 master.cpp:5540] Authenticating slave(308)@172.17.0.3:36786
> I0229 02:11:02.513216 2150 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(673)@172.17.0.3:36786
> I0229 02:11:02.513319 2154 status_update_manager.cpp:320] Received status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.513401 2154 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.513730 2152 authenticator.cpp:98] Creating new server SASL connection
> I0229 02:11:02.513952 2150 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0229 02:11:02.514041 2150 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0229 02:11:02.514322 2145 authenticator.cpp:203] Received SASL authentication start
> I0229 02:11:02.514397 2145 authenticator.cpp:325] Authentication requires more steps
> I0229 02:11:02.514547 2153 authenticatee.cpp:258] Received SASL authentication step
> I0229 02:11:02.514673 2153 authenticator.cpp:231] Received SASL authentication step
> I0229 02:11:02.514708 2153 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '3036a6611147' server FQDN: '3036a6611147' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0229 02:11:02.514720 2153 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0229 02:11:02.514778 2153 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0229 02:11:02.514811 2153 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: '3036a6611147' server FQDN: '3036a6611147' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0229 02:11:02.514823 2153 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0229 02:11:02.514832 2153 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0229 02:11:02.514852 2153 authenticator.cpp:317] Authentication success
> I0229 02:11:02.515035 2153 authenticatee.cpp:298] Authentication success
> I0229 02:11:02.515146 2153 master.cpp:5570] Successfully authenticated principal 'test-principal' at slave(308)@172.17.0.3:36786
> I0229 02:11:02.515251 2153 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(673)@172.17.0.3:36786
> I0229 02:11:02.516299 2146 slave.cpp:927] Successfully authenticated with master master@172.17.0.3:36786
> I0229 02:11:02.516770 2146 slave.cpp:1321] Will retry registration in 1.20168ms if necessary
> I0229 02:11:02.517236 2146 master.cpp:4414] Re-registering slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(307)@172.17.0.3:36786 (3036a6611147)
> I0229 02:11:02.517813 2146 master.cpp:4601] Sending updated checkpointed resources to slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(308)@172.17.0.3:36786 (3036a6611147)
> I0229 02:11:02.518044 2146 slave.cpp:1071] Re-registered with master master@172.17.0.3:36786
> I0229 02:11:02.518594 2148 hierarchical.cpp:548] Slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 reactivated
> I0229 02:11:02.519234 2146 slave.cpp:1107] Forwarding total oversubscribed resources
> I0229 02:11:02.519526 2155 master.cpp:4663] Received update of slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(308)@172.17.0.3:36786 (3036a6611147) with total oversubscribed resources
> I0229 02:11:02.519976 2146 slave.cpp:2248] Updating framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 pid to scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786
> I0229 02:11:02.520033 2146 slave.cpp:2264] Checkpointing framework pid 'scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786' to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/framework.pid'
> I0229 02:11:02.520256 2155 hierarchical.cpp:531] Slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 (3036a6611147) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I0229 02:11:02.520561 2155 hierarchical.cpp:1437] No resources available to allocate!
> I0229 02:11:02.520611 2155 hierarchical.cpp:1532] No inverse offers to send out!
> I0229 02:11:02.520635 2155 hierarchical.cpp:1150] Performed allocation for slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 in 283292ns
> I0229 02:11:02.520766 2146 slave.cpp:2341] Updated checkpointed resources from to
> I0229 02:11:02.602648 2154 status_update_manager.cpp:181] Resuming sending status updates
> W0229 02:11:02.602721 2154 status_update_manager.cpp:188] Resending status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.602764 2154 status_update_manager.cpp:374] Forwarding update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 to the slave
> I0229 02:11:02.602999 2154 status_update_manager.cpp:181] Resuming sending status updates
> W0229 02:11:02.603032 2154 status_update_manager.cpp:188] Resending status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.603058 2154 status_update_manager.cpp:374] Forwarding update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 to the slave
> I0229 02:11:02.603255 2154 slave.cpp:3294] Status update manager successfully handled status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.603399 2154 slave.cpp:3400] Forwarding the update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 to master@172.17.0.3:36786
> I0229 02:11:02.603621 2154 slave.cpp:3400] Forwarding the update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 to master@172.17.0.3:36786
> I0229 02:11:02.603940 2154 master.cpp:4808] Status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 from slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(308)@172.17.0.3:36786 (3036a6611147)
> I0229 02:11:02.603986 2154 master.cpp:4856] Forwarding status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.604146 2154 master.cpp:6464] Updating the state of task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (latest state: TASK_LOST, status update state: TASK_LOST)
> I0229 02:11:02.604966 2154 master.cpp:4808] Status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 from slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(308)@172.17.0.3:36786 (3036a6611147)
> I0229 02:11:02.605010 2154 master.cpp:4856] Forwarding status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.605139 2154 master.cpp:6464] Updating the state of task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (latest state: TASK_LOST, status update state: TASK_LOST)
> I0229 02:11:02.605356 2154 sched.cpp:981] Scheduler::statusUpdate took 61179ns
> ../../src/tests/slave_recovery_tests.cpp:791: Failure
> Mock function called more times than expected - returning directly.
> Function call: statusUpdate(0x7ffff1b38c70, @0x2b8c7e7d1650 112-byte object <50-E1 4D-73 8C-2B 00-00 00-00 00-00 00-00 00-00 D0-4E 02-A0 8C-2B 00-00 F0-60 02-A0 8C-2B 00-00 05-00 00-00 01-00 00-00 30-F0 28-02 00-00 00-00 90-30 02-A0 8C-2B 00-00 10-30 02-A0 8C-2B 00-00 18-00 00-00 00-2B 00-00 74-42 9E-DD D9-BB D5-41 10-AD 03-A0 8C-2B 00-00 00-00 00-00 00-00 00-00 10-B2 01-A0 8C-2B 00-00 00-00 00-00 DF-13 00-00>)
> Expected: to be called once
> Actual: called twice - over-saturated and active
> I0229 02:11:02.605726 2154 sched.cpp:981] Scheduler::statusUpdate took 171976ns
> I0229 02:11:02.606462 2147 master.cpp:3966] Processing ACKNOWLEDGE call 9514b5e3-4a43-4593-b93f-d886e3791c84 for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (default) at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786 on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0
> I0229 02:11:02.606490 2154 hierarchical.cpp:890] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 from framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.606529 2147 master.cpp:6530] Removing task 6f4f1f8c-2649-4c70-9767-2ea122a79101 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 at slave(308)@172.17.0.3:36786 (3036a6611147)
> I0229 02:11:02.606905 2147 master.cpp:3966] Processing ACKNOWLEDGE call 9514b5e3-4a43-4593-b93f-d886e3791c84 for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (default) at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786 on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0
> I0229 02:11:02.607291 2156 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.607429 2156 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_LOST (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.652583 2156 status_update_manager.cpp:528] Cleaning up status update stream for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.653198 2156 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.653383 2156 slave.cpp:2412] Status update manager successfully handled status update acknowledgement (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.653452 2156 slave.cpp:5718] Completing task 6f4f1f8c-2649-4c70-9767-2ea122a79101
> I0229 02:11:02.653503 2156 slave.cpp:3990] Cleaning up executor '6f4f1f8c-2649-4c70-9767-2ea122a79101' of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 at executor(1)@172.17.0.3:43632
> I0229 02:11:02.657869 2147 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/runs/7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868' for gc 6.99999500224593days in the future
> I0229 02:11:02.658114 2147 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101' for gc 6.99999500224593days in the future
> I0229 02:11:02.658231 2147 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101/runs/7083e51a-c5ab-4d7b-a9e5-aca9cb9cd868' for gc 6.99999500224593days in the future
> I0229 02:11:02.658488 2145 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000/executors/6f4f1f8c-2649-4c70-9767-2ea122a79101' for gc 6.99999500224593days in the future
> I0229 02:11:02.658499 2156 slave.cpp:4078] Cleaning up framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.658641 2158 status_update_manager.cpp:282] Closing status update streams for framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.658742 2150 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000' for gc 6.99999500224593days in the future
> I0229 02:11:02.658831 2150 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_eVw0V2/meta/slaves/d551df7b-0c69-4bc9-b113-eca605384c49-S0/frameworks/d551df7b-0c69-4bc9-b113-eca605384c49-0000' for gc 6.99999500224593days in the future
> E0229 02:11:02.658875 2156 slave.cpp:2405] Failed to handle status update acknowledgement (UUID: 9514b5e3-4a43-4593-b93f-d886e3791c84) for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000: Cannot find the status update stream for task 6f4f1f8c-2649-4c70-9767-2ea122a79101 of framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.679185 2158 hierarchical.cpp:1532] No inverse offers to send out!
> I0229 02:11:02.679271 2158 hierarchical.cpp:1130] Performed allocation for 1 slaves in 1.029109ms
> I0229 02:11:02.679770 2158 master.cpp:5369] Sending 1 offers to framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (default) at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786
> I0229 02:11:02.680276 2158 sched.cpp:873] Scheduler::resourceOffers took 112861ns
> I0229 02:11:02.698971 2124 sched.cpp:1903] Asked to stop the driver
> I0229 02:11:02.699208 2150 sched.cpp:1143] Stopping framework 'd551df7b-0c69-4bc9-b113-eca605384c49-0000'
> I0229 02:11:02.699738 2150 master.cpp:5940] Processing TEARDOWN call for framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (default) at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786
> I0229 02:11:02.699774 2150 master.cpp:5952] Removing framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 (default) at scheduler-2f5c2abf-e929-4d08-9a8a-5869e11e22ad@172.17.0.3:36786
> I0229 02:11:02.700911 2150 hierarchical.cpp:375] Deactivated framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.701093 2124 master.cpp:1026] Master terminating
> I0229 02:11:02.701534 2150 hierarchical.cpp:890] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave d551df7b-0c69-4bc9-b113-eca605384c49-S0 from framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.701709 2150 hierarchical.cpp:326] Removed framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.702055 2150 hierarchical.cpp:505] Removed slave d551df7b-0c69-4bc9-b113-eca605384c49-S0
> I0229 02:11:02.702139 2150 slave.cpp:2079] Asked to shut down framework d551df7b-0c69-4bc9-b113-eca605384c49-0000 by master@172.17.0.3:36786
> W0229 02:11:02.702172 2150 slave.cpp:2094] Cannot shut down unknown framework d551df7b-0c69-4bc9-b113-eca605384c49-0000
> I0229 02:11:02.702206 2150 slave.cpp:3528] master@172.17.0.3:36786 exited
> W0229 02:11:02.706275 2150 slave.cpp:3531] Master disconnected! Waiting for a new master to be elected
> I0229 02:11:02.752670 2145 slave.cpp:668] Slave terminating
> [ FAILED ] SlaveRecoveryTest/0.RecoverTerminatedExecutor, where TypeParam = mesos::internal::slave::MesosContainerizer (1582 ms)
> {code}
> Logs from a good run:
> {code}
> [ RUN ] SlaveRecoveryTest/0.RecoverTerminatedExecutor
> I0228 18:55:37.914356 2118 leveldb.cpp:174] Opened db in 114.208389ms
> I0228 18:55:37.941313 2118 leveldb.cpp:181] Compacted db in 26.862209ms
> I0228 18:55:37.941436 2118 leveldb.cpp:196] Created db iterator in 32336ns
> I0228 18:55:37.941454 2118 leveldb.cpp:202] Seeked to beginning of db in 3799ns
> I0228 18:55:37.941465 2118 leveldb.cpp:271] Iterated through 0 keys in the db in 331ns
> I0228 18:55:37.941524 2118 replica.cpp:779] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0228 18:55:37.942369 2148 recover.cpp:447] Starting replica recovery
> I0228 18:55:37.942694 2148 recover.cpp:473] Replica is in EMPTY status
> I0228 18:55:37.944351 2147 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from (9844)@172.17.0.3:58779
> I0228 18:55:37.945255 2148 recover.cpp:193] Received a recover response from a replica in EMPTY status
> I0228 18:55:37.946694 2148 recover.cpp:564] Updating replica status to STARTING
> I0228 18:55:37.950327 2145 master.cpp:376] Master 8cb42f1a-ab2c-4063-8e86-859f724f606b (ebb7e5710eae) started on 172.17.0.3:58779
> I0228 18:55:37.950374 2145 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/ecnC7S/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/ecnC7S/master" --zk_session_timeout="10secs"
> I0228 18:55:37.950772 2145 master.cpp:423] Master only allowing authenticated frameworks to register
> I0228 18:55:37.950783 2145 master.cpp:428] Master only allowing authenticated slaves to register
> I0228 18:55:37.950793 2145 credentials.hpp:35] Loading credentials for authentication from '/tmp/ecnC7S/credentials'
> I0228 18:55:37.951211 2145 master.cpp:468] Using default 'crammd5' authenticator
> I0228 18:55:37.951508 2145 master.cpp:537] Using default 'basic' HTTP authenticator
> I0228 18:55:37.951655 2145 master.cpp:571] Authorization enabled
> I0228 18:55:37.952121 2142 hierarchical.cpp:144] Initialized hierarchical allocator process
> I0228 18:55:37.952214 2142 whitelist_watcher.cpp:77] No whitelist given
> I0228 18:55:37.955916 2145 master.cpp:1712] The newly elected leader is master@172.17.0.3:58779 with id 8cb42f1a-ab2c-4063-8e86-859f724f606b
> I0228 18:55:37.956073 2145 master.cpp:1725] Elected as the leading master!
> I0228 18:55:37.956151 2145 master.cpp:1470] Recovering from registrar
> I0228 18:55:37.956349 2144 registrar.cpp:307] Recovering registrar
> I0228 18:55:37.972228 2148 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 25.240296ms
> I0228 18:55:37.972316 2148 replica.cpp:320] Persisted replica status to STARTING
> I0228 18:55:37.972709 2148 recover.cpp:473] Replica is in STARTING status
> I0228 18:55:37.975121 2148 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from (9847)@172.17.0.3:58779
> I0228 18:55:37.975909 2148 recover.cpp:193] Received a recover response from a replica in STARTING status
> I0228 18:55:37.978641 2148 recover.cpp:564] Updating replica status to VOTING
> I0228 18:55:37.999315 2148 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 20.327117ms
> I0228 18:55:37.999399 2148 replica.cpp:320] Persisted replica status to VOTING
> I0228 18:55:37.999673 2148 recover.cpp:578] Successfully joined the Paxos group
> I0228 18:55:37.999883 2148 recover.cpp:462] Recover process terminated
> I0228 18:55:38.000686 2142 log.cpp:659] Attempting to start the writer
> I0228 18:55:38.002662 2142 replica.cpp:493] Replica received implicit promise request from (9848)@172.17.0.3:58779 with proposal 1
> I0228 18:55:38.033356 2142 leveldb.cpp:304] Persisting metadata (8 bytes) to leveldb took 30.623998ms
> I0228 18:55:38.033432 2142 replica.cpp:342] Persisted promised to 1
> I0228 18:55:38.035011 2143 coordinator.cpp:238] Coordinator attempting to fill missing positions
> I0228 18:55:38.037057 2142 replica.cpp:388] Replica received explicit promise request from (9849)@172.17.0.3:58779 for position 0 with proposal 2
> I0228 18:55:38.070173 2142 leveldb.cpp:341] Persisting action (8 bytes) to leveldb took 32.934897ms
> I0228 18:55:38.070277 2142 replica.cpp:712] Persisted action at 0
> I0228 18:55:38.072190 2142 replica.cpp:537] Replica received write request for position 0 from (9850)@172.17.0.3:58779
> I0228 18:55:38.072540 2142 leveldb.cpp:436] Reading position from leveldb took 59250ns
> I0228 18:55:38.112357 2142 leveldb.cpp:341] Persisting action (14 bytes) to leveldb took 39.661651ms
> I0228 18:55:38.112449 2142 replica.cpp:712] Persisted action at 0
> I0228 18:55:38.113600 2142 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
> I0228 18:55:38.146307 2142 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 32.66039ms
> I0228 18:55:38.146385 2142 replica.cpp:712] Persisted action at 0
> I0228 18:55:38.146423 2142 replica.cpp:697] Replica learned NOP action at position 0
> I0228 18:55:38.147629 2137 log.cpp:675] Writer started with ending position 0
> I0228 18:55:38.148942 2137 leveldb.cpp:436] Reading position from leveldb took 69646ns
> I0228 18:55:38.150367 2138 registrar.cpp:340] Successfully fetched the registry (0B) in 193.948928ms
> I0228 18:55:38.150549 2138 registrar.cpp:439] Applied 1 operations in 42065ns; attempting to update the 'registry'
> I0228 18:55:38.154400 2140 log.cpp:683] Attempting to append 170 bytes to the log
> I0228 18:55:38.154647 2152 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
> I0228 18:55:38.155762 2138 replica.cpp:537] Replica received write request for position 1 from (9851)@172.17.0.3:58779
> I0228 18:55:38.204361 2138 leveldb.cpp:341] Persisting action (189 bytes) to leveldb took 48.528957ms
> I0228 18:55:38.204459 2138 replica.cpp:712] Persisted action at 1
> I0228 18:55:38.206050 2138 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
> I0228 18:55:38.254456 2138 leveldb.cpp:341] Persisting action (191 bytes) to leveldb took 48.338559ms
> I0228 18:55:38.254559 2138 replica.cpp:712] Persisted action at 1
> I0228 18:55:38.254600 2138 replica.cpp:697] Replica learned APPEND action at position 1
> I0228 18:55:38.256258 2137 registrar.cpp:484] Successfully updated the 'registry' in 105.6128ms
> I0228 18:55:38.256438 2137 registrar.cpp:370] Successfully recovered registrar
> I0228 18:55:38.256533 2150 log.cpp:702] Attempting to truncate the log to 1
> I0228 18:55:38.256718 2137 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
> I0228 18:55:38.256917 2150 master.cpp:1522] Recovered 0 slaves from the Registry (131B) ; allowing 10mins for slaves to re-register
> I0228 18:55:38.257408 2150 hierarchical.cpp:171] Skipping recovery of hierarchical allocator: nothing to recover
> I0228 18:55:38.257995 2152 replica.cpp:537] Replica received write request for position 2 from (9852)@172.17.0.3:58779
> I0228 18:55:38.296432 2152 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 38.370462ms
> I0228 18:55:38.296525 2152 replica.cpp:712] Persisted action at 2
> I0228 18:55:38.297710 2138 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
> I0228 18:55:38.349069 2138 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 51.225225ms
> I0228 18:55:38.349252 2138 leveldb.cpp:399] Deleting ~1 keys from leveldb took 89416ns
> I0228 18:55:38.349282 2138 replica.cpp:712] Persisted action at 2
> I0228 18:55:38.349318 2138 replica.cpp:697] Replica learned TRUNCATE action at position 2
> I0228 18:55:38.367254 2118 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W0228 18:55:38.367934 2118 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
> I0228 18:55:38.375131 2143 slave.cpp:193] Slave started on 307)@172.17.0.3:58779
> I0228 18:55:38.375349 2143 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --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_RecoverTerminatedExecutor_rHFO1G/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/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_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G"
> I0228 18:55:38.376035 2143 credentials.hpp:83] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/credential'
> I0228 18:55:38.376386 2143 slave.cpp:324] Slave using credential for: test-principal
> I0228 18:55:38.376652 2143 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0228 18:55:38.377331 2143 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0228 18:55:38.377483 2143 slave.cpp:472] Slave attributes: [ ]
> I0228 18:55:38.377588 2143 slave.cpp:477] Slave hostname: ebb7e5710eae
> I0228 18:55:38.379653 2137 state.cpp:58] Recovering state from '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta'
> I0228 18:55:38.380345 2137 status_update_manager.cpp:200] Recovering status update manager
> I0228 18:55:38.380529 2137 containerizer.cpp:407] Recovering containerizer
> I0228 18:55:38.385637 2138 provisioner.cpp:245] Provisioner recovery complete
> I0228 18:55:38.385814 2118 sched.cpp:222] Version: 0.28.0
> I0228 18:55:38.386225 2141 slave.cpp:4565] Finished recovery
> I0228 18:55:38.386695 2143 sched.cpp:326] New master detected at master@172.17.0.3:58779
> I0228 18:55:38.386844 2143 sched.cpp:382] Authenticating with master master@172.17.0.3:58779
> I0228 18:55:38.386869 2143 sched.cpp:389] Using default CRAM-MD5 authenticatee
> I0228 18:55:38.387190 2150 authenticatee.cpp:121] Creating new client SASL connection
> I0228 18:55:38.387573 2150 master.cpp:5541] Authenticating scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779
> I0228 18:55:38.387691 2138 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(674)@172.17.0.3:58779
> I0228 18:55:38.388062 2138 authenticator.cpp:98] Creating new server SASL connection
> I0228 18:55:38.388432 2152 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0228 18:55:38.388468 2152 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0228 18:55:38.388617 2138 authenticator.cpp:203] Received SASL authentication start
> I0228 18:55:38.388689 2138 authenticator.cpp:325] Authentication requires more steps
> I0228 18:55:38.388784 2138 authenticatee.cpp:258] Received SASL authentication step
> I0228 18:55:38.388890 2138 authenticator.cpp:231] Received SASL authentication step
> I0228 18:55:38.388927 2138 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ebb7e5710eae' server FQDN: 'ebb7e5710eae' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0228 18:55:38.388944 2138 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0228 18:55:38.389003 2138 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0228 18:55:38.389046 2138 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ebb7e5710eae' server FQDN: 'ebb7e5710eae' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0228 18:55:38.389066 2138 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0228 18:55:38.389078 2138 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0228 18:55:38.389101 2138 authenticator.cpp:317] Authentication success
> I0228 18:55:38.389322 2144 authenticatee.cpp:298] Authentication success
> I0228 18:55:38.389431 2152 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(674)@172.17.0.3:58779
> I0228 18:55:38.389591 2150 master.cpp:5571] Successfully authenticated principal 'test-principal' at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779
> I0228 18:55:38.389958 2143 sched.cpp:471] Successfully authenticated with master master@172.17.0.3:58779
> I0228 18:55:38.389986 2143 sched.cpp:776] Sending SUBSCRIBE call to master@172.17.0.3:58779
> I0228 18:55:38.390100 2143 sched.cpp:809] Will retry registration in 1.715153707secs if necessary
> I0228 18:55:38.390249 2151 master.cpp:2280] Received SUBSCRIBE call for framework 'default' at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779
> I0228 18:55:38.390319 2151 master.cpp:1751] Authorizing framework principal 'test-principal' to receive offers for role '*'
> I0228 18:55:38.390579 2151 master.cpp:2351] Subscribing framework default with checkpointing enabled and capabilities [ ]
> I0228 18:55:38.391083 2142 hierarchical.cpp:265] Added framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.391175 2142 hierarchical.cpp:1437] No resources available to allocate!
> I0228 18:55:38.391216 2142 hierarchical.cpp:1532] No inverse offers to send out!
> I0228 18:55:38.391263 2142 hierarchical.cpp:1130] Performed allocation for 0 slaves in 154731ns
> I0228 18:55:38.391296 2147 sched.cpp:703] Framework registered with 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.391343 2147 sched.cpp:717] Scheduler::registered took 25181ns
> I0228 18:55:38.392155 2141 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0228 18:55:38.392815 2141 slave.cpp:796] New master detected at master@172.17.0.3:58779
> I0228 18:55:38.392930 2141 slave.cpp:859] Authenticating with master master@172.17.0.3:58779
> I0228 18:55:38.392956 2141 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0228 18:55:38.393198 2141 slave.cpp:832] Detecting new master
> I0228 18:55:38.393371 2141 slave.cpp:4751] Received oversubscribable resources from the resource estimator
> I0228 18:55:38.393489 2141 status_update_manager.cpp:174] Pausing sending status updates
> I0228 18:55:38.393673 2141 authenticatee.cpp:121] Creating new client SASL connection
> I0228 18:55:38.394181 2141 master.cpp:5541] Authenticating slave(307)@172.17.0.3:58779
> I0228 18:55:38.394426 2141 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(675)@172.17.0.3:58779
> I0228 18:55:38.394837 2141 authenticator.cpp:98] Creating new server SASL connection
> I0228 18:55:38.395114 2141 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0228 18:55:38.395146 2141 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0228 18:55:38.395267 2141 authenticator.cpp:203] Received SASL authentication start
> I0228 18:55:38.395354 2141 authenticator.cpp:325] Authentication requires more steps
> I0228 18:55:38.395452 2141 authenticatee.cpp:258] Received SASL authentication step
> I0228 18:55:38.395581 2141 authenticator.cpp:231] Received SASL authentication step
> I0228 18:55:38.395623 2141 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ebb7e5710eae' server FQDN: 'ebb7e5710eae' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0228 18:55:38.395642 2141 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0228 18:55:38.395722 2141 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0228 18:55:38.395772 2141 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ebb7e5710eae' server FQDN: 'ebb7e5710eae' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0228 18:55:38.395789 2141 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0228 18:55:38.395798 2141 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0228 18:55:38.395833 2141 authenticator.cpp:317] Authentication success
> I0228 18:55:38.396147 2141 authenticatee.cpp:298] Authentication success
> I0228 18:55:38.396280 2141 master.cpp:5571] Successfully authenticated principal 'test-principal' at slave(307)@172.17.0.3:58779
> I0228 18:55:38.396399 2141 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(675)@172.17.0.3:58779
> I0228 18:55:38.396824 2141 slave.cpp:927] Successfully authenticated with master master@172.17.0.3:58779
> I0228 18:55:38.397006 2141 slave.cpp:1321] Will retry registration in 7.607848ms if necessary
> I0228 18:55:38.397450 2141 master.cpp:4255] Registering slave at slave(307)@172.17.0.3:58779 (ebb7e5710eae) with id 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0
> I0228 18:55:38.398105 2141 registrar.cpp:439] Applied 1 operations in 89536ns; attempting to update the 'registry'
> I0228 18:55:38.400717 2147 log.cpp:683] Attempting to append 339 bytes to the log
> I0228 18:55:38.401324 2143 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
> I0228 18:55:38.402549 2144 replica.cpp:537] Replica received write request for position 3 from (9866)@172.17.0.3:58779
> I0228 18:55:38.406535 2152 slave.cpp:1321] Will retry registration in 30.166245ms if necessary
> I0228 18:55:38.406738 2149 master.cpp:4243] Ignoring register slave message from slave(307)@172.17.0.3:58779 (ebb7e5710eae) as admission is already in progress
> I0228 18:55:38.411780 2144 leveldb.cpp:341] Persisting action (358 bytes) to leveldb took 9.128675ms
> I0228 18:55:38.411871 2144 replica.cpp:712] Persisted action at 3
> I0228 18:55:38.413658 2144 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
> I0228 18:55:38.437741 2149 slave.cpp:1321] Will retry registration in 26.773163ms if necessary
> I0228 18:55:38.438109 2149 master.cpp:4243] Ignoring register slave message from slave(307)@172.17.0.3:58779 (ebb7e5710eae) as admission is already in progress
> I0228 18:55:38.447325 2144 leveldb.cpp:341] Persisting action (360 bytes) to leveldb took 33.542646ms
> I0228 18:55:38.447417 2144 replica.cpp:712] Persisted action at 3
> I0228 18:55:38.447456 2144 replica.cpp:697] Replica learned APPEND action at position 3
> I0228 18:55:38.449620 2151 registrar.cpp:484] Successfully updated the 'registry' in 51.421952ms
> I0228 18:55:38.449982 2151 log.cpp:702] Attempting to truncate the log to 3
> I0228 18:55:38.450227 2151 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
> I0228 18:55:38.450724 2144 master.cpp:4323] Registered slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(307)@172.17.0.3:58779 (ebb7e5710eae) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0228 18:55:38.450893 2144 slave.cpp:971] Registered with master master@172.17.0.3:58779; given slave ID 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0
> I0228 18:55:38.450914 2144 fetcher.cpp:81] Clearing fetcher cache
> I0228 18:55:38.451091 2138 hierarchical.cpp:473] Added slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 (ebb7e5710eae) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0228 18:55:38.451346 2144 slave.cpp:994] Checkpointing SlaveInfo to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/slave.info'
> I0228 18:55:38.451781 2144 slave.cpp:1030] Forwarding total oversubscribed resources
> I0228 18:55:38.451879 2144 slave.cpp:3482] Received ping from slave-observer(285)@172.17.0.3:58779
> I0228 18:55:38.452075 2144 status_update_manager.cpp:181] Resuming sending status updates
> I0228 18:55:38.452134 2138 hierarchical.cpp:1532] No inverse offers to send out!
> I0228 18:55:38.452173 2138 hierarchical.cpp:1150] Performed allocation for slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 in 1.042777ms
> I0228 18:55:38.452208 2144 master.cpp:4664] Received update of slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(307)@172.17.0.3:58779 (ebb7e5710eae) with total oversubscribed resources
> I0228 18:55:38.453052 2144 master.cpp:5370] Sending 1 offers to framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (default) at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779
> I0228 18:55:38.453397 2146 replica.cpp:537] Replica received write request for position 4 from (9867)@172.17.0.3:58779
> I0228 18:55:38.453454 2151 hierarchical.cpp:531] Slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 (ebb7e5710eae) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I0228 18:55:38.453621 2151 hierarchical.cpp:1437] No resources available to allocate!
> I0228 18:55:38.453660 2151 hierarchical.cpp:1532] No inverse offers to send out!
> I0228 18:55:38.453680 2151 hierarchical.cpp:1150] Performed allocation for slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 in 181027ns
> I0228 18:55:38.454643 2142 sched.cpp:873] Scheduler::resourceOffers took 201519ns
> I0228 18:55:38.457087 2147 master.cpp:3153] Processing ACCEPT call for offers: [ 8cb42f1a-ab2c-4063-8e86-859f724f606b-O0 ] on slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(307)@172.17.0.3:58779 (ebb7e5710eae) for framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (default) at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779
> I0228 18:55:38.457165 2147 master.cpp:2825] Authorizing framework principal 'test-principal' to launch task c8d01c56-9ee0-4936-b0b6-207e5188ea7b as user 'mesos'
> I0228 18:55:38.459369 2139 master.hpp:176] Adding task c8d01c56-9ee0-4936-b0b6-207e5188ea7b with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 (ebb7e5710eae)
> I0228 18:55:38.459660 2139 master.cpp:3638] Launching task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (default) at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(307)@172.17.0.3:58779 (ebb7e5710eae)
> I0228 18:55:38.460167 2139 slave.cpp:1361] Got assigned task c8d01c56-9ee0-4936-b0b6-207e5188ea7b for framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.460394 2139 slave.cpp:5287] Checkpointing FrameworkInfo to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/framework.info'
> I0228 18:55:38.461010 2139 slave.cpp:5298] Checkpointing framework pid 'scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779' to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/framework.pid'
> I0228 18:55:38.461572 2139 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0228 18:55:38.463532 2139 slave.cpp:1480] Launching task c8d01c56-9ee0-4936-b0b6-207e5188ea7b for framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.463740 2139 resources.cpp:572] Parsing resources as JSON failed: cpus:0.1;mem:32
> Trying semicolon-delimited string format instead
> I0228 18:55:38.464825 2139 paths.cpp:474] Trying to chown '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/runs/b17e17d0-b39c-47f5-9199-8ab69991b2ce' to user 'mesos'
> I0228 18:55:38.498957 2139 slave.cpp:5739] Checkpointing ExecutorInfo to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/executor.info'
> I0228 18:55:38.500051 2139 slave.cpp:5367] Launching executor c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/runs/b17e17d0-b39c-47f5-9199-8ab69991b2ce'
> I0228 18:55:38.501173 2140 containerizer.cpp:666] Starting container 'b17e17d0-b39c-47f5-9199-8ab69991b2ce' for executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework '8cb42f1a-ab2c-4063-8e86-859f724f606b-0000'
> I0228 18:55:38.502866 2139 slave.cpp:5762] Checkpointing TaskInfo to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/runs/b17e17d0-b39c-47f5-9199-8ab69991b2ce/tasks/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/task.info'
> I0228 18:55:38.503651 2139 slave.cpp:1698] Queuing task 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' for executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.503965 2139 slave.cpp:749] Successfully attached file '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/runs/b17e17d0-b39c-47f5-9199-8ab69991b2ce'
> I0228 18:55:38.508589 2146 leveldb.cpp:341] Persisting action (16 bytes) to leveldb took 55.006184ms
> I0228 18:55:38.508730 2146 replica.cpp:712] Persisted action at 4
> I0228 18:55:38.509603 2147 launcher.cpp:147] Forked child with pid '8479' for container 'b17e17d0-b39c-47f5-9199-8ab69991b2ce'
> I0228 18:55:38.509955 2147 containerizer.cpp:1104] Checkpointing executor's forked pid 8479 to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/runs/b17e17d0-b39c-47f5-9199-8ab69991b2ce/pids/forked.pid'
> I0228 18:55:38.512609 2152 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
> I0228 18:55:38.565299 2152 leveldb.cpp:341] Persisting action (18 bytes) to leveldb took 52.640863ms
> I0228 18:55:38.565444 2152 leveldb.cpp:399] Deleting ~2 keys from leveldb took 85308ns
> I0228 18:55:38.565472 2152 replica.cpp:712] Persisted action at 4
> I0228 18:55:38.565508 2152 replica.cpp:697] Replica learned TRUNCATE action at position 4
> WARNING: Logging before InitGoogleLogging() is written to STDERR
> I0228 18:55:38.717453 8493 process.cpp:991] libprocess is initialized on 172.17.0.3:51860 for 16 cpus
> I0228 18:55:38.718441 8493 logging.cpp:193] Logging to STDERR
> I0228 18:55:38.721381 8493 exec.cpp:143] Version: 0.28.0
> I0228 18:55:38.735302 8515 exec.cpp:193] Executor started at: executor(1)@172.17.0.3:51860 with pid 8493
> I0228 18:55:38.739423 2152 slave.cpp:2643] Got registration for executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 from executor(1)@172.17.0.3:51860
> I0228 18:55:38.740824 2152 slave.cpp:2729] Checkpointing executor pid 'executor(1)@172.17.0.3:51860' to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/runs/b17e17d0-b39c-47f5-9199-8ab69991b2ce/pids/libprocess.pid'
> I0228 18:55:38.743635 8515 exec.cpp:217] Executor registered on slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0
> I0228 18:55:38.743845 2151 slave.cpp:1863] Sending queued task 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' to executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 at executor(1)@172.17.0.3:51860
> I0228 18:55:38.746657 8515 exec.cpp:229] Executor::registered took 382086ns
> Registered executor on ebb7e5710eae
> I0228 18:55:38.752070 8522 exec.cpp:304] Executor asked to run task 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b'
> I0228 18:55:38.752290 8522 exec.cpp:313] Executor::launchTask took 168846ns
> Starting task c8d01c56-9ee0-4936-b0b6-207e5188ea7b
> Forked command at 8524
> sh -c 'sleep 1000'
> I0228 18:55:38.758271 8507 exec.cpp:526] Executor sending status update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.760519 2148 slave.cpp:3002] Handling status update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 from executor(1)@172.17.0.3:51860
> I0228 18:55:38.762673 2151 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.763099 2151 status_update_manager.cpp:497] Creating StatusUpdate stream for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.768440 2151 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.827239 2151 status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 to the slave
> I0228 18:55:38.827796 2137 slave.cpp:3400] Forwarding the update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 to master@172.17.0.3:58779
> I0228 18:55:38.828155 2137 slave.cpp:3294] Status update manager successfully handled status update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.828207 2137 slave.cpp:3310] Sending acknowledgement for status update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 to executor(1)@172.17.0.3:51860
> I0228 18:55:38.828341 2151 master.cpp:4809] Status update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 from slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(307)@172.17.0.3:58779 (ebb7e5710eae)
> I0228 18:55:38.828387 2151 master.cpp:4857] Forwarding status update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.828584 2151 master.cpp:6465] Updating the state of task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (latest state: TASK_RUNNING, status update state: TASK_RUNNING)
> I0228 18:55:38.828795 2151 sched.cpp:981] Scheduler::statusUpdate took 29373ns
> I0228 18:55:38.829053 2151 master.cpp:3967] Processing ACKNOWLEDGE call a4ca595a-4867-4625-ba20-0e8551b748db for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (default) at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779 on slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0
> I0228 18:55:38.829280 8518 exec.cpp:350] Executor received status update acknowledgement a4ca595a-4867-4625-ba20-0e8551b748db for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.829401 2137 status_update_manager.cpp:392] Received status update acknowledgement (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.829613 2137 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_RUNNING (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.915546 2137 slave.cpp:2412] Status update manager successfully handled status update acknowledgement (UUID: a4ca595a-4867-4625-ba20-0e8551b748db) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.916538 2137 slave.cpp:668] Slave terminating
> I0228 18:55:38.917208 2142 master.cpp:1174] Slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(307)@172.17.0.3:58779 (ebb7e5710eae) disconnected
> I0228 18:55:38.917270 2142 master.cpp:2635] Disconnecting slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(307)@172.17.0.3:58779 (ebb7e5710eae)
> I0228 18:55:38.917348 2142 master.cpp:2654] Deactivating slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(307)@172.17.0.3:58779 (ebb7e5710eae)
> I0228 18:55:38.917595 2142 hierarchical.cpp:560] Slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 deactivated
> I0228 18:55:38.924058 2118 containerizer.cpp:149] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W0228 18:55:38.924893 2118 backend.cpp:48] Failed to create 'bind' backend: BindBackend requires root privileges
> I0228 18:55:38.926322 8518 exec.cpp:390] Executor asked to shutdown
> Shutting down
> Sending SIGTERM to process tree at pid 8524
> I0228 18:55:38.926470 8518 exec.cpp:405] Executor::shutdown took 15617ns
> I0228 18:55:38.926626 8518 exec.cpp:87] Scheduling shutdown of the executor in 5secs
> I0228 18:55:38.932049 2137 slave.cpp:193] Slave started on 308)@172.17.0.3:58779
> I0228 18:55:38.932098 2137 slave.cpp:194] Flags at startup: --appc_simple_discovery_uri_prefix="http://" --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_RecoverTerminatedExecutor_rHFO1G/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/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_enable_support="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G"
> I0228 18:55:38.932719 2137 credentials.hpp:83] Loading credential for authentication from '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/credential'
> I0228 18:55:38.932991 2137 slave.cpp:324] Slave using credential for: test-principal
> I0228 18:55:38.933192 2137 resources.cpp:572] Parsing resources as JSON failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> Trying semicolon-delimited string format instead
> I0228 18:55:38.934157 2137 slave.cpp:464] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0228 18:55:38.934257 2137 slave.cpp:472] Slave attributes: [ ]
> I0228 18:55:38.934273 2137 slave.cpp:477] Slave hostname: ebb7e5710eae
> Sent SIGTERM to the following process trees:
> [
> -+- 8524 sh -c sleep 1000
> \--- 8525 sleep 1000
> ]
> I0228 18:55:38.936388 2137 state.cpp:58] Recovering state from '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta'
> I0228 18:55:38.936566 2137 state.cpp:698] No checkpointed resources found at '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/resources/resources.info'
> I0228 18:55:38.946091 2146 fetcher.cpp:81] Clearing fetcher cache
> I0228 18:55:38.946215 2146 slave.cpp:4653] Recovering framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.946326 2146 slave.cpp:5476] Recovering executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.947993 2146 slave.cpp:749] Successfully attached file '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/runs/b17e17d0-b39c-47f5-9199-8ab69991b2ce'
> I0228 18:55:38.948055 2146 status_update_manager.cpp:200] Recovering status update manager
> I0228 18:55:38.948087 2146 status_update_manager.cpp:208] Recovering executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.948166 2146 status_update_manager.cpp:497] Creating StatusUpdate stream for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.948761 2146 status_update_manager.cpp:800] Replaying status update stream for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b
> I0228 18:55:38.949712 2146 containerizer.cpp:407] Recovering containerizer
> I0228 18:55:38.949829 2146 containerizer.cpp:462] Recovering container 'b17e17d0-b39c-47f5-9199-8ab69991b2ce' for executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.953066 2145 provisioner.cpp:245] Provisioner recovery complete
> I0228 18:55:38.954900 2144 slave.cpp:4505] Sending reconnect request to executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 at executor(1)@172.17.0.3:51860
> Command terminated with signal Terminated (pid: 8524)
> I0228 18:55:38.957415 8509 exec.cpp:258] Ignoring reconnect message from slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 because the driver is aborted!
> I0228 18:55:38.958354 8515 exec.cpp:526] Executor sending status update TASK_KILLED (UUID: ccdbbee3-d901-4bfc-8c01-bf3f6bdcfcf2) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:38.969535 2145 hierarchical.cpp:1437] No resources available to allocate!
> I0228 18:55:38.969614 2145 hierarchical.cpp:1532] No inverse offers to send out!
> I0228 18:55:38.969652 2145 hierarchical.cpp:1130] Performed allocation for 1 slaves in 326670ns
> I0228 18:55:38.969918 2145 slave.cpp:2942] Cleaning up un-reregistered executors
> I0228 18:55:38.969954 2145 slave.cpp:2960] Killing un-reregistered executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 at executor(1)@172.17.0.3:51860
> I0228 18:55:38.970160 2145 slave.cpp:4565] Finished recovery
> I0228 18:55:38.970830 2145 slave.cpp:4737] Querying resource estimator for oversubscribable resources
> I0228 18:55:38.971015 2145 containerizer.cpp:1378] Destroying container 'b17e17d0-b39c-47f5-9199-8ab69991b2ce'
> I0228 18:55:38.976845 2148 slave.cpp:796] New master detected at master@172.17.0.3:58779
> I0228 18:55:38.976989 2148 slave.cpp:859] Authenticating with master master@172.17.0.3:58779
> I0228 18:55:38.977010 2148 slave.cpp:864] Using default CRAM-MD5 authenticatee
> I0228 18:55:38.978238 2148 slave.cpp:832] Detecting new master
> I0228 18:55:38.978389 2148 slave.cpp:4751] Received oversubscribable resources from the resource estimator
> I0228 18:55:38.978512 2148 status_update_manager.cpp:174] Pausing sending status updates
> I0228 18:55:38.978659 2148 authenticatee.cpp:121] Creating new client SASL connection
> I0228 18:55:38.979097 2148 master.cpp:5541] Authenticating slave(308)@172.17.0.3:58779
> I0228 18:55:38.980293 2149 authenticator.cpp:413] Starting authentication session for crammd5_authenticatee(676)@172.17.0.3:58779
> I0228 18:55:38.980713 2149 authenticator.cpp:98] Creating new server SASL connection
> I0228 18:55:38.981109 2149 authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> I0228 18:55:38.981139 2149 authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0228 18:55:38.981256 2149 authenticator.cpp:203] Received SASL authentication start
> I0228 18:55:38.981314 2149 authenticator.cpp:325] Authentication requires more steps
> I0228 18:55:38.981406 2149 authenticatee.cpp:258] Received SASL authentication step
> I0228 18:55:38.981506 2149 authenticator.cpp:231] Received SASL authentication step
> I0228 18:55:38.981539 2149 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ebb7e5710eae' server FQDN: 'ebb7e5710eae' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0228 18:55:38.981552 2149 auxprop.cpp:179] Looking up auxiliary property '*userPassword'
> I0228 18:55:38.981605 2149 auxprop.cpp:179] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0228 18:55:38.981637 2149 auxprop.cpp:107] Request to lookup properties for user: 'test-principal' realm: 'ebb7e5710eae' server FQDN: 'ebb7e5710eae' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0228 18:55:38.981650 2149 auxprop.cpp:129] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0228 18:55:38.981659 2149 auxprop.cpp:129] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0228 18:55:38.981678 2149 authenticator.cpp:317] Authentication success
> I0228 18:55:38.981853 2149 authenticatee.cpp:298] Authentication success
> I0228 18:55:38.981956 2149 master.cpp:5571] Successfully authenticated principal 'test-principal' at slave(308)@172.17.0.3:58779
> I0228 18:55:38.982041 2149 authenticator.cpp:431] Authentication session cleanup for crammd5_authenticatee(676)@172.17.0.3:58779
> I0228 18:55:38.982636 2143 slave.cpp:927] Successfully authenticated with master master@172.17.0.3:58779
> I0228 18:55:38.983650 2143 slave.cpp:1321] Will retry registration in 16.297049ms if necessary
> I0228 18:55:38.983955 2149 master.cpp:4415] Re-registering slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(307)@172.17.0.3:58779 (ebb7e5710eae)
> I0228 18:55:38.984370 2143 slave.cpp:1071] Re-registered with master master@172.17.0.3:58779
> I0228 18:55:38.984467 2143 slave.cpp:1107] Forwarding total oversubscribed resources
> I0228 18:55:38.984486 2149 master.cpp:4602] Sending updated checkpointed resources to slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(308)@172.17.0.3:58779 (ebb7e5710eae)
> I0228 18:55:38.984675 2150 hierarchical.cpp:548] Slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 reactivated
> I0228 18:55:38.984678 2143 slave.cpp:2248] Updating framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 pid to scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779
> I0228 18:55:38.984750 2143 slave.cpp:2264] Checkpointing framework pid 'scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779' to '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/framework.pid'
> I0228 18:55:38.984777 2151 status_update_manager.cpp:181] Resuming sending status updates
> I0228 18:55:38.985026 2149 master.cpp:4664] Received update of slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(308)@172.17.0.3:58779 (ebb7e5710eae) with total oversubscribed resources
> I0228 18:55:38.985646 2149 hierarchical.cpp:531] Slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 (ebb7e5710eae) updated with oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
> I0228 18:55:38.985857 2149 hierarchical.cpp:1437] No resources available to allocate!
> I0228 18:55:38.985911 2149 hierarchical.cpp:1532] No inverse offers to send out!
> I0228 18:55:38.985941 2149 hierarchical.cpp:1150] Performed allocation for slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 in 238847ns
> I0228 18:55:39.001564 2143 slave.cpp:2341] Updated checkpointed resources from to
> I0228 18:55:39.001654 2143 status_update_manager.cpp:181] Resuming sending status updates
> I0228 18:55:39.010548 2143 hierarchical.cpp:1437] No resources available to allocate!
> I0228 18:55:39.010625 2143 hierarchical.cpp:1532] No inverse offers to send out!
> I0228 18:55:39.010671 2143 hierarchical.cpp:1130] Performed allocation for 1 slaves in 342632ns
> I0228 18:55:39.010896 2143 containerizer.cpp:1594] Executor for container 'b17e17d0-b39c-47f5-9199-8ab69991b2ce' has exited
> I0228 18:55:39.013821 2141 provisioner.cpp:306] Ignoring destroy request for unknown container b17e17d0-b39c-47f5-9199-8ab69991b2ce
> I0228 18:55:39.014214 2147 slave.cpp:3886] Executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 terminated with signal Killed
> I0228 18:55:39.014413 2147 slave.cpp:3002] Handling status update TASK_LOST (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 from @0.0.0.0:0
> I0228 18:55:39.015018 2141 slave.cpp:5677] Terminating task c8d01c56-9ee0-4936-b0b6-207e5188ea7b
> W0228 18:55:39.015465 2147 containerizer.cpp:1220] Ignoring update for unknown container: b17e17d0-b39c-47f5-9199-8ab69991b2ce
> I0228 18:55:39.015846 2149 status_update_manager.cpp:320] Received status update TASK_LOST (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.015918 2149 status_update_manager.cpp:824] Checkpointing UPDATE for status update TASK_LOST (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.093351 2149 status_update_manager.cpp:374] Forwarding update TASK_LOST (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 to the slave
> I0228 18:55:39.093796 2147 slave.cpp:3400] Forwarding the update TASK_LOST (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 to master@172.17.0.3:58779
> I0228 18:55:39.094002 2147 slave.cpp:3294] Status update manager successfully handled status update TASK_LOST (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.094364 2147 master.cpp:4809] Status update TASK_LOST (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 from slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(308)@172.17.0.3:58779 (ebb7e5710eae)
> I0228 18:55:39.094409 2147 master.cpp:4857] Forwarding status update TASK_LOST (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.094568 2147 master.cpp:6465] Updating the state of task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (latest state: TASK_LOST, status update state: TASK_LOST)
> I0228 18:55:39.095481 2147 sched.cpp:981] Scheduler::statusUpdate took 63297ns
> I0228 18:55:39.096104 2147 hierarchical.cpp:890] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 from framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.096654 2144 master.cpp:3967] Processing ACKNOWLEDGE call 42cbd18d-2403-460c-ba56-b4abcce76970 for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (default) at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779 on slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0
> I0228 18:55:39.096804 2144 master.cpp:6531] Removing task c8d01c56-9ee0-4936-b0b6-207e5188ea7b with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 on slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 at slave(308)@172.17.0.3:58779 (ebb7e5710eae)
> I0228 18:55:39.097435 2138 status_update_manager.cpp:392] Received status update acknowledgement (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.097587 2138 status_update_manager.cpp:824] Checkpointing ACK for status update TASK_LOST (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.144846 2138 status_update_manager.cpp:528] Cleaning up status update stream for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.145447 2144 slave.cpp:2412] Status update manager successfully handled status update acknowledgement (UUID: 42cbd18d-2403-460c-ba56-b4abcce76970) for task c8d01c56-9ee0-4936-b0b6-207e5188ea7b of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.145524 2144 slave.cpp:5718] Completing task c8d01c56-9ee0-4936-b0b6-207e5188ea7b
> I0228 18:55:39.145582 2144 slave.cpp:3990] Cleaning up executor 'c8d01c56-9ee0-4936-b0b6-207e5188ea7b' of framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 at executor(1)@172.17.0.3:51860
> I0228 18:55:39.146116 2150 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/runs/b17e17d0-b39c-47f5-9199-8ab69991b2ce' for gc 1.00000010852698weeks in the future
> I0228 18:55:39.146311 2150 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b' for gc 1.00000010852698weeks in the future
> I0228 18:55:39.146446 2150 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b/runs/b17e17d0-b39c-47f5-9199-8ab69991b2ce' for gc 1.00000010852698weeks in the future
> I0228 18:55:39.146652 2144 slave.cpp:4078] Cleaning up framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.146649 2147 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000/executors/c8d01c56-9ee0-4936-b0b6-207e5188ea7b' for gc 1.00000010852698weeks in the future
> I0228 18:55:39.146769 2147 status_update_manager.cpp:282] Closing status update streams for framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.146868 2141 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000' for gc 1.00000010852698weeks in the future
> I0228 18:55:39.146953 2141 gc.cpp:54] Scheduling '/tmp/SlaveRecoveryTest_0_RecoverTerminatedExecutor_rHFO1G/meta/slaves/8cb42f1a-ab2c-4063-8e86-859f724f606b-S0/frameworks/8cb42f1a-ab2c-4063-8e86-859f724f606b-0000' for gc 1.00000010852698weeks in the future
> I0228 18:55:39.169520 2149 hierarchical.cpp:1532] No inverse offers to send out!
> I0228 18:55:39.169739 2149 hierarchical.cpp:1130] Performed allocation for 1 slaves in 1.324616ms
> I0228 18:55:39.170438 2149 master.cpp:5370] Sending 1 offers to framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (default) at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779
> I0228 18:55:39.171244 2147 sched.cpp:873] Scheduler::resourceOffers took 121098ns
> I0228 18:55:39.188771 2118 sched.cpp:1903] Asked to stop the driver
> I0228 18:55:39.189337 2144 sched.cpp:1143] Stopping framework '8cb42f1a-ab2c-4063-8e86-859f724f606b-0000'
> I0228 18:55:39.189926 2144 master.cpp:5941] Processing TEARDOWN call for framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (default) at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779
> I0228 18:55:39.189965 2144 master.cpp:5953] Removing framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 (default) at scheduler-d293eae5-f06f-4ef9-b988-fba8d18815a2@172.17.0.3:58779
> I0228 18:55:39.191135 2144 hierarchical.cpp:375] Deactivated framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.191373 2118 master.cpp:1027] Master terminating
> I0228 18:55:39.191716 2144 hierarchical.cpp:890] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0 from framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.191902 2144 hierarchical.cpp:326] Removed framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.192230 2144 hierarchical.cpp:505] Removed slave 8cb42f1a-ab2c-4063-8e86-859f724f606b-S0
> I0228 18:55:39.192319 2144 slave.cpp:2079] Asked to shut down framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000 by master@172.17.0.3:58779
> W0228 18:55:39.192348 2144 slave.cpp:2094] Cannot shut down unknown framework 8cb42f1a-ab2c-4063-8e86-859f724f606b-0000
> I0228 18:55:39.192380 2144 slave.cpp:3528] master@172.17.0.3:58779 exited
> W0228 18:55:39.192395 2144 slave.cpp:3531] Master disconnected! Waiting for a new master to be elected
> I0228 18:55:39.222730 2143 slave.cpp:668] Slave terminating
> [ OK ] SlaveRecoveryTest/0.RecoverTerminatedExecutor (1431 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)