Skip to content

Bound the pod log read in Task readOutputs - #1798

Merged
gjkim42 merged 1 commit into
kelos-dev:mainfrom
sperano:fix/task-log-read-timeout
Oct 9, 2026
Merged

gjkim42 merged 1 commit into
kelos-dev:mainfrom
sperano:fix/task-log-read-timeout

Conversation

@sperano

@sperano sperano commented Oct 7, 2026 •

Copy link
Copy Markdown
Contributor

What type of PR is this?

/kind bug

What this PR does / why we need it:

TaskReconciler.readOutputs reads the tail of a finished pod's log through the reconcile context. That context has no deadline. If the API server never answers the log request, Stream() blocks forever. The Task controller runs a single worker, so from then on no Task is reconciled.

We hit this in production on v0.58.0. For 108 minutes, newly created Tasks stayed at status: null, with no finalizer and no Job. The controller pod stayed Running and Ready, so nothing flagged the problem. Only a restart of kelos-controller-manager cleared it.

A goroutine dump taken with SIGQUIT showed the only Task worker blocked in readOutputs. Its HTTP/2 request goroutine had already written the request and was waiting for response headers that never came:

Goroutine dump (trimmed)
goroutine 874 [select, 108 minutes]:
golang.org/x/net/http2.(*ClientConn).roundTrip(...)
	golang.org/x/net@v0.48.0/http2/transport.go:1397
...
k8s.io/client-go/rest.(*Request).Stream(...)
	k8s.io/client-go@v0.35.1/rest/request.go:921
github.com/kelos-dev/kelos/internal/controller.(*TaskReconciler).readOutputs(...)
	internal/controller/task_controller.go:1065
github.com/kelos-dev/kelos/internal/controller.(*TaskReconciler).updateStatus(...)
	internal/controller/task_controller.go:924
github.com/kelos-dev/kelos/internal/controller.(*TaskReconciler).Reconcile(...)
	internal/controller/task_controller.go:202
sigs.k8s.io/controller-runtime/pkg/internal/controller.(*Controller[...]).Reconcile(...)
	sigs.k8s.io/controller-runtime@v0.23.1/pkg/internal/controller/controller.go:222
...

goroutine 667803 [select, 108 minutes]:
golang.org/x/net/http2.(*clientStream).writeRequest(...)
	golang.org/x/net@v0.48.0/http2/transport.go:1566
golang.org/x/net/http2.(*clientStream).doRequest(...)
	golang.org/x/net@v0.48.0/http2/transport.go:1427
created by golang.org/x/net/http2.(*ClientConn).roundTrip in goroutine 874

Both of those waits also return when the request context is cancelled. This PR wraps the context in readOutputs with a 15s timeout (podLogReadTimeout), which bounds both Stream() and the body read. When the read fails, readOutputs returns no outputs, as it already does for any log error, and the existing output retry (outputRetryWindow / outputRetryInterval) tries again.

Which issue(s) this PR is related to:

N/A

Special notes for your reviewer:

  • TestReadOutputsParsesLogTail covers the happy path. A real clientset is pointed at an httptest server, and the test checks the request path, container and tailLines, plus the parsed outputs and results.
  • TestReadOutputsTimesOutOnHungLogStream uses a server that accepts the request and never responds, the same state as in the dump. It checks that readOutputs returns no outputs within the timeout. The test fails against the code before this change. podLogReadTimeout is a package variable so the test can shorten it to 100ms; the production value is 15s.
  • WorkerPoolReconciler.readPodOutputs has the same unbounded log read. I left it out to keep this change focused, and I'm happy to follow up.
  • Ran make update (no changes), make verify, make test, make test-integration and make build. All pass.

Does this PR introduce a user-facing change?

Fixed the Task controller stopping all Task reconciliation when a request for a finished pod's logs never received a response. The log read now times out after 15 seconds.

@cubic-dev-ai cubic-dev-ai Bot left a comment •

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All reported issues were addressed across 2 files

Reply to a comment to ask cubic a question or push back. It learns from your replies.

Turn on auto-fix | Re-trigger cubic

readOutputs streamed a finished pod's log tail with the reconcile
context, which has no deadline. If the log stream to the API server
hangs, the call never returns and the Task controller's single worker
stops reconciling every Task until the controller restarts.

Wrap the log request in a 15s timeout. A failed read already returns no
outputs, and the existing output retry tries again.
@gjkim42

gjkim42 commented Oct 9, 2026

Copy link
Copy Markdown
Collaborator

the bug seems serious. Thanks for the report.

/kelos review

@kelos-bot

kelos-bot Bot commented Oct 9, 2026 •

Copy link
Copy Markdown
Contributor

🤖 Kelos Task Status

Task kelos-reviewer-issue-comment-f7fa192a0907 has succeeded. ✅

@kelos-bot

kelos-bot Bot commented Oct 9, 2026

Copy link
Copy Markdown
Contributor

🤖 Kelos Reviewer Agent @gjkim42

Review Summary

Verdict: APPROVE
Overall correctness: patch is correct
Scope: Puts a 15s timeout (podLogReadTimeout) on the pod log read in TaskReconciler.readOutputs, so a log request that never gets a response can no longer block the Task controller's only worker. Adds happy-path and hung-stream unit tests.

Findings Overview

Priority Count File:Line Summary
P0 0 — none
P1 0 — none
P2 0 — none
P3 0 — none

Findings

No qualifying findings.

Reviewed against PR head e2b9d03:

  • Correctness: context.WithTimeout at internal/controller/task_controller.go:1065 covers the whole request, including the wait for response headers in Stream() and the body read in io.ReadAll. client-go does not retry once the context has expired. When the read fails, readOutputs returns (nil, nil), and updateStatus already handles that by requeueing on outputRetryInterval until outputRetryWindow closes. No other code path changes.
  • Tests: TestReadOutputsParsesLogTail covers the happy path with real assertions on the request path, container and tailLines, plus the parsed outputs and results. TestReadOutputsTimesOutOnHungLogStream reproduces the state from the goroutine dump (request sent, headers never arrive). Without the fix, the handler only returns after hangBudget and the test fails on both the elapsed-time check and the handler's t.Errorf, so it does guard the regression. Overriding the package variable is safe: the test is not parallel, cleanup restores the value, and the package's t.Parallel() tests (in session_controller_test.go) never read it.
  • Conventions: The PR follows the template and /kind bug fits. The commit message has no PR link. The release note describes the user-visible fix. The new comment explains why the timeout exists rather than restating the code.

Suggestions (optional)

  • [P3] internal/controller/task_controller_test.go:2202 — The hung-stream test only covers the case where response headers never arrive, so only Stream() is tested. The PR description also says the timeout bounds the body read. A second handler that sends headers and then stalls would cover the io.ReadAll path too: call w.WriteHeader(http.StatusOK) and w.(http.Flusher).Flush(), then block on <-req.Context().Done(). A server that stalls mid-body after the kubelet proxy has started streaming is a separate way to hang.
  • [P3] internal/controller/task_controller.go:1075 — A timed-out read is logged at V(1), the same as any other log error, so it is invisible at default verbosity. Since the incident was hard to detect, consider logging context.DeadlineExceeded at the default level. Repeated timeouts would then point operators to a slow log endpoint before Tasks start losing outputs, results or usage.

Key takeaways

  • The fix is minimal and correctly bounds the hang. With the defaults, a log endpoint that keeps hanging now holds the single Task worker for about 15s per attempt and roughly 45–60s per completed Task across the retry window. That is a bounded slowdown instead of a complete stall.
  • WorkerPoolReconciler.readPodOutputs (internal/controller/workerpool_controller.go:1440) has the same unbounded Stream(ctx) + io.ReadAll pattern. The author already mentioned it. A tracking issue or a quick follow-up would close the same failure mode there.

@gjkim42
gjkim42 enabled auto-merge October 9, 2026 16:28
@gjkim42
gjkim42 added this pull request to the merge queue Oct 9, 2026
Merged via the queue into kelos-dev:main with commit 7b886ec Oct 9, 2026
33 checks passed

This branch was successfully deployed

1 active deployment
ok-to-test — e2b9d036 Deployed Oct 7, 2026 by sperano via fork-e2e / e2e-with-environment #1844
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants