fix: shutdown logger after container process exits #2337

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

cmd/nerdctl/container_logs_test.go

+	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

cmd/nerdctl/container_logs_test.go

+	}
+
+	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

cmd/nerdctl/container_logs_test.go

+	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

cmd/nerdctl/container_logs_test.go

+	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

cmd/nerdctl/container_logs_test.go

@@ -143,3 +143,49 @@ func TestLogsWithFailingContainer(t *testing.T) {
 	base.Cmd("logs", "-f", containerName).AssertNoOut("baz")
 	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.

cmd/nerdctl/container_logs_test.go

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

pkg/cmd/container/logs.go

@@ -90,6 +91,8 @@ func Logs(ctx context.Context, client *containerd.Client, container string, opti
 						// Setup goroutine to send stop event if container task finishes:
 						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

pkg/logging/logging.go

 	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

pkg/logging/logging.go

+	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

pkg/logging/logging.go

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

pkg/cmd/container/create.go

@@ -639,8 +639,9 @@ func writeCIDFile(path, id string) error {
 }

 // 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

pkg/logging/logging.go

@@ -234,11 +246,24 @@ func loggerFunc(dataStore string) (logging.LoggerFunc, error) {
 			if err != nil {
 				return err
 			}
-			if err := ready(); err != nil {
+
+			lockFile := getLockPath(dataStore, config.Namespace, config.ID)


may be loggerLock is more explicit here

Signed-off-by: Mrudul Harwani <[email protected]>

…ocessed data Signed-off-by: Mrudul Harwani <[email protected]>

Signed-off-by: Mrudul Harwani <[email protected]>

AkihiroSuda · 2023-08-02T06:53:46Z

pkg/logging/logging.go

-	LogURI string            `json:"-"`
+	Driver      string            `json:"driver"`
+	Opts        map[string]string `json:"opts,omitempty"`
+	HostAddress string            `json:"host"`


Suggested change

HostAddress string `json:"host"`

ContainerdAddress string `json:"containerdAddress"`

Ideally log-config.json should not contain the address, but it can be refactored later

do we need a default value for HostAddress ?

cmd/nerdctl/container_logs_test.go

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

pkg/logging/logging.go

-	LogURI string            `json:"-"`
+	Driver      string            `json:"driver"`
+	Opts        map[string]string `json:"opts,omitempty"`
+	HostAddress string            `json:"host"`


do we need a default value for HostAddress ?

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

pkg/logging/logging.go

+	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

pkg/logging/logging.go

+
+	// 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?

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 <[email protected]>

add tests for the logging changes

5d5aa5c

Signed-off-by: Mrudul Harwani <[email protected]>

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

6316ae9

…ocessed data Signed-off-by: Mrudul Harwani <[email protected]>

minor changes to address review feedback

17a33f9

Signed-off-by: Mrudul Harwani <[email protected]>

implement method to wait for logger exit

808dd0c

Signed-off-by: Mrudul Harwani <[email protected]>

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 <[email protected]>

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

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

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: shutdown logger after container process exits #2337

fix: shutdown logger after container process exits #2337

mharwani commented Jun 29, 2023

fahedouch commented Jul 10, 2023 •

edited

Loading

mharwani commented Jul 11, 2023

fahedouch Jul 16, 2023

fahedouch Jul 16, 2023

mharwani Jul 19, 2023

fahedouch Jul 16, 2023

fahedouch Jul 16, 2023

fahedouch Jul 16, 2023 •

edited

Loading

mharwani Jul 19, 2023

fahedouch Jul 16, 2023

mharwani Jul 19, 2023

fahedouch Jul 23, 2023 •

edited

Loading

mharwani Jul 27, 2023

mharwani Jul 31, 2023

fahedouch Jul 16, 2023

fahedouch Jul 16, 2023

fahedouch Jul 16, 2023

mharwani Jul 19, 2023

fahedouch Jul 16, 2023

mharwani Jul 19, 2023

mharwani commented Jul 19, 2023

AkihiroSuda commented Jul 21, 2023

fahedouch left a comment

AkihiroSuda commented Jul 31, 2023

fahedouch Jul 31, 2023

AkihiroSuda Aug 2, 2023

fahedouch Aug 10, 2023

fahedouch Aug 10, 2023

fahedouch Aug 10, 2023

fahedouch Aug 10, 2023

fahedouch commented Aug 25, 2023

AkihiroSuda commented Oct 8, 2023

apostasie commented Aug 8, 2024

	"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)

	HostAddress string `json:"host"`
	ContainerdAddress string `json:"containerdAddress"`

	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()

fix: shutdown logger after container process exits #2337

Are you sure you want to change the base?

fix: shutdown logger after container process exits #2337

Conversation

mharwani commented Jun 29, 2023

fahedouch commented Jul 10, 2023 • edited Loading

mharwani commented Jul 11, 2023

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

fahedouch Jul 16, 2023 • edited Loading

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

fahedouch Jul 23, 2023 • edited Loading

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

mharwani commented Jul 19, 2023

AkihiroSuda commented Jul 21, 2023

fahedouch left a comment

Choose a reason for hiding this comment

AkihiroSuda commented Jul 31, 2023

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

fahedouch commented Aug 25, 2023

AkihiroSuda commented Oct 8, 2023

apostasie commented Aug 8, 2024

fahedouch commented Jul 10, 2023 •

edited

Loading

fahedouch Jul 16, 2023 •

edited

Loading

fahedouch Jul 23, 2023 •

edited

Loading