File logger sometimes misses last log line sent from output extension

[nadiamoe]

Brief summary

In SM we use an output extension to output metrics in a particular format for our consumption. This output extension also outputs a log line for each check in the script:

https://github.com/grafana/synthetic-monitoring-agent/blob/d9a40a5294f7c94e15d15fdbbc8570ac8447b6c4/xk6/sm/output.go#L153

Which looks like this:

time="2024-07-12T21:11:22+02:00" level=info msg="check result" check="response code was 200" metric=checks_total scenario=default source=sm value=1

We have recently noticed, however, that in some executions this log line does not appear, for the same script.

I made a hacky script that runs k6 continuously and checks if the log line is missing, and this seems to happen once every ~100 iterations, meaning that in ~1% of the cases that log line is not printed.

With the reproduction script I was able to narrow down a bit what's going on:

• This does not seem to happen for log lines printed within the script via console.log, or at least not in 10k iterations
• This only happens when --log-output is a file
• This happens more often if --verbose is used.

Digging a bit I suspect the reason for this lies here:

k6/log/file.go

Lines 113 to 128 in 04b53e4

	select {
	case entry := <-h.loglines:
	if _, err := h.bw.Write(entry); err != nil {
	h.fallbackLogger.Errorf("failed to write a log message to a logfile: %w", err)
	}
	case <-ctx.Done():
	if err := h.bw.Flush(); err != nil {
	h.fallbackLogger.Errorf("failed to flush buffer: %w", err)
	}
	if err := h.w.Close(); err != nil {
	h.fallbackLogger.Errorf("failed to close logfile: %w", err)
	}
	return
	}

I suspect it might be possible for the context to get cancelled while there are still log lines on the channel. I crudely patched k6 to yell if there are still stuff on the channel when the context is done:

diff --git a/log/file.go b/log/file.go
index 6da7e94b..ab34e9f6 100644
--- a/log/file.go
+++ b/log/file.go
@@ -116,6 +116,12 @@ func (h *fileHook) Listen(ctx context.Context) {
 				h.fallbackLogger.Errorf("failed to write a log message to a logfile: %w", err)
 			}
 		case <-ctx.Done():
+			select {
+			case <-h.loglines:
+				h.fallbackLogger.Errorf("Pending log lines found")
+			default:
+			}
+
 			if err := h.bw.Flush(); err != nil {
 				h.fallbackLogger.Errorf("failed to flush buffer: %w", err)
 			}

Running the reproduction script, I can see Pending log lines found in the same execution where the log line is missing.

From what I can see, k6 is doing everything right concurrency wise, but I think this may be happening because logrus might be calling hooks on a separate goroutine, which is not synchronized with anything. If this were the case, it would explain this sometimes failing, as the output extension's Stop() method is invoked reasonably shortly before calling stopLoggers(), which triggers the cancellation of that context (by means of

k6/cmd/root.go

Line 277 in 04b53e4

cancel()

)

I'm not sure what a possible solution for this would look like.

k6 version

k6 v0.52.0 (go1.22.5, linux/amd64)

OS

Arch linux

Docker version and image (if applicable)

No response

Steps to reproduce the problem

1. Build k6 with an output extension that logs something on Stop()
2. Run any k6 script with --log-ouput=file=something and --verbose (--verbose makes it more likely to happen)
3. Repeat 2 100 times or so
4. Observe that sometimes, the log line is missing

Expected behaviour

Log lines should always be there.

Actual behaviour

Log line is sometimes missing.

[nadiamoe]

I've gave Logrus a closer look, and it doesn't seem to go async anywhere actually. The k6 stop sequence still looks correct to me. I have no idea how this can be happening 😕

[nadiamoe]

Kay, I have might found a flaw in the k6 logic for closing this logger. My understanding of how this works when k6 run is invoked

1. Root command's PersistentRunE runs. setupLoggers is called, whic calls setLoggerHook. A separate goroutine is spun up for Listen, which is the one consuming log entries.
2. The run function runs.
3. During run, the extension logs stuff. ⚠️ Logs are swallowed without waiting for them to be consumed by Listen because the channel is buffered. This is what I missed on my first analysis.
4. Run finishes, stopLoggers is called, and after some channel/context dance, the context Listen has is cancelled. The select inside randomly decided whether to suck pending log lines, or terminate.
5. If we're unlucky, pending lines remain in the buffered channel.

When the context is cancelled, it is not guaranteed that the channel is empty, but it is guaranteed that no more entries will be submitted to it. Therefore, draining it on context cancellation should be enough to fix this.

[mstoykov]

Hi, I looked into this and did some testing, and went to have lunch while you were commenting 😅 .

We do have async log handling in the file hook as it is based on the loki one - where you need to buffer log lines either way, and it was fairly important when it was developed that this doesn't block on console.log.

In retrospect both the loki, and the file implementation, likely doesn't need this that much. On the other hand we still need to flush/sync on exiting the process (especially on errors where we will use OsExit).

I tried to close the channel and it works, but looking over the code it seems like there could be raises on errosr where while we are closing, something still writes logs :(. So I don't think this is a good idea after all.

If the fix you proposed works well enough for your case I would prefer we do it like this and leave it as we would want to replace logrus ... one day. But that realistically won't be fast :(.

[nadiamoe]

there could be raises on errosr where while we are closing, something still writes logs :(. So I don't think this is a good idea after all.

If this happens, the patch I proposed will either ignore those logs, or keep consuming them until stopLoggers times out, if I'm not mistaken.

I'm personally not sure whether that's better than panicking, so I'll leave it up to your best judgement 😄

[mstoykov]

Panicking seems worse :).

And I am mostly talking about there being 1-2 more lines. Your code will only continue looping if there are continously more logs that it can't read fast enough. So ... likely a different kind of bug if that happens 😅