Skip to content

Fix log statement 'failed to exit' timeout accuracy#42488

Merged
tianon merged 1 commit into
moby:masterfrom
sparrc:log-fix-wait-timeout
Jun 8, 2021
Merged

Fix log statement 'failed to exit' timeout accuracy#42488
tianon merged 1 commit into
moby:masterfrom
sparrc:log-fix-wait-timeout

Conversation

@sparrc

@sparrc sparrc commented Jun 8, 2021 •
edited
Loading

Copy link
Copy Markdown

log statement should reflect how long it actually waited, not how long
it theoretically could wait based on the 'seconds' integer passed in.

- What I did

If killPossiblyDeadProcess fails then wait is modified to only wait 2 seconds rather than keeping the original timeout of seconds

Since this log message was still logging seconds, this could lead to these strange messages in the logs (notice how the log message says it waited 30 seconds, but the message was logged only 2 seconds later):

time="2021-06-08T20:09:54.614066632Z" level=debug msg="Sending kill signal 15 to container cf5a81802409f5fe73406546afa3f77dd495b0046c0dc9c78582c632b278215a"
time="2021-06-08T20:09:56.614434823Z" level=error msg="Error sending stop (signal 15) to container" container=cf5a81802409f5fe73406546afa3f77dd495b0046c0dc9c78582c632b278215a error="CONTAINER KILL FAILED AHHHHHHHHHHH"
time="2021-06-08T20:09:56.614461182Z" level=info msg="Container failed to exit within 30 seconds of signal 15 - using the force" container=cf5a81802409f5fe73406546afa3f77dd495b0046c0dc9c78582c632b278215a

After this change the log messages accurately reflects that it only waited 2 seconds:

time="2021-06-08T20:26:36.094058401Z" level=debug msg="Sending kill signal 15 to container 30560ce2477e7d8a71cf28d47d4e29b73db6f17d2fb07cfd0d14d4c1380566c7"
time="2021-06-08T20:26:38.094387498Z" level=error msg="Error sending stop (signal 15) to container" container=30560ce2477e7d8a71cf28d47d4e29b73db6f17d2fb07cfd0d14d4c1380566c7 error="CONTAINER KILL FAILED AHHHHHHHHHHH"
time="2021-06-08T20:26:38.094516426Z" level=info msg="Container failed to exit within 2s of signal 15 - using the force" container=30560ce2477e7d8a71cf28d47d4e29b73db6f17d2fb07cfd0d14d4c1380566c7

- How to verify it

modify code to always return error from killWithSignal

- Description for the changelog

NA (follow-up to #41588)

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

Fix log statement 'failed to exit' timeout accuracy
d15ce13 
log statement should reflect how long it actually waited, not how long
it theoretically could wait based on the 'seconds' integer passed in.

Signed-off-by: Cam <[email protected]>
@sparrc
sparrc force-pushed the log-fix-wait-timeout branch from 131b311 to d15ce13 Compare June 8, 2021 20:38
@thaJeztah

thaJeztah commented Jun 8, 2021

Copy link
Copy Markdown
Member

Ah, yes, looks like we missed that in #41586.

CI failure; is unrelated (tracked in #42458)

[2021-06-08T20:53:10.246Z] === Failed
[2021-06-08T20:53:10.246Z] === FAIL: libnetwork/iptables TestConcurrencyNoWait (0.11s)
[2021-06-08T20:53:10.246Z]     iptables_test.go:217:  (iptables failed: iptables -t nat -A DOCKEREST -p tcp -d 192.168.1.1 --dport 1234 -j DNAT --to-destination 172.17.0.1:4321 ! -i lo: Another app is currently holding the xtables lock. Perhaps you want to use the -w option?
[2021-06-08T20:53:10.246Z]          (exit status 4))

thaJeztah
thaJeztah approved these changes Jun 8, 2021
View reviewed changes

@thaJeztah thaJeztah 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

thanks!

@tianon
tianon merged commit adb26d3 into moby:master Jun 8, 2021
@thaJeztah thaJeztah added this to the 21.xx milestone Jun 8, 2021
@sparrc
sparrc deleted the log-fix-wait-timeout branch June 8, 2021 23:45
@thaJeztah thaJeztah mentioned this pull request Oct 21, 2021
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@tianon tianon tianon approved these changes
@thaJeztah thaJeztah thaJeztah approved these changes

Assignees

No one assigned

Labels

kind/bugfix PR's that fix bugs process/cherry-picked status/2-code-review

Projects

None yet

Milestone

23.0.0

Development

Successfully merging this pull request may close these issues.

3 participants

@sparrc @thaJeztah @tianon