Fix FF_KUBERNETES_HONOR_ENTRYPOINT duplicating job logs on non-UTC nodes
What does this MR do?
Makes the Kubernetes entrypoint log forwarder recognize its pause and resume markers when the kubelet's timestamp ends in an offset such as +02:00, not only in Z. commandStatus looks for the space within the longest timestamp the kubelet writes and parses what comes before it with time.RFC3339Nano.
Why was this MR needed?
With FF_KUBERNETES_HONOR_ENTRYPOINT, entrypointLogForwarder forwards the build container's log stream and read-logs the build output from its log file; the forwarder pauses between a step's start and exit markers so that each line is logged once. Since !4883 (merged) the check takes the timestamp to be the first 30 bytes of the line, and since !5018 (merged) parses them with 2006-01-02T15:04:05.999999999Z, where the Z is a literal.
The kubelet parses the timestamp the container runtime wrote and writes it back in the same zone (cri-client logs.go, L245), and containerd writes time.Now() in its local zone (logger.go). On a node outside UTC the timestamp is 35 bytes long and no marker is recognized: every line of the step reaches the job log twice (the 00O and 01O pair in the issue), and the forwarder logs the markers, which read-logs keeps out.
@l2y's analysis in the issue found the check and proposed this fix; here the search for the space stops after the longest timestamp, so a long first word never reaches time.Parse. The check on main also reads past the end of a line of exactly 30 bytes and panics; I don't expect such a line from the kubelet, but the new test pins it.
What's the best way to test this MR?
go test ./executors/kubernetes/ -run TestEntrypointLogForwarder -count=1 -vThe forward, pause and resume case and the missing-space case now run for Z, +02:00, +00:00 and -05:00, and two cases are new: a marker after a first word that is not a timestamp, and lines too short for a timestamp and a space. On main (965334ce) the offset cases fail and the 30-byte line panics; with the change all pass.
I had no cluster outside UTC, so this is tested through the unit tests and the issue's job log. On one, the issue's config.toml and .gitlab-ci.yml should show each line once, on 01O, instead of on both 00O and 01O.
The new tests on main, without the fix
--- FAIL: TestEntrypointLogForwarder (0.00s)
--- FAIL: TestEntrypointLogForwarder/forward,_pause,_resume (0.00s)
--- PASS: TestEntrypointLogForwarder/forward,_pause,_resume/UTC (0.00s)
--- FAIL: TestEntrypointLogForwarder/forward,_pause,_resume/positive_offset (0.00s)
--- FAIL: TestEntrypointLogForwarder/forward,_pause,_resume/zero_offset (0.00s)
--- FAIL: TestEntrypointLogForwarder/forward,_pause,_resume/negative_offset (0.00s)
--- PASS: TestEntrypointLogForwarder/marker_after_something_other_than_a_timestamp (0.00s)
--- FAIL: TestEntrypointLogForwarder/lines_too_short_for_a_timestamp_and_a_space (0.00s)
panic: runtime error: index out of range [30] with length 30 [recovered, repanicked]With the short lines skipped, so that the panic does not stop the run:
--- FAIL: TestEntrypointLogForwarder/with_timestamp (0.00s)
--- PASS: TestEntrypointLogForwarder/with_timestamp/UTC (0.00s)
--- FAIL: TestEntrypointLogForwarder/with_timestamp/positive_offset (0.00s)
--- FAIL: TestEntrypointLogForwarder/with_timestamp/zero_offset (0.00s)
--- FAIL: TestEntrypointLogForwarder/with_timestamp/negative_offset (0.00s)The +02:00 case shows the markers forwarded and the paused lines kept:
--- Expected
+++ Actual
@@ -2,2 +2,6 @@
2024-07-25T11:50:54.008163908+02:00 2
+2024-07-25T11:50:54.008163908+02:00 {"script": "some/script"}
+2024-07-25T11:50:54.008163908+02:00 3
+2024-07-25T11:50:54.008163908+02:00 4
+2024-07-25T11:50:54.008163908+02:00 {"command_exit_code": 0}
2024-07-25T11:50:54.008163908+02:00 5Local checks
With Go 1.26.10, all pass: go build ./..., go vet ./executors/kubernetes/... ./shells/..., go vet -tags 'integration kubernetes' ./executors/kubernetes/, gofmt, make check_test_directives, go test -race ./executors/kubernetes/, go test ./executors/kubernetes/... ./shells/..., and golangci-lint 2.14.0 on ./executors/kubernetes/... (0 issues).
What are the relevant issue numbers?
Closes #39470 (closed)
Related to #38286 (closed), which reported the same duplication on 17.5.2 with +01:00 timestamps and was closed as inactive.