Skip to content

Fix hung docker stop if stop signal and daemon.Kill both fail#41586

Merged
cpuguy83 merged 1 commit into
moby:masterfrom
sparrc:stop-refactor
Apr 14, 2021
Merged

Fix hung docker stop if stop signal and daemon.Kill both fail#41586
cpuguy83 merged 1 commit into
moby:masterfrom
sparrc:stop-refactor

Conversation

@sparrc

@sparrc sparrc commented Oct 24, 2020

Copy link
Copy Markdown

replaces #41580

this refactors the Stop command to fix a few issues and behaviors that
dont seem completely correct:

  1. first it fixes a situation where stop could hang forever (docker stop hangs forever if it falls back to docker kill and docker kill fails #41579)
  2. fixes a behavior where if sending the
    stop signal failed, then the code directly sends a -9 signal. If that
    fails, it returns without waiting for the process to exit or going
    through the full docker kill codepath.
  3. fixes a behavior where if sending the stop signal failed, then the
    code sends a -9 signal. If that succeeds, then we still go through the
    same stop waiting process, and may even go through the docker kill path
    again, even though we've already sent a -9.
  4. fixes a behavior where the code would wait the full 30 seconds after
    sending a stop signal, even if we already know the stop signal failed.

(2 and 3 were both fixed to not send a -9 directly, and instead rely on the docker kill codepath)

fixes #41579

- What I did

remove waiting without a timeout when docker kill fails within docker stop

before change:

cli:

% docker stop # hangs forever
Oct 23 04:17:23 ip-10-0-0-176.us-west-2.compute.internal dockerd[29371]: time="2020-10-23T04:17:23.883792164Z" level=info msg="Container e0d10e9ca9d06815a903de8bab96c98b7b7d2435f6afc41bbe54e188f112564c failed to exit within 10 seconds of signal 15 - using the force"

after change:
cli:

% docker stop kt
Error response from daemon: cannot stop container: kt: foo error

docker logs:

Oct 24 20:30:08 ip-10-0-0-157.us-west-2.compute.internal dockerd[30001]: time="2020-10-24T20:30:08.683984540Z" level=info msg="Container failed to exit within 10 seconds of signal 15 - using the force" container=ae525e8f6493cdebe26ba275b7c8f02509827b27d6b637dc99614fd90fe67f4c
Oct 24 20:30:10 ip-10-0-0-157.us-west-2.compute.internal dockerd[30001]: time="2020-10-24T20:30:10.684154746Z" level=error msg="Error killing the container" container=ae525e8f6493cdebe26ba275b7c8f02509827b27d6b637dc99614fd90fe67f4c error="foo error"
Oct 24 20:30:10 ip-10-0-0-157.us-west-2.compute.internal dockerd[30001]: time="2020-10-24T20:30:10.684256073Z" level=error msg="Handler for POST /v1.40/containers/kt/stop returned error: cannot stop container: kt: foo error"

- Description for the changelog

Fix hung docker stop if SIGTERM and SIGKILL both fail

- A picture of a cute animal (not mandatory but encouraged)

@sparrc sparrc changed the title docker daemon container stop refactor Fix hung docker stop if stop signal and daemon.Kill both fail Oct 27, 2020
@sparrc

sparrc commented Oct 28, 2020

Copy link
Copy Markdown
Author

hello, any chance I could get some eyes on this and #41588 ? Im free to do a skype call if it would help to talk through the changes

@thaJeztah

Copy link
Copy Markdown
Member

@cpuguy83 PTAL; looks like this is making changes in the same area as your PR #41698

@sparrc

sparrc commented Feb 16, 2021

Copy link
Copy Markdown
Author

hello, we are continuing to see this issue in ECS, any chance we could get some eyes on this fix?

@cpuguy83 cpuguy83 left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just a nit about the else but otherwise this seems ok.

I don't see what this is fixing, though, other than waiting indefinitely (which is itself worthy of fixing of course).
In which case it's probably also good to plumb a context through from the http request.

Comment thread daemon/stop.go Outdated
Comment thread daemon/stop.go Outdated

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For defaults here I'd start with 10s (if no duration was passed in).
In the error condition we can drop that down to 2 seconds.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, this is done, but also I should not that I refactored the default handling and stop timeout a little bit after realizing that waiting forever is the intended behavior when this function is called with seconds < 0. At least according to the comment on the ContainerStop function:

moby/daemon/stop.go

Lines 13 to 21 in 46cdcd2

// ContainerStop looks for the given container and stops it.
// In case the container fails to stop gracefully within a time duration
// specified by the timeout argument, in seconds, it is forcefully
// terminated (killed).
//
// If the timeout is nil, the container's StopTimeout value is used, if set,
// otherwise the engine default. A negative timeout value can be specified,
// meaning no timeout, i.e. no forceful termination is performed.
func (daemon *Daemon) ContainerStop(name string, timeout *int) error {

Comment thread daemon/stop.go Outdated

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Lets set this explicitly to context.TODO(), especially since context should never be nil.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Then there is no need for var cancel, since that can be dealt with inside the if

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

TODO() because we really need to propagate a context down to this function, I have a separate PR that does that.
This will effectively allow an API request to cancel the wait instead of detaching from it.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

okay will do

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this is done, I have added the TODO context and made new contexts with timeouts internal to this func "subCtx"

Comment thread daemon/stop.go Outdated

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would bump this up to a higher value just because if the system is loaded this could have cause more issues.... maybe a minute?

I don't think we have the container lock here. Presuming I'm right waiting shouldn't cause any problems just so long as we eventually give up.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

At this point the kill signal has failed for some reason, waiting for 1 minute seems overly long to me. Reason being that a caller of this function may set a timeout for how long they are willing to wait at a higher level than this function. If they passed in 10s as the timeout (the default) to container stop it seems a bit excessive to wait for an entire minute after the kill signal has failed.

If you'd really like to wait longer here, perhaps something on the order of 10 seconds?

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@sparrc Currently the only way for the caller to set a timeout is from the passed in wait value. We could use that, but I think 2 seconds is too small and indefinite is too long.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In ECS we implemented a timeout to avoid our code waiting forever on docker returning from the ContainerStop function call. In my opinion this function shouldn't wait much longer than what the user passes in via the seconds argument.

If we use wait again here, then this function will usually take around wait seconds, with the possibility to take 2 * wait seconds. To me this is probably better than wait + 60s

I guess this is all a moot point anyways if you say that you have a change incoming to add the ability for the user to pass in a context anyways. I will amend this PR to use wait again here.

@sparrc sparrc Feb 24, 2021

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That being said, in the above code we lower wait to 2s when SIGTERM fails (ie after killPossiblyDeadProcess fails), so this logic may start to get complicated unless you would like me to also increase the wait after SIGTERM failure to something else?

Comment thread daemon/stop.go Outdated

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We lost the comment explaining the reasoning for 2 seconds here. Can we add something back in? Otherwise this looks like a magic number without an explanation.

Also: this clobbers the value assigned to wait on line 48

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it is a bit of a magic number, I can add a comment but Im not sure I have anything great to say about it. If you look around these files and kill functions there are quite a lot places where it does "this failed but wait 2 seconds to see if the container exited anyways", so I was just following that pattern.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are you intentionally overwriting the value passed in as seconds though?

@sparrc sparrc Feb 25, 2021

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes it's intentionally being overwritten, I'm not sure I agree with the behavior but the intention was to preserve the existing behavior as much as possible while getting rid of the infinite hang.

If you look at the deleted code in line 58 you can see that if killPossiblyDeadProcess returns an error then the container would be given 2 seconds to exit before calling killPossiblyDeadProcess(container, 9), so the intention here was just to maintain that behavior.

I guess instead of waiting just 2 seconds when killPossibleDeadProcess fails we could wait for the full seconds seconds.....I'm just not exactly sure what we'd be waiting for though since we already know that the kill function failed.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

see comment below: #41586 (comment)

Comment thread daemon/stop.go Outdated
Comment on lines 63 to 68

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If seconds is 0, even if we set a value for wait on line 59 we're still not setting a timeout on the context? Is that intentional? Would it be better to check whether wait is zero here?

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

docker stop explicitly allows disabling the docker kill fallback by setting a negative timeout value (and thus waiting forever after SIGTERM). That's why it's checking >=.

If the user explicitly set the timeout for the wait after sending a stop signal to 0, then I guess we should respect that.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If the user explicitly set the timeout for the wait after sending a stop signal to 0, then I guess we should respect that.

You're doing that on line 59 irrespective of whether seconds was >= 0 which is why I'm confused.

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

see comment below: #41586 (comment)

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If I'm summarizing that accurately, seconds < 0 == "user requested that we wait forever" (so we do so even when signal sending fails).

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yep that's correct

Comment thread daemon/stop.go Outdated
Comment on lines 73 to 77

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's worth inverting the conditional and out-denting the logic here since there's nothing left to do if there was no error

Suggested change
if err != nil {
// the container has still not exited, and the kill function errored, so log the error here:
if err == nil {
return success()
}
// the container has still not exited, and the kill function errored, so log the error here:

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sure i can do that

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree, but I also feel like there's an edge case here when the user specifies seconds < 0 (thus no timeout), but the "wait for container to stop" context gets cancelled for other reasons, such as the client disconnecting.

My interpretation of seconds < 0 is "client requested we wait forever" but that implies "client requested we 'stop' but never kill" so I think after the if err == nil block, we probably should also handle that edge case, right?

Suggested change
if err != nil {
// the container has still not exited, and the kill function errored, so log the error here:
if err == nil {
return success()
}
if seconds < 0 {
// if the client requested that we never kill / wait forever, but container.Wait was still interrupted (parent context cancelled, for example), we should propagate the signal failure
return err
}
// the container has still not exited, and the kill function errored, so log the error here:

(Have to admit I'm a little bit out of my depth, so I might be misunderstanding the flow.)

Should we also explicitly invoke cancel() here since we know for sure that the current subCtx is finished? (before we confusingly reuse/shadow those variable names later in the "kill" block)

@sparrc

sparrc commented Feb 26, 2021

Copy link
Copy Markdown
Author

Just wanted to check in here with @samuelkarp and @cpuguy83 and summarize the current behavior in this PR, you can see it below. For simplicity's sake I'm equating "send SIGTERM" with killPossiblyDeadProcess and "send SIGKILL" with daemon.Kill.

For next steps on this PR, which of these behaviors do we want to change? My understanding is that @cpuguy83 would like to increase the 2 second wait after SIGKILL failures. @samuelkarp would possibly like to remove the potential to wait forever after SIGTERM fails (ie, keep the wait at 2s even if seconds is negative). Is that correct?

sunny day scenario:

  1. send SIGTERM to container
  2. wait up to seconds seconds for it to exit (or wait forever if seconds is negative)
  3. send SIGKILL to container
  4. return nil (success)

SIGTERM fails scenario:

  1. send SIGTERM to container, it fails
  2. wait 2 seconds to see if container exited anyways (or wait forever is seconds is negative)
  3. send SIGKILL to container
  4. return nil (success)

SIGKILL fails scenario:

  1. send SIGTERM to container
  2. wait up to seconds seconds for it to exit (or wait forever if seconds is negative)
  3. send SIGKILL to container, it fails
  4. wait 2 seconds to see if container exited anyways
  5. if container exits, return nil (success), if it doesn't exit then return error

@mmerkes

mmerkes commented Mar 17, 2021

Copy link
Copy Markdown

@sparrc @cpuguy83 @samuelkarp What's the status of this PR? Would love to get it merged. Sounds like it would fix somewhat frequent issues with see on Kubernetes nodes.

@sparrc

sparrc commented Mar 23, 2021

Copy link
Copy Markdown
Author

@cpuguy83 more thoughts on this?

@sparrc

sparrc commented Apr 5, 2021

Copy link
Copy Markdown
Author

@cpuguy83 any time to take another look at this? We're still regularly seeing customers running into this issue

@cpuguy83 cpuguy83 left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm fine with it like this. LGTM.

@cpuguy83

cpuguy83 commented Apr 5, 2021

Copy link
Copy Markdown
Member

Can you re-push so we can trigger CI again?

@sparrc

sparrc commented Apr 5, 2021

Copy link
Copy Markdown
Author

yes will do

@sparrc

sparrc commented Apr 5, 2021

Copy link
Copy Markdown
Author

from what I can tell most of the tests passed except on s390x and win rs5, which seem to be unrelated failures, does it look OK @cpuguy83 ?

@cpuguy83

cpuguy83 commented Apr 5, 2021

Copy link
Copy Markdown
Member
[2021-04-05T17:18:29.821Z] daemon/stop.go:41:10: `propogate` is a misspelling of `propagate` (misspell)
[2021-04-05T17:18:29.821Z] 	// TODO propogate a context down to this function

@sparrc

sparrc commented Apr 5, 2021

Copy link
Copy Markdown
Author
[2021-04-05T17:18:29.821Z] daemon/stop.go:41:10: `propogate` is a misspelling of `propagate` (misspell)
[2021-04-05T17:18:29.821Z] 	// TODO propogate a context down to this function

oops! fixed ✅

@sparrc

sparrc commented Apr 6, 2021

Copy link
Copy Markdown
Author

Now it seems to only be failing on the s390x integration tests, so i think this time it's an unrelated failure. How does it look @cpuguy83 ?

@sparrc

sparrc commented Apr 12, 2021

Copy link
Copy Markdown
Author

Is there anything we are waiting on to get this merged? Does it need to be reviewed by another maintainer?

@cpuguy83
cpuguy83 requested a review from tianon April 12, 2021 15:58
@cpuguy83

Copy link
Copy Markdown
Member

@sparrc Yes, still needs another review.

@tianon tianon left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure I'm the right maintainer to have review this, but I've left a few comments/questions. 😅

Comment thread daemon/stop.go Outdated
Comment on lines 62 to 65

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Doesn't calling context.WithCancel without ever calling cancel cause a minor leak?

https://golang.org/pkg/context/#WithCancel

Canceling this context releases resources associated with it, so code should call cancel as soon as the operations running in this Context complete.

So this should probably be something like this instead, right?

var subCtx context.Context, cancel context.CancelFunc
if seconds >= 0 {
	subCtx, cancel = context.WithTimeout(ctx, wait)
} else {
	subCtx, cancel = context.WithCancel(ctx)
}
defer cancel()

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes i can make this change

Comment thread daemon/stop.go Outdated
Comment on lines 63 to 68

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If I'm summarizing that accurately, seconds < 0 == "user requested that we wait forever" (so we do so even when signal sending fails).

Comment thread daemon/stop.go Outdated
Comment on lines 73 to 77

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I agree, but I also feel like there's an edge case here when the user specifies seconds < 0 (thus no timeout), but the "wait for container to stop" context gets cancelled for other reasons, such as the client disconnecting.

My interpretation of seconds < 0 is "client requested we wait forever" but that implies "client requested we 'stop' but never kill" so I think after the if err == nil block, we probably should also handle that edge case, right?

Suggested change
if err != nil {
// the container has still not exited, and the kill function errored, so log the error here:
if err == nil {
return success()
}
if seconds < 0 {
// if the client requested that we never kill / wait forever, but container.Wait was still interrupted (parent context cancelled, for example), we should propagate the signal failure
return err
}
// the container has still not exited, and the kill function errored, so log the error here:

(Have to admit I'm a little bit out of my depth, so I might be misunderstanding the flow.)

Should we also explicitly invoke cancel() here since we know for sure that the current subCtx is finished? (before we confusingly reuse/shadow those variable names later in the "kill" block)

@sparrc

sparrc commented Apr 13, 2021

Copy link
Copy Markdown
Author

I agree, but I also feel like there's an edge case here when the user specifies seconds < 0 (thus no timeout), but the "wait for container to stop" context gets cancelled for other reasons, such as the client disconnecting.

My interpretation of seconds < 0 is "client requested we wait forever" but that implies "client requested we 'stop' but never kill" so I think after the if err == nil block, we probably should also handle that edge case, right?

if err == nil {
	return success()
}
if seconds < 0 {
	// if the client requested that we never kill / wait forever, but container.Wait was still interrupted (parent context cancelled, for example), we should propagate the signal failure
	return err
}
// the container has still not exited, and the kill function errored, so log the error here:

(Have to admit I'm a little bit out of my depth, so I might be misunderstanding the flow.)

Should we also explicitly invoke cancel() here since we know for sure that the current subCtx is finished? (before we confusingly reuse/shadow those variable names later in the "kill" block)

(Github won't let me comment in-line for some reason)

  1. I disagree that we should return success() when err == nil. At this point that would mean that SIGTERM sent to the container succeeded, yet the container never exited. I think in this case we should log that the container never exited and move on to SIGKILL, as the code is currently doing.
  2. Yes you're correct...there is an edge case where seconds is less than 0 and the context could be cancelled during the wait function for some reason. I can add in the second if-statement as you've suggested.

this refactors the Stop command to fix a few issues and behaviors that
dont seem completely correct:

1. first it fixes a situation where stop could hang forever (moby#41579)
2. fixes a behavior where if sending the
stop signal failed, then the code directly sends a -9 signal. If that
fails, it returns without waiting for the process to exit or going
through the full docker kill codepath.
3. fixes a behavior where if sending the stop signal failed, then the
code sends a -9 signal. If that succeeds, then we still go through the
same stop waiting process, and may even go through the docker kill path
again, even though we've already sent a -9.
4. fixes a behavior where the code would wait the full 30 seconds after
sending a stop signal, even if we already know the stop signal failed.

fixes moby#41579

Signed-off-by: Cam <[email protected]>
@sparrc

sparrc commented Apr 13, 2021

Copy link
Copy Markdown
Author

Okay, I have pushed some changes addressing comments, @tianon can you please take another look?

@tianon tianon left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

(I guess there's technically a tiny edge case for where SIGKILL succeeds but doesn't kill the process/container, but I've only ever seen that with much deeper underlying system issues like a kernel lockup, so IMO it isn't worth handling in any special way here.)

@cpuguy83

Copy link
Copy Markdown
Member

I think that can, and probably should be, dealt with by deleting the task in containerd, but not necessary to deal with here.

@cpuguy83 cpuguy83 left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

docker stop hangs forever if it falls back to docker kill and docker kill fails

7 participants