fix: shutdown logger after container process exits by mharwani · Pull Request #2337 · containerd/nerdctl

mharwani · 2023-06-29T09:42:28Z

Addresses #2313

Container task is not deleted after it exits, leaving the runtime shim and logger open throughout the lifecycle of a container. This can be a problem when there is unprocessed stdout data after a container task finishes and the logger is blocked forever waiting for a newline or EOF.

This PR fixes the issue by piping container output instead of reading directly from stdout and stderr file descriptors. Closing the io pipes upon task exit allows the logger to shutdown gracefully and process leftover data without a newline .

fahedouch · 2023-07-10T22:37:02Z

Hi @mharwani, as mentioned here closing task io io.Close() after task exiting should close FIFOs => send EOF to stdio => logger will receive EOF

mharwani · 2023-07-11T14:19:38Z

Hi @mharwani, as mentioned here closing task io io.Close() after task exiting should close FIFOs => send EOF to stdio => logger will receive EOF

Hi @fahedouch, I tried closing the task IO upon container exit with task.IO().Close(), but it did not fix the issue. The scanner did not receive EOF. I posted my thoughts here:

From what I understand, when a task is running in detached mode it uses logURI as the task IO, which doesn't have any FIFOs open and does nothing on close.

fahedouch · 2023-07-16T13:15:03Z

+	base := testutil.NewBase(t)
+	containerName := testutil.Identifier(t)
+	defer base.Cmd("rm", containerName).Run()
+	expected := []string{}


Suggested change

expected := []string{}

expected := make([]string, 10)

fahedouch · 2023-07-16T13:19:15Z

+	}
+
+	base.Cmd("run", "-d", "--name", containerName, testutil.CommonImage,
+		"sh", "-euc", "for i in `seq 1 10`; do echo $i; sleep 1; done").AssertOK()


Suggested change

"sh", "-euc", "for i in `seq 1 10`; do echo $i; sleep 1; done").AssertOK()

"sh", "-euc", "for i in `seq 1 10`; do echo $i; done").AssertOK()

I added sleep to have both the container task and the logs command running concurrently

fahedouch · 2023-07-16T13:20:43Z

+	base.Cmd("run", "-d", "--name", containerName, testutil.CommonImage,
+		"sh", "-euc", "for i in `seq 1 10`; do echo $i; sleep 1; done").AssertOK()
+	base.Cmd("logs", "-f", containerName).AssertOutContainsAll(expected...)
+	base.Cmd("rm", "-f", containerName).AssertOK()


useless regarding defer

fahedouch · 2023-07-16T13:21:15Z

+	t.Parallel()
+	base := testutil.NewBase(t)
+	containerName := testutil.Identifier(t)
+	defer base.Cmd("rm", containerName).Run()


Suggested change

defer base.Cmd("rm", containerName).Run()

defer base.Cmd("rm", "-f", containerName).Run()

fahedouch · 2023-07-16T13:22:53Z

 	base.Cmd("rm", "-f", containerName).AssertOK()
 }
+
+func TestLogsWithRunningContainer(t *testing.T) {


what this test covers comparing to this one ?

The other test runs the log command after the container has stopped running, but this one tests logs during the task execution and as logs are being sent to the logger with the --follow option.

fahedouch · 2023-07-16T14:31:06Z

 						go func() {
 							<-waitCh
+							// wait 100ms to let logViewer process data sent after container exit, if any
+							time.Sleep(100 * time.Millisecond)


have you experienced data not processed by the LogViewer?

Yes, the logger may process additional data after container exits and there is no newline or EOF. For example, the following will not print any logs without time.Sleep:

sudo nerdctl run -d --name test alpine sh -c 'sleep 10; echo -n hello' sudo nerdctl logs -f test

Sleeping for 100ms is undeterministic. There should be a better way to do this. Maybe somehow wait for the logger to finish instead of container wait?

Yes, waiting for the logger to complete instead of waiting for the container to exit gives a more accurate result

Sorry, didn't get a chance to work on it. I will send a new revision later today.

@fahedouch To wait for the logger to complete, it has to send a signal to the LogViewer. I'm using file locks to accomplish this IPC. PTAL here and here. Thanks!

fahedouch · 2023-07-16T14:36:05Z

 	if err := driver.PreProcess(dataStore, config); err != nil {
 		return err
 	}
+	exit, err := getContainerWait(ctx, hostAddress, config)


Suggested change

exit, err := getContainerWait(ctx, hostAddress, config)

exitCh, err := getContainerWait(ctx, hostAddress, config)

fahedouch · 2023-07-16T14:46:09Z

+	stderrR, stderrW := io.Pipe()
+	copyStream := func(reader io.Reader, writer *io.PipeWriter) {
+		// copy using a buffer of size 16K
+		buf := make([]byte, 16*1024)


Suggested change

buf := make([]byte, 16*1024)

buf := make([]byte, 16<<10)

Why choose a 16k buffer?

Changed it to 32k as that is what containerd uses to copy stdio:
https://github.com/containerd/containerd/blob/main/cio/io.go#L34

fahedouch · 2023-07-16T15:13:12Z


 // generateLogConfig creates a LogConfig for the current container store
-func generateLogConfig(dataStore string, id string, logDriver string, logOpt []string, ns string) (logConfig logging.LogConfig, err error) {
+func generateLogConfig(dataStore string, id string, logDriver string, logOpt []string, gOpt *types.GlobalCommandOptions) (logConfig logging.LogConfig, err error) {


why passing a pointer here gOpt *types.GlobalCommandOptions?

mharwani · 2023-07-19T15:32:36Z

It looks like the environment setup is failing for some of the checks because curl cannot reach the endpoint https://raw.githubusercontent.com/AkihiroSuda/containerized-systemd/v0.1.1/docker-entrypoint.sh:
SSL: no alternative certificate subject name matches target host name 'raw.githubusercontent.com'

Any ideas?

AkihiroSuda · 2023-07-21T15:16:04Z

CI is now green for Linux.
Please try rebasing to make Windows CI green

fahedouch

@mharwani PTAL #2337 (comment)

AkihiroSuda · 2023-07-31T06:52:39Z

Windows tests are failing

=== NAME  TestLogs
    container_logs_test.go:42: assertion failed: 
        Command:  C:\Windows\system32\config\systemprofile\go\bin\nerdctl.exe --namespace=nerdctl-test logs --since 10s nerdctl-testlogs
        ExitCode: 0
        Stdout:   
        Stderr:   
        Failures:
        Expected stdout to contain "foo\nbar"
=== CONT  TestLogsWithoutNewlineOrEOF
--- FAIL: TestLogs (4.60s)
=== NAME  TestLogsAfterRestartingContainer

https://cirrus-ci.com/task/4610614887186432?logs=build#L843

fahedouch · 2023-07-31T17:49:36Z

 			}
-			if err := ready(); err != nil {
+
+			lockFile := getLockPath(dataStore, config.Namespace, config.ID)


may be loggerLock is more explicit here

Signed-off-by: Mrudul Harwani <mharwani@amazon.com>

…ocessed data Signed-off-by: Mrudul Harwani <mharwani@amazon.com>

Signed-off-by: Mrudul Harwani <mharwani@amazon.com>

fahedouch · 2023-08-10T22:21:08Z

+	for {
+		select {
+		case <-ctx.Done():
+			return nil, fmt.Errorf("timed out waiting for container task to start")


Suggested change

return nil, fmt.Errorf("timed out waiting for container task to start")

return nil, errors.New("timed out waiting for container task to start")

fahedouch · 2023-08-10T22:28:26Z

+
+	// If task was not found, it's possible that the container runtime is still being created.
+	// Retry every 100ms.
+	ticker := time.NewTicker(100 * time.Millisecond)


Suggested change

ticker := time.NewTicker(100 * time.Millisecond)

ticker := time.NewTicker(100 * time.Millisecond)

defer ticker.Stop()

fahedouch · 2023-08-25T09:57:22Z

@mharwani PTAL

AkihiroSuda · 2023-10-08T22:21:24Z

ping @mharwani

apostasie · 2024-08-08T17:47:14Z

Hey @mharwani

Would you still be interested in carrying this PR through?
If so, could you rebase (a lot has changed) and see about @fahedouch comments?

fahedouch · 2025-02-20T10:13:24Z

Sorry for ping again @mharwani

Would you still be interested in carrying this PR through?

…xits [carry #2337] ensure logger completion after container exit

AkihiroSuda added the area/logging label Jun 29, 2023

mharwani marked this pull request as ready for review June 29, 2023 19:07

fahedouch self-requested a review July 1, 2023 22:35

fahedouch added this to the v1.5.0 milestone Jul 1, 2023

mharwani force-pushed the mharwani/shutdown-logger-after-exit branch from 97ef2b7 to 9d8a14f Compare July 10, 2023 17:31

fahedouch reviewed Jul 16, 2023

View reviewed changes

ginglis13 mentioned this pull request Jul 17, 2023

update buildkit to v0.12.0 #2374

Merged

mharwani force-pushed the mharwani/shutdown-logger-after-exit branch from 9d8a14f to 8763da2 Compare July 19, 2023 14:58

mharwani requested a review from fahedouch July 19, 2023 15:41

fahedouch reviewed Jul 27, 2023

View reviewed changes

AkihiroSuda modified the milestones: v1.5.0, v1.5.1 (tentative) Jul 30, 2023

mharwani force-pushed the mharwani/shutdown-logger-after-exit branch from 8763da2 to 23b24a6 Compare July 31, 2023 05:08

fahedouch reviewed Jul 31, 2023

View reviewed changes

mharwani force-pushed the mharwani/shutdown-logger-after-exit branch from 3ce8c17 to 1df7878 Compare August 1, 2023 21:18

mharwani added 5 commits August 1, 2023 14:20

fix: shutdown logger after container process exits

a45f5d1

Signed-off-by: Mrudul Harwani <mharwani@amazon.com>

add tests for the logging changes

5d5aa5c

Signed-off-by: Mrudul Harwani <mharwani@amazon.com>

wait after container exit in logs cmd instead of json_logger for unpr…

6316ae9

…ocessed data Signed-off-by: Mrudul Harwani <mharwani@amazon.com>

minor changes to address review feedback

17a33f9

Signed-off-by: Mrudul Harwani <mharwani@amazon.com>

implement method to wait for logger exit

808dd0c

Signed-off-by: Mrudul Harwani <mharwani@amazon.com>

mharwani force-pushed the mharwani/shutdown-logger-after-exit branch from 1df7878 to 39fe0b3 Compare August 1, 2023 21:20

add retry attempts in logger to wait for task start

0050ac5

Signed-off-by: Mrudul Harwani <mharwani@amazon.com>

mharwani force-pushed the mharwani/shutdown-logger-after-exit branch from 39fe0b3 to 0050ac5 Compare August 1, 2023 21:30

AkihiroSuda reviewed Aug 2, 2023

View reviewed changes

Comment thread pkg/logging/logging.go

fahedouch self-requested a review August 8, 2023 20:37

fahedouch reviewed Aug 10, 2023

View reviewed changes

AkihiroSuda modified the milestones: v1.5.1, v1.5.2 Sep 11, 2023

AkihiroSuda removed this from the v1.6.1 (tentative) milestone Oct 8, 2023

fahedouch mentioned this pull request Nov 1, 2023

[Carry 2337] shutdown logger after exit #2621

Closed

fahedouch mentioned this pull request Mar 6, 2025

[carry #2337] ensure logger completion after container exit #3995

Merged

AkihiroSuda added a commit that referenced this pull request Mar 10, 2025

Merge pull request #3995 from fahedouch/carry-shutdown-logger-after-e…

7df4f3d

…xits [carry #2337] ensure logger completion after container exit

fahedouch closed this Apr 4, 2025

	"sh", "-euc", "for i in `seq 1 10`; do echo $i; sleep 1; done").AssertOK()
	"sh", "-euc", "for i in `seq 1 10`; do echo $i; done").AssertOK()

	defer base.Cmd("rm", containerName).Run()
	defer base.Cmd("rm", "-f", containerName).Run()

	exit, err := getContainerWait(ctx, hostAddress, config)
	exitCh, err := getContainerWait(ctx, hostAddress, config)

	return nil, fmt.Errorf("timed out waiting for container task to start")
	return nil, errors.New("timed out waiting for container task to start")

	ticker := time.NewTicker(100 * time.Millisecond)
	ticker := time.NewTicker(100 * time.Millisecond)
	defer ticker.Stop()

Conversation

mharwani commented Jun 29, 2023

Uh oh!

fahedouch commented Jul 10, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

mharwani commented Jul 11, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

fahedouch Jul 16, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

fahedouch Jul 23, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mharwani commented Jul 19, 2023

Uh oh!

AkihiroSuda commented Jul 21, 2023

Uh oh!

fahedouch left a comment

Choose a reason for hiding this comment

Uh oh!

AkihiroSuda commented Jul 31, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

fahedouch commented Aug 25, 2023

Uh oh!

AkihiroSuda commented Oct 8, 2023

Uh oh!

apostasie commented Aug 8, 2024

Uh oh!

fahedouch commented Feb 20, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

fahedouch commented Jul 10, 2023 •

edited

Loading

fahedouch Jul 16, 2023 •

edited

Loading

fahedouch Jul 23, 2023 •

edited

Loading