Warn if podman stop timeout expires that sigkill was sent #11880

rhatdan · 2021-10-06T19:57:50Z

Note: the Warning message will not come to podman-remote.
It would be difficult to plumb, and not really worth the effort.

Fixes: #11854

Signed-off-by: Daniel J Walsh dwalsh@redhat.com

What this PR does / why we need it:

How to verify it

Which issue(s) this PR fixes:

Special notes for your reviewer:

openshift-ci · 2021-10-06T19:57:52Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: rhatdan

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

~~OWNERS~~ [rhatdan]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

TomSweeneyRedHat · 2021-10-06T20:50:07Z

docs/source/markdown/podman.1.md

@@ -82,7 +82,7 @@ Remote connections use local containers.conf for default.

 #### **--log-level**=*level*

-Log messages above specified level: debug, info, warn, error (default), fatal or panic (default: "error")
+Log messages above specified level: debug, info, warn, error (default), fatal or panic (default: "warn")


I know this is pre-existing, but should it be this?

Suggested change

Log messages above specified level: debug, info, warn, error (default), fatal or panic (default: "warn")

Log messages at the specified level: debug, info, warn, error (default), fatal, or panic (default: "warn")

Default is no longer error, it's Warn

TomSweeneyRedHat · 2021-10-06T20:51:10Z

couple small nits in a message, otherwise LGTM

mheon · 2021-10-06T20:57:02Z

libpod/oci_conmon_linux.go

@@ -441,7 +441,7 @@ func (r *ConmonOCIRuntime) StopContainer(ctr *Container, timeout uint, all bool)
 		}

 		if err := waitContainerStop(ctr, time.Duration(timeout)*time.Second); err != nil {
-			logrus.Infof("Timed out stopping container %s, resorting to SIGKILL: %v", ctr.ID(), err)
+			logrus.Warnf("Timed out stopping container %s, resorting to SIGKILL: %v", ctr.ID(), err)


We should not be printing the error in the WARN-level logs. Make that a debug-level IMO.

Huh? The hole discussion was to raise this to a warn level, not a Info.

We need two logrus lines here: One to print "Timed out stopping container..." (warn level) and one to print "Error stopping container" (debug level).

edsantiago · 2021-10-07T00:47:19Z

Sorry I missed your ping this afternoon; I was clerking at our local election. I don't see a bats test, so I don't know what went wrong with your tests, but I'll look at it tomorrow.

rhatdan · 2021-10-07T09:12:21Z

Here is the test I was trying to write.

@test "podman stop -t 1 Generate warning" {

    run_podman run --rm --name stopme -d $IMAGE sleep 100
    cid=$output
    $PODMAN stop -t 1 stopme >/dev/null
    is "$output" ".*Timed out stopping container ${cid}, resorting to SIGKILL: given PIDs did not die within timeout.*" "Status of container should print warning'"
}

edsantiago · 2021-10-07T11:03:48Z

Ah - that explains it. Using $PODMAN calls podman directly, without the bats run helper. The easy solution is:

     run_podman stop -t 1 stopme
    is "$output" ".*Timed out ..."

rhatdan · 2021-10-07T12:41:19Z

Yikes, I must have accidently cut & Pasted that from where I stole the code. /dope slap

edsantiago · 2021-10-07T14:31:14Z

test/system/050-stop.bats

+
+    run_podman run --rm --name stopme -d $IMAGE sleep 100
+    cid=$output
+    run_podman stop -t 1 stopme >/dev/null


The >/dev/null is unnecessary (and misleading, because it actually gets ignored); but not worth repushing for. LGTM.

edsantiago · 2021-10-07T14:32:03Z

test/system/050-stop.bats

+@test "podman stop -t 1 Generate warning" {
+
+    run_podman run --rm --name stopme -d $IMAGE sleep 100
+    cid=$output


This too is unnecessary (you never use $cid) but again, not worth a re-push

edsantiago · 2021-10-07T14:48:04Z

test/system/050-stop.bats

@@ -166,4 +166,12 @@ load helpers
    is "$output" "137" "Exit code of killed container"
 }

+@test "podman stop -t 1 Generate warning" {
+


looks like you need skip_if_remote; when you repush, can you take care of the two issues below? Thanks

edsantiago · 2021-10-07T21:13:10Z

libpod/oci_conmon_linux.go

@@ -441,7 +441,8 @@ func (r *ConmonOCIRuntime) StopContainer(ctr *Container, timeout uint, all bool)
 		}

 		if err := waitContainerStop(ctr, time.Duration(timeout)*time.Second); err != nil {
-			logrus.Infof("Timed out stopping container %s, resorting to SIGKILL: %v", ctr.ID(), err)
+			logrus.Debugf("Timed out stopping container %s with %s, resorting to SIGKILL: %v", ctr.ID(), unix.SignalName(syscall.Signal(stopSignal)), err)
+			logrus.Warnf("Failed to stopping container %s with %s, resorting to SIGKILL: %v", ctr.ID(), unix.SignalName(syscall.Signal(stopSignal)), err)


"Failed to stopping"??

Okay, I see this is in response to @mheon's comment:

We need two logrus lines here: One to print "Timed out stopping container..." (warn level) and one to print "Error stopping container" (debug level).

...but I don't understand the request. @mheon could you clarify, possibly with a code sample to reduce ambiguity?

edsantiago · 2021-10-07T23:51:37Z

test/e2e/stop_test.go

+		session.WaitWithDefaultTimeout()
+		Expect(session).Should(Exit(0))
+		warning := session.ErrorToString()
+		Expect(warning).To(ContainSubstring("Timed out stopping container"))


I think you mean StopSignal TERM failed to stop container here (the Timed out one is now just debug).

But I still don't understand @mheon's reason for requesting two messages.

We don't want to print the error message every time, it's largely irrelevant to the situation and will reduce clarity (I expect it's going to be rather long - "failed to stop PID %d after %d seconds" or somesuch.

What we actually want is to print the "Timed out stopping container %s" message first as a logrus.Warnf, then print "Error stopping container %s using stop signal: %v" including the error message as a Debugf so the error isn't entirely lost.

The PR now prints.

./bin/podman stop -t 2 -l WARN[0002] StopSignal SIGTERM failed to stop container hungry_bassi in 2 seconds, resorting to SIGKILL 729d71716d7c024e1b274a6ebf7d41bf65faa43b4324d0017a72cf1375059df0

Debug message actually includes the error.

edsantiago · 2021-10-08T10:58:27Z

test/e2e/stop_test.go

+		session.WaitWithDefaultTimeout()
+		Expect(session).Should(Exit(0))
+		warning := session.ErrorToString()
+		Expect(warning).To(ContainSubstring("StopSignal SIGTERM failed to stop container test4 in 1 seconds, resorting to SIGKILL"))


s/test4/test5/

Note: the Warning message will not come to podman-remote. It would be difficult to plumb, and not really worth the effort. Fixes: containers#11854 Signed-off-by: Daniel J Walsh <dwalsh@redhat.com>

mheon · 2021-10-08T18:22:01Z

LGTM

edsantiago · 2021-10-08T22:31:42Z

/lgtm
/hold

Quite a slog for something that seemed so simple! Thanks, @rhatdan!

rhatdan · 2021-10-10T10:51:48Z

/hold cancel

openshift-ci bot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 6, 2021

rhatdan force-pushed the stoptimeout branch from 12fac5e to 462385a Compare October 6, 2021 19:58

TomSweeneyRedHat reviewed Oct 6, 2021

View reviewed changes

mheon reviewed Oct 6, 2021

View reviewed changes

rhatdan force-pushed the stoptimeout branch from 462385a to e2b75a7 Compare October 6, 2021 21:18

rhatdan mentioned this pull request Oct 7, 2021

[ci:docs] Change podman.1 man page to show corret log-level default #11885

Merged

rhatdan force-pushed the stoptimeout branch from e2b75a7 to ae6005d Compare October 7, 2021 12:47

edsantiago reviewed Oct 7, 2021

View reviewed changes

rhatdan force-pushed the stoptimeout branch from ae6005d to d22334b Compare October 7, 2021 19:36

edsantiago reviewed Oct 7, 2021

View reviewed changes

rhatdan force-pushed the stoptimeout branch from d22334b to ac463b5 Compare October 7, 2021 22:02

edsantiago reviewed Oct 7, 2021

View reviewed changes

rhatdan force-pushed the stoptimeout branch from ac463b5 to afb5d07 Compare October 8, 2021 09:58

edsantiago reviewed Oct 8, 2021

View reviewed changes

Warn if podman stop timeout expires that sigkill was sent

48d26a8

Note: the Warning message will not come to podman-remote. It would be difficult to plumb, and not really worth the effort. Fixes: containers#11854 Signed-off-by: Daniel J Walsh <dwalsh@redhat.com>

rhatdan force-pushed the stoptimeout branch from afb5d07 to 48d26a8 Compare October 8, 2021 11:07

openshift-ci bot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Oct 8, 2021

openshift-ci bot assigned edsantiago Oct 8, 2021

openshift-ci bot added the lgtm Indicates that a PR is ready to be merged. label Oct 8, 2021

openshift-ci bot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Oct 10, 2021

openshift-merge-robot merged commit c47f714 into containers:main Oct 10, 2021

github-actions bot added the locked - please file new issue/PR Assist humans wanting to comment on an old issue or PR with locked comments. label Sep 22, 2023

github-actions bot locked as resolved and limited conversation to collaborators Sep 22, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Warn if podman stop timeout expires that sigkill was sent #11880

Warn if podman stop timeout expires that sigkill was sent #11880

rhatdan commented Oct 6, 2021 •

edited

Loading

openshift-ci bot commented Oct 6, 2021

TomSweeneyRedHat Oct 6, 2021 •

edited

Loading

mheon Oct 6, 2021

TomSweeneyRedHat commented Oct 6, 2021

mheon Oct 6, 2021

rhatdan Oct 6, 2021

mheon Oct 7, 2021

edsantiago commented Oct 7, 2021

rhatdan commented Oct 7, 2021

edsantiago commented Oct 7, 2021

rhatdan commented Oct 7, 2021

edsantiago Oct 7, 2021

edsantiago Oct 7, 2021

edsantiago Oct 7, 2021

edsantiago Oct 7, 2021

edsantiago Oct 7, 2021

edsantiago Oct 7, 2021

mheon Oct 8, 2021

rhatdan Oct 8, 2021

rhatdan Oct 8, 2021

edsantiago Oct 8, 2021

mheon commented Oct 8, 2021

edsantiago commented Oct 8, 2021

rhatdan commented Oct 10, 2021

	Log messages above specified level: debug, info, warn, error (default), fatal or panic (default: "warn")
	Log messages at the specified level: debug, info, warn, error (default), fatal, or panic (default: "warn")

Warn if podman stop timeout expires that sigkill was sent #11880

Warn if podman stop timeout expires that sigkill was sent #11880

Conversation

rhatdan commented Oct 6, 2021 • edited Loading

What this PR does / why we need it:

How to verify it

Which issue(s) this PR fixes:

Special notes for your reviewer:

openshift-ci bot commented Oct 6, 2021

TomSweeneyRedHat Oct 6, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

TomSweeneyRedHat commented Oct 6, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edsantiago commented Oct 7, 2021

rhatdan commented Oct 7, 2021

edsantiago commented Oct 7, 2021

rhatdan commented Oct 7, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mheon commented Oct 8, 2021

edsantiago commented Oct 8, 2021

rhatdan commented Oct 10, 2021

rhatdan commented Oct 6, 2021 •

edited

Loading

TomSweeneyRedHat Oct 6, 2021 •

edited

Loading