The k8s executor never stops when a container's last 2 log lines share a timestamp #3112
Ben McMahon opened 2 days ago

The signature

The build log ends at the init container's last line, Job working directory initialized. The build reads RUNNING until its job timeout. OneDev then marks it TIMED_OUT, and fails every job that depends on it.

It's not localized to any projects, and happens about 1 in 3 builds.

The cause

collectContainerLog, in server-core/src/main/java/io/onedev/server/util/KubernetesUtils.java. The lines below come from tag v16.5.8.

The method follows 1 container with kubectl logs --follow --timestamps=true. After each reconnect it resumes at --since-time. Line 225 accepts a line only when its timestamp comes strictly after the last accepted timestamp. The check for the end-of-log marker sits inside that gate:

225: if (timestamp == null || lastInstantRef.get() == null || timestamp.isAfter(lastInstantRef.get())) {
229:     if (exitCondition instanceof SeenMessage seenMessage && message.contains(seenMessage.getMessage())) {
234:             seenMessageRef.set(true);

cri-o gives 1 timestamp to every line that it writes in one flush. So when the marker carries the timestamp of the line before it, the method discards the marker and never sets seenMessageRef.

Then it seems like this loop cannot end:

265: if (seenMessageRef.get() || abortError.get()) {
267:     break;
268: } else if (exitCondition instanceof CommandCompleted || exitCondition instanceof SeenMessageOrCommandCompleted) {
269:     break;
270: } else {
272:     Thread.sleep(1000);   // reconnect at the same --since-time, with no end

The executor passes a plain SeenMessage for every container (KubernetesExecutor.java:992), so the code reaches neither break. The thread runs 1 kubectl logs a second against a container that already terminated and prints nothing more. It throws nothing, so the server logs nothing. Only the job timeout stops it.

The executor follows init first (KubernetesExecutor.java:746, :951). That is why the log always stops exactly there. The defect does not touch the pod, because this loop only watches it.

The code change was in ebb21682, on 2026-08-14, Nothing has touched the file since.

Reproducing

It might only be consistently possible to re-produce this using a mock, otherwise, a two node kubeadm cluster using crio should work given enough runs

1/1
Type
Bug
Priority
Normal
Assignee
Affected Versions
16.5.8+
Labels
No labels
Issue Votes (0)
Watchers (2)
Reference
OD-3112
Please wait...
Connection lost or session expired, reload to recover
Page is in error, reload to recover