[
https://issues.apache.org/jira/browse/MESOS-3509?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15099128#comment-15099128
]
Zhitao Li commented on MESOS-3509:
----------------------------------
I'll post some inconclusive findings since my last change seems to made this
test from "flaky" to "failing".
In short, clock/timer implementation in {{libevent}} seems to allow a timer to
be created *out of order* w.r.t to {{Clock::advance()}} in certain cases. As a
result, timer created after Clock advancing code was not affected by that and
instead waiting for a real wall time of 120s
({{slave::REGISTER_RETRY_INTERVAL_MAX * 2}}), which is longer than the default
15s of {{AWAIT_READY}}.
I took a snippet of log to run the test with {{--libevent}} and {{GLOG_v=3}}:
{panel}
I0114 23:25:16.880738 129300 authenticator.cpp:317] Authentication success
I0114 23:25:16.880803 129295 process.cpp:2502] Resuming master@127.0.0.1:31370
at 2016-01-14 23:25:16.878512896+00:00
I0114 23:25:16.880844 129301 process.cpp:2502] Resuming
crammd5_authenticator(1)@127.0.0.1:31370 at 2016-01-14 23:25:16.878512896+00:00
I0114 23:25:16.880861 129295 master.cpp:5475] Successfully authenticated
principal 'test-principal' at slave(1)@127.0.0.1:31370
I0114 23:25:16.880903 129301 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(3)@127.0.0.1:31370
I0114 23:25:16.880873 129298 process.cpp:2502] Resuming
crammd5_authenticatee(3)@127.0.0.1:31370 at 2016-01-14 23:25:16.878512896+00:00
I0114 23:25:16.880975 129301 process.cpp:2800] Donating thread to
crammd5_authenticator_session(3)@127.0.0.1:31370 while waiting
I0114 23:25:16.880991 129298 authenticatee.cpp:298] Authentication success
I0114 23:25:16.881000 129301 process.cpp:2502] Resuming
crammd5_authenticator_session(3)@127.0.0.1:31370 at 2016-01-14
23:25:16.878512896+00:00
I0114 23:25:16.881027 129301 process.cpp:2607] Cleaning up
crammd5_authenticator_session(3)@127.0.0.1:31370
I0114 23:25:16.881069 129298 process.cpp:2502] Resuming
slave(1)@127.0.0.1:31370 at 2016-01-14 23:25:16.878512896+00:00
I0114 23:25:16.881184 129300 process.cpp:2502] Resuming
crammd5_authenticatee(3)@127.0.0.1:31370 at 2016-01-14 23:25:16.878512896+00:00
I0114 23:25:16.881225 129300 process.cpp:2607] Cleaning up
crammd5_authenticatee(3)@127.0.0.1:31370
I0114 23:25:16.881301 129298 slave.cpp:860] Successfully authenticated with
master master@127.0.0.1:31370
I0114 23:25:16.881631 129296 process.cpp:2502] Resuming master@127.0.0.1:31370
at 2016-01-14 23:25:16.878512896+00:00
I0114 23:25:16.881629 129298 slave.cpp:1254] Will retry registration in
2.172151ms if necessary
I0114 23:25:16.881724 129298 clock.cpp:279] Created a timer for
slave(1)@127.0.0.1:31370 in 2.172151ms in the future (2016-01-14
23:25:16.880685047+00:00)
I0114 23:25:16.881906 129296 master.cpp:4314] Re-registering slave
a9a5fba6-3191-424d-a1cf-5d12f35ada17-S0 at slave(1)@127.0.0.1:31370 (localhost)
I0114 23:25:16.882228 129294 process.cpp:2502] Resuming
slave(1)@127.0.0.1:31370 at 2016-01-14 23:25:16.878512896+00:00
I0114 23:25:16.882613 129295 process.cpp:2502] Resuming
slave(1)@127.0.0.1:31370 at 2016-01-14 23:25:16.878512896+00:00
I0114 23:25:16.882622 129296 master.cpp:4502] Sending updated checkpointed
resources to slave a9a5fba6-3191-424d-a1cf-5d12f35ada17-S0 at
slave(1)@127.0.0.1:31370 (localhost)
I0114 23:25:16.882712 129295 pid.cpp:93] Attempting to parse
'scheduler-72698b83-ea69-4f94-ac79-1fe005ba5ea9@127.0.0.1:31370' into a PID
W0114 23:25:16.882750 129295 slave.cpp:2162] Dropping updateFramework message
for a9a5fba6-3191-424d-a1cf-5d12f35ada17-0000 because the slave is in
DISCONNECTED state
I0114 23:25:16.882935 129295 slave.cpp:2277] Updated checkpointed resources
from to
I0114 23:25:16.883074 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:25:16.878512896+00:00
I0114 23:25:16.883116 129302 clock.cpp:197] Clock has settled
I0114 23:25:16.888927 129289 clock.cpp:465] Clock is settled
I0114 23:25:16.889067 129289 clock.cpp:381] Clock advanced (2mins) to 0x20681f0
I0114 23:25:16.889143 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:16.878512896+00:00
I0114 23:25:16.889176 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:16.880685047+00:00
I0114 23:25:16.889196 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:16.882896819+00:00
I0114 23:25:16.889209 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:16.965011968+00:00
I0114 23:25:16.889220 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:17.800440064+00:00
I0114 23:25:16.889231 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:18.572319400+00:00
I0114 23:25:16.889242 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:21.561927936+00:00
I0114 23:25:16.889253 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:21.847002880+00:00
I0114 23:25:16.889263 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:21.847010048+00:00
I0114 23:25:16.889278 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:21.847998976+00:00
I0114 23:25:16.889291 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:21.848186112+00:00
I0114 23:25:16.889300 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:21.866167040+00:00
I0114 23:25:16.889313 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:21.878512896+00:00
I0114 23:25:16.889335 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:26.810558976+00:00
I0114 23:25:16.889349 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:26.877099008+00:00
I0114 23:25:16.889360 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:31.846153984+00:00
I0114 23:25:16.889371 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:31.847229952+00:00
I0114 23:25:16.889382 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:25:31.857804032+00:00
I0114 23:25:16.889394 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:26:16.843522048+00:00
I0114 23:25:16.889405 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:26:16.874211072+00:00
I0114 23:25:16.889420 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:26:31.858716928+00:00
I0114 23:25:16.889433 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:26:41.746949888+00:00
I0114 23:25:16.889492 129302 clock.cpp:435] Clock of slave(1)@127.0.0.1:31370
updated to 2016-01-14 23:25:16.880685047+00:00
I0114 23:25:16.889524 129302 clock.cpp:435] Clock of slave(1)@127.0.0.1:31370
updated to 2016-01-14 23:25:16.882896819+00:00
I0114 23:25:16.889550 129302 clock.cpp:435] Clock of reaper(1)@127.0.0.1:31370
updated to 2016-01-14 23:25:16.965011968+00:00
I0114 23:25:16.889576 129302 clock.cpp:435] Clock of (1)@127.0.0.1:31370
updated to 2016-01-14 23:25:17.800440064+00:00
I0114 23:25:16.889600 129302 clock.cpp:435] Clock of
scheduler-72698b83-ea69-4f94-ac79-1fe005ba5ea9@127.0.0.1:31370 updated to
2016-01-14 23:25:18.572319400+00:00
I0114 23:25:16.889622 129302 clock.cpp:435] Clock of slave(1)@127.0.0.1:31370
updated to 2016-01-14 23:25:21.847002880+00:00
I0114 23:25:16.889639 129302 clock.cpp:435] Clock of
scheduler-72698b83-ea69-4f94-ac79-1fe005ba5ea9@127.0.0.1:31370 updated to
2016-01-14 23:25:21.847010048+00:00
I0114 23:25:16.889655 129302 clock.cpp:435] Clock of master@127.0.0.1:31370
updated to 2016-01-14 23:25:21.847998976+00:00
I0114 23:25:16.889670 129302 clock.cpp:435] Clock of master@127.0.0.1:31370
updated to 2016-01-14 23:25:21.848186112+00:00
I0114 23:25:16.889684 129302 clock.cpp:435] Clock of (1)@127.0.0.1:31370
updated to 2016-01-14 23:25:21.866167040+00:00
I0114 23:25:16.889698 129302 clock.cpp:435] Clock of slave(1)@127.0.0.1:31370
updated to 2016-01-14 23:25:21.878512896+00:00
I0114 23:25:16.889717 129302 clock.cpp:435] Clock of master@127.0.0.1:31370
updated to 2016-01-14 23:25:21.878512896+00:00
I0114 23:25:16.889734 129302 clock.cpp:435] Clock of (12)@127.0.0.1:31370
updated to 2016-01-14 23:25:26.877099008+00:00
I0114 23:25:16.889750 129302 clock.cpp:435] Clock of slave(1)@127.0.0.1:31370
updated to 2016-01-14 23:25:31.847229952+00:00
I0114 23:25:16.889768 129302 clock.cpp:435] Clock of
slave-observer(1)@127.0.0.1:31370 updated to 2016-01-14 23:25:31.857804032+00:00
I0114 23:25:16.889788 129302 clock.cpp:435] Clock of slave(1)@127.0.0.1:31370
updated to 2016-01-14 23:26:16.843522048+00:00
I0114 23:25:16.889803 129302 clock.cpp:435] Clock of slave(1)@127.0.0.1:31370
updated to 2016-01-14 23:26:16.874211072+00:00
I0114 23:25:16.889818 129302 clock.cpp:435] Clock of slave(1)@127.0.0.1:31370
updated to 2016-01-14 23:26:31.858716928+00:00
I0114 23:25:16.889840 129302 clock.cpp:435] Clock of slave(1)@127.0.0.1:31370
updated to 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.889869 129302 clock.cpp:435] Clock of reaper(1)@127.0.0.1:31370
updated to 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.889911 129302 clock.cpp:435] Clock of (1)@127.0.0.1:31370
updated to 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.889961 129295 process.cpp:2502] Resuming (1)@127.0.0.1:31370 at
2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.889979 129302 clock.cpp:435] Clock of
scheduler-72698b83-ea69-4f94-ac79-1fe005ba5ea9@127.0.0.1:31370 updated to
2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890038 129302 process.cpp:2459] Dropping event for process
__waiter__(1)@127.0.0.1:31370
I0114 23:25:16.890038 129300 process.cpp:2502] Resuming
scheduler-72698b83-ea69-4f94-ac79-1fe005ba5ea9@127.0.0.1:31370 at 2016-01-14
23:27:16.878512896+00:00
I0114 23:25:16.890151 129301 process.cpp:2502] Resuming
scheduler-72698b83-ea69-4f94-ac79-1fe005ba5ea9@127.0.0.1:31370 at 2016-01-14
23:27:16.878512896+00:00
I0114 23:25:16.890157 129302 clock.cpp:435] Clock of master@127.0.0.1:31370
updated to 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890240 129299 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890247 129297 process.cpp:2502] Resuming
slave(1)@127.0.0.1:31370 at 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890326 129299 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:16.978512896+00:00)
I0114 23:25:16.890338 129297 slave.cpp:643] Slave asked to shut down by
master@127.0.0.1:31370
I0114 23:25:16.890390 129299 process.cpp:2502] Resuming master@127.0.0.1:31370
at 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890447 129297 slave.cpp:2012] Asked to shut down framework
a9a5fba6-3191-424d-a1cf-5d12f35ada17-0000 by master@127.0.0.1:31370
I0114 23:25:16.890486 129297 slave.cpp:2037] Shutting down framework
a9a5fba6-3191-424d-a1cf-5d12f35ada17-0000
I0114 23:25:16.890527 129295 hierarchical.cpp:1302] Allocating cpus(*):1;
mem(*):960; disk(*):1024; ports(*):[31000-32000] on slave
a9a5fba6-3191-424d-a1cf-5d12f35ada17-S0 to framework
a9a5fba6-3191-424d-a1cf-5d12f35ada17-0000
I0114 23:25:16.890581 129302 clock.cpp:435] Clock of (12)@127.0.0.1:31370
updated to 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890629 129297 slave.cpp:4062] Shutting down executor 'default'
of framework a9a5fba6-3191-424d-a1cf-5d12f35ada17-0000 at
executor(1)@127.0.0.1:31370
I0114 23:25:16.890657 129300 process.cpp:2502] Resuming (12)@127.0.0.1:31370 at
2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890640 129302 process.cpp:2459] Dropping event for process
__waiter__(3)@127.0.0.1:31370
I0114 23:25:16.890688 129297 clock.cpp:435] Clock of
executor(1)@127.0.0.1:31370 updated to 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890764 129299 process.cpp:2502] Resuming
executor(1)@127.0.0.1:31370 at 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890807 129297 clock.cpp:279] Created a timer for
slave(1)@127.0.0.1:31370 in 2mins in the future (2016-01-14
23:29:16.878512896+00:00)
I0114 23:25:16.890839 129302 clock.cpp:435] Clock of
slave-observer(1)@127.0.0.1:31370 updated to 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890872 129295 hierarchical.cpp:1423] No inverse offers to send
out!
I0114 23:25:16.890954 129301 process.cpp:2502] Resuming master@127.0.0.1:31370
at 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.890970 129295 hierarchical.cpp:1079] Performed allocation for 1
slaves in 951514ns
I0114 23:25:16.891015 129302 process.cpp:2459] Dropping event for process
__waiter__(2)@127.0.0.1:31370
I0114 23:25:16.891034 129295 clock.cpp:279] Created a timer for
(1)@127.0.0.1:31370 in 1secs in the future (2016-01-14 23:27:17.878512896+00:00)
I0114 23:25:16.891047 129302 clock.cpp:197] Clock has settled
I0114 23:25:16.890995 129300 process.cpp:2502] Resuming
slave-observer(1)@127.0.0.1:31370 at 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.891175 129300 clock.cpp:279] Created a timer for
slave-observer(1)@127.0.0.1:31370 in 15secs in the future (2016-01-14
23:27:31.878512896+00:00)
I0114 23:25:16.891261 129301 master.cpp:5274] Sending 1 offers to framework
a9a5fba6-3191-424d-a1cf-5d12f35ada17-0000 (default) at
scheduler-72698b83-ea69-4f94-ac79-1fe005ba5ea9@127.0.0.1:31370
I0114 23:25:16.891410 129300 process.cpp:2502] Resuming
scheduler-72698b83-ea69-4f94-ac79-1fe005ba5ea9@127.0.0.1:31370 at 2016-01-14
23:27:16.878512896+00:00
I0114 23:25:16.891501 129297 slave.cpp:1125] Skipping registration because
slave is terminating
I0114 23:25:16.891551 129297 slave.cpp:1125] Skipping registration because
slave is terminating
I0114 23:25:16.891572 129300 pid.cpp:93] Attempting to parse
'master@127.0.0.1:31370' into a PID
I0114 23:25:16.891604 129300 sched.cpp:795] Received 1 offers
I0114 23:25:16.891623 129297 slave.cpp:4601] Querying resource estimator for
oversubscribable resources
I0114 23:25:16.891635 129300 pid.cpp:93] Attempting to parse
'slave(1)@127.0.0.1:31370' into a PID
I0114 23:25:16.891669 129300 sched.cpp:805] Saving PID
'slave(1)@127.0.0.1:31370'
I0114 23:25:16.891683 129297 clock.cpp:435] Clock of (13)@127.0.0.1:31370
updated to 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.891736 129300 sched.cpp:819] Scheduler::resourceOffers took
15034ns
I0114 23:25:16.891798 129300 process.cpp:2502] Resuming (13)@127.0.0.1:31370 at
2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.891907 129297 slave.cpp:4157] Ignoring registration timeout for
executor 'default' because the framework
a9a5fba6-3191-424d-a1cf-5d12f35ada17-0000 is terminating
I0114 23:25:16.891988 129297 slave.cpp:3407] No pings from master received
within 75secs
I0114 23:25:16.892041 129297 slave.cpp:3371] Received ping from
slave-observer(1)@127.0.0.1:31370
I0114 23:25:16.892079 129297 clock.cpp:279] Created a timer for
slave(1)@127.0.0.1:31370 in 75secs in the future (2016-01-14
23:28:31.878512896+00:00)
I0114 23:25:16.892169 129301 process.cpp:2502] Resuming
slave-observer(1)@127.0.0.1:31370 at 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.892174 129297 slave.cpp:4238] Current disk usage 28.78%. Max
allowed age: 4.285739606220718days
I0114 23:25:16.892249 129297 clock.cpp:435] Clock of (11)@127.0.0.1:31370
updated to 2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.892308 129297 clock.cpp:279] Created a timer for
slave(1)@127.0.0.1:31370 in 1mins in the future (2016-01-14
23:28:16.878512896+00:00)
I0114 23:25:16.892303 129298 process.cpp:2502] Resuming (11)@127.0.0.1:31370 at
2016-01-14 23:27:16.878512896+00:00
I0114 23:25:16.892375 129297 slave.cpp:4615] Received oversubscribable
resources from the resource estimator
I0114 23:25:16.892424 129297 clock.cpp:279] Created a timer for
slave(1)@127.0.0.1:31370 in 15secs in the future (2016-01-14
23:27:31.878512896+00:00)
I0114 23:25:16.899250 129289 clock.cpp:465] Clock is settled
I0114 23:25:16.899281 129289 clock.cpp:361] Clock resumed at 0x20681f0
I0114 23:25:16.899389 129289 process.cpp:2492] Spawned process
__latch__(11)@127.0.0.1:31370
I0114 23:25:16.899410 129294 process.cpp:2502] Resuming __gc__@127.0.0.1:31370
at 2016-01-14 23:27:16.899399936+00:00
I0114 23:25:16.899416 129295 process.cpp:2502] Resuming
__latch__(11)@127.0.0.1:31370 at 2016-01-14 23:27:16.899409920+00:00
I0114 23:25:16.899461 129289 process.cpp:2492] Spawned process
__waiter__(4)@127.0.0.1:31370
I0114 23:25:16.899464 129295 process.cpp:2502] Resuming
__waiter__(4)@127.0.0.1:31370 at 2016-01-14 23:27:16.899459072+00:00
I0114 23:25:16.899516 129295 process.cpp:3372] Running waiter process for
__latch__(11)@127.0.0.1:31370
I0114 23:25:16.899591 129295 clock.cpp:279] Created a timer for
__waiter__(4)@127.0.0.1:31370 in 2mins in the future (2016-01-14
23:29:16.899578880+00:00)
I0114 23:25:16.979509 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:16.979500032+00:00
I0114 23:25:16.979542 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:16.978512896+00:00
I0114 23:25:16.979636 129300 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:16.979628032+00:00
I0114 23:25:16.979722 129300 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:17.079695104+00:00)
I0114 23:25:17.079978 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:17.079970048+00:00
I0114 23:25:17.080010 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:17.079695104+00:00
I0114 23:25:17.080107 129296 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:17.080089088+00:00
I0114 23:25:17.080185 129296 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:17.180174080+00:00)
I0114 23:25:17.180435 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:17.180428032+00:00
I0114 23:25:17.180455 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:17.180174080+00:00
I0114 23:25:17.180527 129294 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:17.180517888+00:00
I0114 23:25:17.180594 129294 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:17.280582912+00:00)
I0114 23:25:17.280858 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:17.280848896+00:00
I0114 23:25:17.280877 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:17.280582912+00:00
I0114 23:25:17.280952 129298 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:17.280943104+00:00
I0114 23:25:17.281026 129298 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:17.381010944+00:00)
I0114 23:25:17.381288 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:17.381277952+00:00
I0114 23:25:17.381310 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:17.381010944+00:00
I0114 23:25:17.381389 129301 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:17.381379072+00:00
I0114 23:25:17.381469 129301 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:17.481444096+00:00)
I0114 23:25:17.481712 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:17.481701888+00:00
I0114 23:25:17.481737 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:17.481444096+00:00
I0114 23:25:17.481827 129299 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:17.481814016+00:00
I0114 23:25:17.481910 129299 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:17.581893120+00:00)
I0114 23:25:17.582175 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:17.582166016+00:00
I0114 23:25:17.582195 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:17.581893120+00:00
I0114 23:25:17.582267 129295 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:17.582257920+00:00
I0114 23:25:17.582345 129295 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:17.682319104+00:00)
I0114 23:25:17.682580 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:17.682572032+00:00
I0114 23:25:17.682602 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:17.682319104+00:00
I0114 23:25:17.682680 129300 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:17.682669056+00:00
I0114 23:25:17.682754 129300 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:17.782738944+00:00)
I0114 23:25:17.783025 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:17.783015936+00:00
I0114 23:25:17.783044 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:17.782738944+00:00
I0114 23:25:17.783126 129296 process.cpp:2502] Resuming
reaper(1)@127.0.0.1:31370 at 2016-01-14 23:27:17.783115008+00:00
I0114 23:25:17.783179 129296 clock.cpp:279] Created a timer for
reaper(1)@127.0.0.1:31370 in 100ms in the future (2016-01-14
23:27:17.883169024+00:00)
I0114 23:25:17.879277 129302 clock.cpp:152] Handling timers up to 2016-01-14
23:27:17.879269888+00:00
I0114 23:25:17.879297 129302 clock.cpp:159] Have timeout(s) at 2016-01-14
23:27:17.878512896+00:00
I0114 23:25:17.879389 129296 process.cpp:2502] Resuming (1)@127.0.0.1:31370 at
2016-01-14 23:27:17.879379968+00:00
I0114 23:25:17.879603 129296 hierarchical.cpp:1329] No resources available to
allocate!
I0114 23:25:17.879639 129296 hierarchical.cpp:1423] No inverse offers to send
out!
I0114 23:25:17.879658 129296 hierarchical.cpp:1079] Performed allocation for 1
slaves in 231805ns
{panel}
As you can see, the {{Clock advanced (2mins) }} line happened before {{Created
a timer for slave(1)@127.0.0.1:31370 in 2mins}} line.
I guess it's probably more productive to loop in author of libevent here?
> SlaveTest.TerminatingSlaveDoesNotReregister is flaky
> ----------------------------------------------------
>
> Key: MESOS-3509
> URL: https://issues.apache.org/jira/browse/MESOS-3509
> Project: Mesos
> Issue Type: Bug
> Affects Versions: 0.25.0
> Reporter: Jie Yu
> Assignee: Liqiang Lin
>
> Observed on Apache CI
> {noformat}
> [ RUN ] SlaveTest.TerminatingSlaveDoesNotReregister
> Using temporary directory
> '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_PiT5jn'
> I0924 04:54:06.645386 29977 leveldb.cpp:176] Opened db in 112.347533ms
> I0924 04:54:06.665618 29977 leveldb.cpp:183] Compacted db in 20.158157ms
> I0924 04:54:06.665704 29977 leveldb.cpp:198] Created db iterator in 24721ns
> I0924 04:54:06.665727 29977 leveldb.cpp:204] Seeked to beginning of db in
> 3125ns
> I0924 04:54:06.665741 29977 leveldb.cpp:273] Iterated through 0 keys in the
> db in 256ns
> I0924 04:54:06.665799 29977 replica.cpp:744] Replica recovered with log
> positions 0 -> 0 with 1 holes and 0 unlearned
> I0924 04:54:06.666378 30000 recover.cpp:449] Starting replica recovery
> I0924 04:54:06.666831 30000 recover.cpp:475] Replica is in EMPTY status
> I0924 04:54:06.667945 30008 replica.cpp:641] Replica in EMPTY status received
> a broadcasted recover request
> I0924 04:54:06.668473 30005 recover.cpp:195] Received a recover response from
> a replica in EMPTY status
> I0924 04:54:06.669003 30007 recover.cpp:566] Updating replica status to
> STARTING
> I0924 04:54:06.669154 30000 master.cpp:370] Master
> bd006350-cdbf-414f-9eef-25f03ccdc5fb (7c9c99874a2d) started on
> 172.17.1.154:55676
> I0924 04:54:06.669347 30000 master.cpp:372] Flags at startup: --acls=""
> --allocation_interval="1secs" --allocator="HierarchicalDRF"
> --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5"
> --authorizers="local"
> --credentials="/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_PiT5jn/credentials"
> --framework_sorter="drf" --help="false" --initialize_driver_logging="true"
> --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO"
> --max_slave_ping_timeouts="5" --quiet="false"
> --recovery_slave_removal_limit="100%" --registry="replicated_log"
> --registry_fetch_timeout="1mins" --registry_store_timeout="25secs"
> --registry_strict="true" --root_submissions="true"
> --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins"
> --user_sorter="drf" --version="false"
> --webui_dir="/mesos/mesos-0.25.0/_inst/share/mesos/webui"
> --work_dir="/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_PiT5jn/master"
> --zk_session_timeout="10secs"
> I0924 04:54:06.669595 30000 master.cpp:417] Master only allowing
> authenticated frameworks to register
> I0924 04:54:06.669605 30000 master.cpp:422] Master only allowing
> authenticated slaves to register
> I0924 04:54:06.669613 30000 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_PiT5jn/credentials'
> I0924 04:54:06.669874 30000 master.cpp:461] Using default 'crammd5'
> authenticator
> I0924 04:54:06.670027 30000 master.cpp:498] Authorization enabled
> I0924 04:54:06.670264 30005 hierarchical.hpp:468] Initialized hierarchical
> allocator process
> I0924 04:54:06.670320 30005 whitelist_watcher.cpp:79] No whitelist given
> I0924 04:54:06.671406 29999 master.cpp:1597] The newly elected leader is
> master@172.17.1.154:55676 with id bd006350-cdbf-414f-9eef-25f03ccdc5fb
> I0924 04:54:06.671438 29999 master.cpp:1610] Elected as the leading master!
> I0924 04:54:06.671461 29999 master.cpp:1370] Recovering from registrar
> I0924 04:54:06.671612 30011 registrar.cpp:309] Recovering registrar
> I0924 04:54:06.704048 30002 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 34.707125ms
> I0924 04:54:06.704123 30002 replica.cpp:323] Persisted replica status to
> STARTING
> I0924 04:54:06.704504 29997 recover.cpp:475] Replica is in STARTING status
> I0924 04:54:06.705658 30002 replica.cpp:641] Replica in STARTING status
> received a broadcasted recover request
> I0924 04:54:06.706466 30007 recover.cpp:195] Received a recover response from
> a replica in STARTING status
> I0924 04:54:06.707064 30004 recover.cpp:566] Updating replica status to VOTING
> I0924 04:54:06.737488 30004 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 30.261425ms
> I0924 04:54:06.737560 30004 replica.cpp:323] Persisted replica status to
> VOTING
> I0924 04:54:06.737746 30004 recover.cpp:580] Successfully joined the Paxos
> group
> I0924 04:54:06.737932 30004 recover.cpp:464] Recover process terminated
> I0924 04:54:06.738535 30009 log.cpp:661] Attempting to start the writer
> I0924 04:54:06.739835 30001 replica.cpp:477] Replica received implicit
> promise request with proposal 1
> I0924 04:54:06.770998 30001 leveldb.cpp:306] Persisting metadata (8 bytes) to
> leveldb took 31.093864ms
> I0924 04:54:06.771077 30001 replica.cpp:345] Persisted promised to 1
> I0924 04:54:06.771845 30002 coordinator.cpp:231] Coordinator attemping to
> fill missing position
> I0924 04:54:06.773066 30002 replica.cpp:378] Replica received explicit
> promise request for position 0 with proposal 2
> I0924 04:54:06.804437 30002 leveldb.cpp:343] Persisting action (8 bytes) to
> leveldb took 31.314548ms
> I0924 04:54:06.804520 30002 replica.cpp:679] Persisted action at 0
> I0924 04:54:06.805915 30002 replica.cpp:511] Replica received write request
> for position 0
> I0924 04:54:06.806094 30002 leveldb.cpp:438] Reading position from leveldb
> took 45268ns
> I0924 04:54:06.837913 30002 leveldb.cpp:343] Persisting action (14 bytes) to
> leveldb took 31.745501ms
> I0924 04:54:06.838006 30002 replica.cpp:679] Persisted action at 0
> I0924 04:54:06.838798 30002 replica.cpp:658] Replica received learned notice
> for position 0
> I0924 04:54:06.871426 30002 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 32.585604ms
> I0924 04:54:06.871502 30002 replica.cpp:679] Persisted action at 0
> I0924 04:54:06.871536 30002 replica.cpp:664] Replica learned NOP action at
> position 0
> I0924 04:54:06.872514 30006 log.cpp:677] Writer started with ending position 0
> I0924 04:54:06.873711 30006 leveldb.cpp:438] Reading position from leveldb
> took 48006ns
> I0924 04:54:06.874902 30004 registrar.cpp:342] Successfully fetched the
> registry (0B) in 203136us
> I0924 04:54:06.875100 30004 registrar.cpp:441] Applied 1 operations in
> 34506ns; attempting to update the 'registry'
> I0924 04:54:06.876008 29999 log.cpp:685] Attempting to append 176 bytes to
> the log
> I0924 04:54:06.876159 30006 coordinator.cpp:341] Coordinator attempting to
> write APPEND action at position 1
> I0924 04:54:06.877343 29996 replica.cpp:511] Replica received write request
> for position 1
> I0924 04:54:06.913260 29996 leveldb.cpp:343] Persisting action (195 bytes) to
> leveldb took 35.865668ms
> I0924 04:54:06.913338 29996 replica.cpp:679] Persisted action at 1
> I0924 04:54:06.914463 29996 replica.cpp:658] Replica received learned notice
> for position 1
> I0924 04:54:06.941951 29996 leveldb.cpp:343] Persisting action (197 bytes) to
> leveldb took 27.224493ms
> I0924 04:54:06.942047 29996 replica.cpp:679] Persisted action at 1
> I0924 04:54:06.942083 29996 replica.cpp:664] Replica learned APPEND action at
> position 1
> I0924 04:54:06.943408 30005 registrar.cpp:486] Successfully updated the
> 'registry' in 68.169984ms
> I0924 04:54:06.943563 30005 registrar.cpp:372] Successfully recovered
> registrar
> I0924 04:54:06.944015 29998 log.cpp:704] Attempting to truncate the log to 1
> I0924 04:54:06.944458 29997 coordinator.cpp:341] Coordinator attempting to
> write TRUNCATE action at position 2
> I0924 04:54:06.944510 29996 master.cpp:1407] Recovered 0 slaves from the
> Registry (137B) ; allowing 10mins for slaves to re-register
> I0924 04:54:06.945586 30001 replica.cpp:511] Replica received write request
> for position 2
> I0924 04:54:06.967072 30001 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 21.44102ms
> I0924 04:54:06.967136 30001 replica.cpp:679] Persisted action at 2
> I0924 04:54:06.968070 30001 replica.cpp:658] Replica received learned notice
> for position 2
> I0924 04:54:06.992204 30001 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 24.095375ms
> I0924 04:54:06.992321 30001 leveldb.cpp:401] Deleting ~1 keys from leveldb
> took 55868ns
> I0924 04:54:06.992532 30001 replica.cpp:679] Persisted action at 2
> I0924 04:54:06.992811 30001 replica.cpp:664] Replica learned TRUNCATE action
> at position 2
> I0924 04:54:07.000255 30008 slave.cpp:190] Slave started on
> 299)@172.17.1.154:55676
> I0924 04:54:07.000752 30008 slave.cpp:191] Flags at startup:
> --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5"
> --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false"
> --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false"
> --cgroups_root="mesos" --container_disk_watch_interval="15secs"
> --containerizers="mesos"
> --credential="/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_yCbi9q/credential"
> --default_role="*" --disk_watch_interval="1mins" --docker="docker"
> --docker_kill_orphans="true" --docker_remove_delay="6hrs"
> --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="2mins"
> --fetcher_cache_dir="/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_yCbi9q/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --image_provisioner_backend="copy" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mesos/mesos-0.25.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"
> --resource_monitoring_interval="1secs"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_yCbi9q"
> I0924 04:54:07.001853 30008 credentials.hpp:85] Loading credential for
> authentication from
> '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_yCbi9q/credential'
> I0924 04:54:07.002065 29977 sched.cpp:164] Version: 0.25.0
> I0924 04:54:07.002388 30008 slave.cpp:321] Slave using credential for:
> test-principal
> I0924 04:54:07.003141 30004 sched.cpp:262] New master detected at
> master@172.17.1.154:55676
> I0924 04:54:07.003265 30008 slave.cpp:354] Slave resources: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> I0924 04:54:07.003336 30004 sched.cpp:318] Authenticating with master
> master@172.17.1.154:55676
> I0924 04:54:07.003521 30008 slave.cpp:384] Slave hostname: 7c9c99874a2d
> I0924 04:54:07.003526 30004 sched.cpp:325] Using default CRAM-MD5
> authenticatee
> I0924 04:54:07.003676 30008 slave.cpp:389] Slave checkpoint: true
> I0924 04:54:07.004098 30011 authenticatee.cpp:115] Creating new client SASL
> connection
> I0924 04:54:07.004578 30007 master.cpp:5132] Authenticating
> scheduler-93ec2a16-2413-4c7e-9ed1-2e35279e616a@172.17.1.154:55676
> I0924 04:54:07.004796 30006 authenticator.cpp:407] Starting authentication
> session for crammd5_authenticatee(669)@172.17.1.154:55676
> I0924 04:54:07.004910 30004 state.cpp:54] Recovering state from
> '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_yCbi9q/meta'
> I0924 04:54:07.005316 29997 authenticator.cpp:92] Creating new server SASL
> connection
> I0924 04:54:07.005751 30010 status_update_manager.cpp:202] Recovering status
> update manager
> I0924 04:54:07.005754 29997 authenticatee.cpp:206] Received SASL
> authentication mechanisms: CRAM-MD5
> I0924 04:54:07.005810 29997 authenticatee.cpp:232] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0924 04:54:07.006036 30010 authenticator.cpp:197] Received SASL
> authentication start
> I0924 04:54:07.006132 30010 authenticator.cpp:319] Authentication requires
> more steps
> I0924 04:54:07.006291 30010 authenticatee.cpp:252] Received SASL
> authentication step
> I0924 04:54:07.006407 29997 slave.cpp:4104] Finished recovery
> I0924 04:54:07.006443 30010 authenticator.cpp:225] Received SASL
> authentication step
> I0924 04:54:07.006700 30010 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '7c9c99874a2d' server FQDN: '7c9c99874a2d'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0924 04:54:07.006810 30010 auxprop.cpp:174] Looking up auxiliary property
> '*userPassword'
> I0924 04:54:07.007015 30010 auxprop.cpp:174] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0924 04:54:07.007077 30010 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '7c9c99874a2d' server FQDN: '7c9c99874a2d'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0924 04:54:07.007202 30010 auxprop.cpp:124] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0924 04:54:07.007321 30010 auxprop.cpp:124] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0924 04:54:07.007336 29997 slave.cpp:4261] Querying resource estimator for
> oversubscribable resources
> I0924 04:54:07.007480 30010 authenticator.cpp:311] Authentication success
> I0924 04:54:07.007685 29999 authenticatee.cpp:292] Authentication success
> I0924 04:54:07.007732 30004 master.cpp:5162] Successfully authenticated
> principal 'test-principal' at
> scheduler-93ec2a16-2413-4c7e-9ed1-2e35279e616a@172.17.1.154:55676
> I0924 04:54:07.007818 30010 authenticator.cpp:425] Authentication session
> cleanup for crammd5_authenticatee(669)@172.17.1.154:55676
> I0924 04:54:07.008213 30006 sched.cpp:407] Successfully authenticated with
> master master@172.17.1.154:55676
> I0924 04:54:07.008236 29997 slave.cpp:699] New master detected at
> master@172.17.1.154:55676
> I0924 04:54:07.008430 30006 sched.cpp:714] Sending SUBSCRIBE call to
> master@172.17.1.154:55676
> I0924 04:54:07.008483 29998 status_update_manager.cpp:176] Pausing sending
> status updates
> I0924 04:54:07.008586 29997 slave.cpp:762] Authenticating with master
> master@172.17.1.154:55676
> I0924 04:54:07.008723 29997 slave.cpp:767] Using default CRAM-MD5
> authenticatee
> I0924 04:54:07.008754 30006 sched.cpp:747] Will retry registration in
> 1.626336152secs if necessary
> I0924 04:54:07.008901 29997 slave.cpp:735] Detecting new master
> I0924 04:54:07.008930 30006 master.cpp:2173] Received SUBSCRIBE call for
> framework 'default' at
> scheduler-93ec2a16-2413-4c7e-9ed1-2e35279e616a@172.17.1.154:55676
> I0924 04:54:07.008987 29998 authenticatee.cpp:115] Creating new client SASL
> connection
> I0924 04:54:07.009007 30006 master.cpp:1636] Authorizing framework principal
> 'test-principal' to receive offers for role '*'
> I0924 04:54:07.009068 29997 slave.cpp:4275] Received oversubscribable
> resources from the resource estimator
> I0924 04:54:07.009196 30006 master.cpp:5132] Authenticating
> slave(299)@172.17.1.154:55676
> I0924 04:54:07.009300 29997 authenticator.cpp:407] Starting authentication
> session for crammd5_authenticatee(670)@172.17.1.154:55676
> I0924 04:54:07.009388 30006 master.cpp:2244] Subscribing framework default
> with checkpointing disabled and capabilities [ ]
> I0924 04:54:07.009531 30005 authenticator.cpp:92] Creating new server SASL
> connection
> I0924 04:54:07.009745 29997 authenticatee.cpp:206] Received SASL
> authentication mechanisms: CRAM-MD5
> I0924 04:54:07.009881 29997 authenticatee.cpp:232] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0924 04:54:07.010095 30006 sched.cpp:641] Framework registered with
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.010107 30002 authenticator.cpp:197] Received SASL
> authentication start
> I0924 04:54:07.010146 30006 sched.cpp:655] Scheduler::registered took 21969ns
> I0924 04:54:07.010164 30002 authenticator.cpp:319] Authentication requires
> more steps
> I0924 04:54:07.010167 29998 hierarchical.hpp:515] Added framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.010208 29998 hierarchical.hpp:1326] No resources available to
> allocate!
> I0924 04:54:07.010232 29998 hierarchical.hpp:1421] No inverse offers to send
> out!
> I0924 04:54:07.010251 29998 hierarchical.hpp:1221] Performed allocation for 0
> slaves in 50319ns
> I0924 04:54:07.010268 30002 authenticatee.cpp:252] Received SASL
> authentication step
> I0924 04:54:07.010380 30002 authenticator.cpp:225] Received SASL
> authentication step
> I0924 04:54:07.010416 30002 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '7c9c99874a2d' server FQDN: '7c9c99874a2d'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0924 04:54:07.010434 30002 auxprop.cpp:174] Looking up auxiliary property
> '*userPassword'
> I0924 04:54:07.010474 30002 auxprop.cpp:174] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0924 04:54:07.010514 30002 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '7c9c99874a2d' server FQDN: '7c9c99874a2d'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0924 04:54:07.010532 30002 auxprop.cpp:124] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0924 04:54:07.010545 30002 auxprop.cpp:124] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0924 04:54:07.010566 30002 authenticator.cpp:311] Authentication success
> I0924 04:54:07.010723 29998 authenticatee.cpp:292] Authentication success
> I0924 04:54:07.010924 30006 master.cpp:5162] Successfully authenticated
> principal 'test-principal' at slave(299)@172.17.1.154:55676
> I0924 04:54:07.011070 29998 slave.cpp:830] Successfully authenticated with
> master master@172.17.1.154:55676
> I0924 04:54:07.011245 29998 slave.cpp:1224] Will retry registration in
> 15.453813ms if necessary
> I0924 04:54:07.011473 30009 authenticator.cpp:425] Authentication session
> cleanup for crammd5_authenticatee(670)@172.17.1.154:55676
> I0924 04:54:07.011514 30008 master.cpp:3856] Registering slave at
> slave(299)@172.17.1.154:55676 (7c9c99874a2d) with id
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0
> I0924 04:54:07.012133 30010 registrar.cpp:441] Applied 1 operations in
> 52871ns; attempting to update the 'registry'
> I0924 04:54:07.013129 30004 log.cpp:685] Attempting to append 345 bytes to
> the log
> I0924 04:54:07.013411 29996 coordinator.cpp:341] Coordinator attempting to
> write APPEND action at position 3
> I0924 04:54:07.014320 30009 replica.cpp:511] Replica received write request
> for position 3
> I0924 04:54:07.027837 30007 slave.cpp:1224] Will retry registration in
> 38.842723ms if necessary
> I0924 04:54:07.028054 29996 master.cpp:3844] Ignoring register slave message
> from slave(299)@172.17.1.154:55676 (7c9c99874a2d) as admission is already in
> progress
> I0924 04:54:07.042615 30009 leveldb.cpp:343] Persisting action (364 bytes) to
> leveldb took 28.247365ms
> I0924 04:54:07.042661 30009 replica.cpp:679] Persisted action at 3
> I0924 04:54:07.043460 30003 replica.cpp:658] Replica received learned notice
> for position 3
> I0924 04:54:07.067387 30004 slave.cpp:1224] Will retry registration in
> 78.089263ms if necessary
> I0924 04:54:07.067571 30009 master.cpp:3844] Ignoring register slave message
> from slave(299)@172.17.1.154:55676 (7c9c99874a2d) as admission is already in
> progress
> I0924 04:54:07.067726 30003 leveldb.cpp:343] Persisting action (366 bytes) to
> leveldb took 24.157267ms
> I0924 04:54:07.067771 30003 replica.cpp:679] Persisted action at 3
> I0924 04:54:07.067807 30003 replica.cpp:664] Replica learned APPEND action at
> position 3
> I0924 04:54:07.069293 30009 registrar.cpp:486] Successfully updated the
> 'registry' in 57.085952ms
> I0924 04:54:07.069537 30000 log.cpp:704] Attempting to truncate the log to 3
> I0924 04:54:07.069870 30000 coordinator.cpp:341] Coordinator attempting to
> write TRUNCATE action at position 4
> I0924 04:54:07.070420 30000 hierarchical.hpp:675] Added slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 (7c9c99874a2d) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
> I0924 04:54:07.070986 30000 hierarchical.hpp:1421] No inverse offers to send
> out!
> I0924 04:54:07.071085 30004 replica.cpp:511] Replica received write request
> for position 4
> I0924 04:54:07.071107 30005 slave.cpp:3132] Received ping from
> slave-observer(268)@172.17.1.154:55676
> I0924 04:54:07.071499 30000 hierarchical.hpp:1239] Performed allocation for
> slave bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 in 710571ns
> I0924 04:54:07.071566 30005 slave.cpp:874] Registered with master
> master@172.17.1.154:55676; given slave ID
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0
> I0924 04:54:07.071707 30005 fetcher.cpp:77] Clearing fetcher cache
> I0924 04:54:07.071993 30000 status_update_manager.cpp:183] Resuming sending
> status updates
> I0924 04:54:07.072276 30005 slave.cpp:897] Checkpointing SlaveInfo to
> '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_yCbi9q/meta/slaves/bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0/slave.info'
> I0924 04:54:07.072701 30005 slave.cpp:933] Forwarding total oversubscribed
> resources
> I0924 04:54:07.071038 30011 master.cpp:3924] Registered slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 at slave(299)@172.17.1.154:55676
> (7c9c99874a2d) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000]
> I0924 04:54:07.073376 30011 master.cpp:4961] Sending 1 offers to framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 (default) at
> scheduler-93ec2a16-2413-4c7e-9ed1-2e35279e616a@172.17.1.154:55676
> I0924 04:54:07.073616 30011 master.cpp:4266] Received update of slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 at slave(299)@172.17.1.154:55676
> (7c9c99874a2d) with total oversubscribed resources
> I0924 04:54:07.074031 30011 hierarchical.hpp:735] Slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 (7c9c99874a2d) updated with
> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000])
> I0924 04:54:07.074501 30011 hierarchical.hpp:1326] No resources available to
> allocate!
> I0924 04:54:07.074534 30011 hierarchical.hpp:1421] No inverse offers to send
> out!
> I0924 04:54:07.074550 30011 hierarchical.hpp:1239] Performed allocation for
> slave bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 in 464700ns
> I0924 04:54:07.074717 29998 sched.cpp:811] Scheduler::resourceOffers took
> 833347ns
> I0924 04:54:07.075932 30001 master.cpp:2912] Processing ACCEPT call for
> offers: [ bd006350-cdbf-414f-9eef-25f03ccdc5fb-O0 ] on slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 at slave(299)@172.17.1.154:55676
> (7c9c99874a2d) for framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> (default) at scheduler-93ec2a16-2413-4c7e-9ed1-2e35279e616a@172.17.1.154:55676
> I0924 04:54:07.076009 30001 master.cpp:2708] Authorizing framework principal
> 'test-principal' to launch task 0 as user 'mesos'
> W0924 04:54:07.077509 30001 validation.cpp:422] Executor default for task 0
> uses less CPUs (None) than the minimum required (0.01). Please update your
> executor, as this will be mandatory in future releases.
> W0924 04:54:07.077560 30001 validation.cpp:434] Executor default for task 0
> uses less memory (None) than the minimum required (32MB). Please update your
> executor, as this will be mandatory in future releases.
> I0924 04:54:07.077864 30001 master.hpp:176] Adding task 0 with resources
> cpus(*):1; mem(*):64 on slave bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0
> (7c9c99874a2d)
> I0924 04:54:07.078027 30001 master.cpp:3242] Launching task 0 of framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 (default) at
> scheduler-93ec2a16-2413-4c7e-9ed1-2e35279e616a@172.17.1.154:55676 with
> resources cpus(*):1; mem(*):64 on slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 at slave(299)@172.17.1.154:55676
> (7c9c99874a2d)
> I0924 04:54:07.078366 30002 slave.cpp:1264] Got assigned task 0 for framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.078779 30001 hierarchical.hpp:1103] Recovered cpus(*):1;
> mem(*):960; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):1;
> mem(*):64) on slave bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 from framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.078855 30001 hierarchical.hpp:1140] Framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 filtered slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 for 5secs
> I0924 04:54:07.078819 30002 slave.cpp:1380] Launching task 0 for framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.090544 30002 slave.cpp:4846] Launching executor default of
> framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 with resources in work
> directory
> '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_yCbi9q/slaves/bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0/frameworks/bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000/executors/default/runs/53b62666-1c94-4942-9cc0-a96f43a023f0'
> I0924 04:54:07.092171 30002 exec.cpp:134] Version: 0.25.0
> I0924 04:54:07.092450 29996 exec.cpp:184] Executor started at:
> executor(96)@172.17.1.154:55676 with pid 29977
> I0924 04:54:07.092682 30002 slave.cpp:1598] Queuing task '0' for executor
> default of framework 'bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.092792 30002 slave.cpp:652] Successfully attached file
> '/tmp/SlaveTest_TerminatingSlaveDoesNotReregister_yCbi9q/slaves/bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0/frameworks/bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000/executors/default/runs/53b62666-1c94-4942-9cc0-a96f43a023f0'
> I0924 04:54:07.093004 30002 slave.cpp:2373] Got registration for executor
> 'default' of framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 from
> executor(96)@172.17.1.154:55676
> I0924 04:54:07.093211 30004 leveldb.cpp:343] Persisting action (16 bytes) to
> leveldb took 21.885809ms
> I0924 04:54:07.093260 30004 replica.cpp:679] Persisted action at 4
> I0924 04:54:07.093518 30004 exec.cpp:208] Executor registered on slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0
> I0924 04:54:07.093580 30004 exec.cpp:220] Executor::registered took 31899ns
> I0924 04:54:07.093616 30002 slave.cpp:1754] Sending queued task '0' to
> executor 'default' of framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.093946 29998 exec.cpp:295] Executor asked to run task '0'
> I0924 04:54:07.094220 29998 exec.cpp:304] Executor::launchTask took 68187ns
> I0924 04:54:07.094442 29996 replica.cpp:658] Replica received learned notice
> for position 4
> I0924 04:54:07.094440 29998 exec.cpp:517] Executor sending status update
> TASK_RUNNING (UUID: a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task 0 of
> framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.094717 30011 slave.cpp:2711] Handling status update
> TASK_RUNNING (UUID: a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task 0 of
> framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 from
> executor(96)@172.17.1.154:55676
> I0924 04:54:07.095018 29998 status_update_manager.cpp:322] Received status
> update TASK_RUNNING (UUID: a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task 0
> of framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.095068 29998 status_update_manager.cpp:499] Creating
> StatusUpdate stream for task 0 of framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.095501 29998 status_update_manager.cpp:376] Forwarding update
> TASK_RUNNING (UUID: a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task 0 of
> framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 to the slave
> I0924 04:54:07.095829 30004 slave.cpp:3010] Forwarding the update
> TASK_RUNNING (UUID: a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task 0 of
> framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 to
> master@172.17.1.154:55676
> I0924 04:54:07.096191 30006 master.cpp:4409] Status update TASK_RUNNING
> (UUID: a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task 0 of framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 from slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 at slave(299)@172.17.1.154:55676
> (7c9c99874a2d)
> I0924 04:54:07.096230 30006 master.cpp:4448] Forwarding status update
> TASK_RUNNING (UUID: a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task 0 of
> framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.096398 30006 master.cpp:6075] Updating the latest state of
> task 0 of framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 to TASK_RUNNING
> I0924 04:54:07.096498 30004 slave.cpp:2934] Status update manager
> successfully handled status update TASK_RUNNING (UUID:
> a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task 0 of framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.096537 30004 slave.cpp:2940] Sending acknowledgement for
> status update TASK_RUNNING (UUID: a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for
> task 0 of framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 to
> executor(96)@172.17.1.154:55676
> I0924 04:54:07.096684 30004 exec.cpp:341] Executor received status update
> acknowledgement a2b0d4fd-ef47-40b4-9550-750dfd926f9d for task 0 of framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.096706 30005 sched.cpp:918] Scheduler::statusUpdate took
> 159638ns
> I0924 04:54:07.097100 30005 master.cpp:3600] Processing ACKNOWLEDGE call
> a2b0d4fd-ef47-40b4-9550-750dfd926f9d for task 0 of framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 (default) at
> scheduler-93ec2a16-2413-4c7e-9ed1-2e35279e616a@172.17.1.154:55676 on slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0
> I0924 04:54:07.097384 30006 status_update_manager.cpp:394] Received status
> update acknowledgement (UUID: a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task
> 0 of framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.097646 30006 slave.cpp:2313] Status update manager
> successfully handled status update acknowledgement (UUID:
> a2b0d4fd-ef47-40b4-9550-750dfd926f9d) for task 0 of framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.098183 29999 status_update_manager.cpp:176] Pausing sending
> status updates
> I0924 04:54:07.098225 29997 slave.cpp:699] New master detected at
> master@172.17.1.154:55676
> I0924 04:54:07.098330 29997 slave.cpp:762] Authenticating with master
> master@172.17.1.154:55676
> I0924 04:54:07.098354 29997 slave.cpp:767] Using default CRAM-MD5
> authenticatee
> I0924 04:54:07.098578 29997 slave.cpp:735] Detecting new master
> I0924 04:54:07.098682 29998 authenticatee.cpp:115] Creating new client SASL
> connection
> I0924 04:54:07.099108 30000 master.cpp:5132] Authenticating
> slave(299)@172.17.1.154:55676
> I0924 04:54:07.099225 30006 authenticator.cpp:407] Starting authentication
> session for crammd5_authenticatee(671)@172.17.1.154:55676
> I0924 04:54:07.099690 30000 authenticator.cpp:92] Creating new server SASL
> connection
> I0924 04:54:07.099915 30006 authenticatee.cpp:206] Received SASL
> authentication mechanisms: CRAM-MD5
> I0924 04:54:07.100013 30006 authenticatee.cpp:232] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0924 04:54:07.100164 30006 authenticator.cpp:197] Received SASL
> authentication start
> I0924 04:54:07.100245 30006 authenticator.cpp:319] Authentication requires
> more steps
> I0924 04:54:07.100467 30007 authenticatee.cpp:252] Received SASL
> authentication step
> I0924 04:54:07.100605 30007 authenticator.cpp:225] Received SASL
> authentication step
> I0924 04:54:07.100642 30007 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '7c9c99874a2d' server FQDN: '7c9c99874a2d'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0924 04:54:07.100658 30007 auxprop.cpp:174] Looking up auxiliary property
> '*userPassword'
> I0924 04:54:07.100718 30007 auxprop.cpp:174] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0924 04:54:07.100766 30007 auxprop.cpp:102] Request to lookup properties for
> user: 'test-principal' realm: '7c9c99874a2d' server FQDN: '7c9c99874a2d'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0924 04:54:07.100790 30007 auxprop.cpp:124] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0924 04:54:07.100802 30007 auxprop.cpp:124] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0924 04:54:07.100826 30007 authenticator.cpp:311] Authentication success
> I0924 04:54:07.101024 30006 authenticatee.cpp:292] Authentication success
> I0924 04:54:07.101088 30011 master.cpp:5162] Successfully authenticated
> principal 'test-principal' at slave(299)@172.17.1.154:55676
> I0924 04:54:07.101315 30006 slave.cpp:830] Successfully authenticated with
> master master@172.17.1.154:55676
> I0924 04:54:07.101629 30006 slave.cpp:1224] Will retry registration in
> 226426ns if necessary
> I0924 04:54:07.101769 30005 authenticator.cpp:425] Authentication session
> cleanup for crammd5_authenticatee(671)@172.17.1.154:55676
> I0924 04:54:07.102208 30008 master.cpp:4016] Re-registering slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 at slave(299)@172.17.1.154:55676
> (7c9c99874a2d)
> I0924 04:54:07.102916 30008 master.cpp:4204] Sending updated checkpointed
> resources to slave bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 at
> slave(299)@172.17.1.154:55676 (7c9c99874a2d)
> W0924 04:54:07.103030 30010 slave.cpp:2127] Dropping updateFramework message
> for bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 because the slave is in
> DISCONNECTED state
> I0924 04:54:07.113637 30007 slave.cpp:2242] Updated checkpointed resources
> from to
> I0924 04:54:07.121868 29996 leveldb.cpp:343] Persisting action (18 bytes) to
> leveldb took 27.362746ms
> I0924 04:54:07.122032 29996 leveldb.cpp:401] Deleting ~2 keys from leveldb
> took 100541ns
> I0924 04:54:07.122069 29996 replica.cpp:679] Persisted action at 4
> I0924 04:54:07.122108 29996 replica.cpp:664] Replica learned TRUNCATE action
> at position 4
> I0924 04:54:07.128528 30006 slave.cpp:621] Slave asked to shut down by
> master@172.17.1.154:55676
> I0924 04:54:07.129091 30006 slave.cpp:1974] Asked to shut down framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 by master@172.17.1.154:55676
> I0924 04:54:07.129199 30006 slave.cpp:1999] Shutting down framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.129402 30006 slave.cpp:3745] Shutting down executor 'default'
> of framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.130210 30006 slave.cpp:1095] Skipping registration because
> slave is terminating
> I0924 04:54:07.130611 30006 slave.cpp:1095] Skipping registration because
> slave is terminating
> I0924 04:54:07.131108 30006 slave.cpp:4261] Querying resource estimator for
> oversubscribable resources
> I0924 04:54:07.131669 30006 slave.cpp:3846] Ignoring registration timeout for
> executor 'default' because the framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 is terminating
> I0924 04:54:07.131726 30006 slave.cpp:3168] No pings from master received
> within 75secs
> I0924 04:54:07.131886 30006 slave.cpp:3920] Current disk usage 13.01%. Max
> allowed age: 5.389529832493959days
> I0924 04:54:07.132267 29999 hierarchical.hpp:1421] No inverse offers to send
> out!
> I0924 04:54:07.132382 29999 hierarchical.hpp:1221] Performed allocation for 1
> slaves in 1.163512ms
> I0924 04:54:07.132840 30006 master.cpp:4961] Sending 1 offers to framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 (default) at
> scheduler-93ec2a16-2413-4c7e-9ed1-2e35279e616a@172.17.1.154:55676
> I0924 04:54:07.132977 29999 slave.cpp:3132] Received ping from
> slave-observer(268)@172.17.1.154:55676
> I0924 04:54:07.133216 29999 slave.cpp:4275] Received oversubscribable
> resources from the resource estimator
> I0924 04:54:07.133376 30006 sched.cpp:811] Scheduler::resourceOffers took
> 29150ns
> I0924 04:54:07.139232 29977 sched.cpp:1771] Asked to stop the driver
> I0924 04:54:07.139361 29977 master.cpp:913] Master terminating
> I0924 04:54:07.139490 29999 sched.cpp:1040] Stopping framework
> 'bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000'
> I0924 04:54:07.140082 29996 hierarchical.hpp:706] Removed slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0
> W0924 04:54:07.140210 29977 master.cpp:6129] Removing task 0 with resources
> cpus(*):1; mem(*):64 of framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> on slave bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 at
> slave(299)@172.17.1.154:55676 (7c9c99874a2d) in non-terminal state
> TASK_RUNNING
> I0924 04:54:07.140774 29977 master.cpp:6172] Removing executor 'default' with
> resources of framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000 on slave
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-S0 at slave(299)@172.17.1.154:55676
> (7c9c99874a2d)
> I0924 04:54:07.141835 30000 hierarchical.hpp:552] Removed framework
> bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> I0924 04:54:07.142173 30000 slave.cpp:3178] master@172.17.1.154:55676 exited
> W0924 04:54:07.142199 30000 slave.cpp:3181] Master disconnected! Waiting for
> a new master to be elected
> I0924 04:54:07.146646 30000 slave.cpp:3814] Killing executor 'default' of
> framework bd006350-cdbf-414f-9eef-25f03ccdc5fb-0000
> F0924 04:54:07.146987 30000 owned.hpp:111] Check failed: 'get()' Must be non
> NULL
> *** Check failure stack trace: ***
> @ 0x2aeb5646f500 google::LogMessage::Fail()
> @ 0x2aeb5646f44c google::LogMessage::SendToLog()
> @ 0x2aeb5646ee4e google::LogMessage::Flush()
> @ 0x2aeb56471d62 google::LogMessageFatal::~LogMessageFatal()
> @ 0xa3e076 google::CheckNotNull<>()
> @ 0xa39165 process::Owned<>::operator->()
> @ 0xa34091 mesos::internal::tests::TestContainerizer::destroy()
> @ 0x2aeb55adde4c
> mesos::internal::slave::Slave::shutdownExecutorTimeout()
> @ 0x2aeb55b1b2a0
> _ZZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS1_11FrameworkIDERKNS1_10ExecutorIDERKNS1_11ContainerIDES5_S8_SB_EEvRKNS_3PIDIT_EEMSF_FvT0_T1_T2_ET3_T4_T5_ENKUlPNS_11ProcessBaseEE_clESS_
> @ 0x2aeb55b49f60
> _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchIN5mesos8internal5slave5SlaveERKNS5_11FrameworkIDERKNS5_10ExecutorIDERKNS5_11ContainerIDES9_SC_SF_EEvRKNS0_3PIDIT_EEMSJ_FvT0_T1_T2_ET3_T4_T5_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_
> @ 0x2aeb563df9df std::function<>::operator()()
> @ 0x2aeb563c9211 process::ProcessBase::visit()
> @ 0x2aeb563cc08c process::DispatchEvent::visit()
> @ 0xbbf49c process::ProcessBase::serve()
> @ 0x2aeb563c568a process::ProcessManager::resume()
> @ 0x2aeb563b8ece process::internal::schedule()
> @ 0x2aeb564154d1
> _ZNSt12_Bind_simpleIFPFvvEvEE9_M_invokeIJEEEvSt12_Index_tupleIJXspT_EEE
> @ 0x2aeb5641542b std::_Bind_simple<>::operator()()
> @ 0x2aeb564153c4 std::thread::_Impl<>::_M_run()
> @ 0x2aeb57bf9a40 (unknown)
> @ 0x2aeb58370182 start_thread
> @ 0x2aeb5868047d (unknown)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
