livepeer / livepeer/go-livepeer
BYOC: spurious ERROR-level logs at every clean /stream/stop
- Dominant language
- Go
- Stars
- 586
- Forks
- 226
- Avg merge
- 1d 17h
- Merged PRs (30d)
- 19
Description
## Symptom
Every clean `/process/stream/.../stop` produces a block of `ERROR`-level log lines that look like real failures but are not. Each component logs its reaction to ctx-cancellation as an error instead of recognising the cancel originated from us.
```text
# (1) ffmpeg subprocess output (Process err= line dumps captured stderr at INFO)
[in#0/flv] Error during demuxing: Input/output error
[out#0/flv] Error writing trailer: Broken pipe
Conversion failed!
# (2) Trickle subscriber preconnect cancelled mid-flight
ERROR failed to preconnect next segment ... err="...context canceled"
# (3) RTMP-to-segment stream-existence probe racing mediamtx teardown
ERROR Stopping segmentation ... err=StreamExists check failed: ... 404
# (4) Orchestrator trickle server reacting to runner closing its subscriber
ERROR Error sending data to client ... err="client disconnected"
```
Operationally costly (alerting / log search noise), misleading (looks like the stack failed when it didn't).
## Root cause
Parallel teardown — every component reacts simultaneously to the same `ctx.Done()` and logs the symptom of *its own dependency disappearing* without checking whether the cancel was self-induced.
## Fix sites + pattern
Same shape across all five: **check `ctx.Err() != nil` (or `errors.Is(err, context.Canceled)`, or `r.Context().Err() != nil` for HTTP handlers) before logging at `ERROR`; demote to `Debug` when cancellation was ours.** Each site is 3-5 lines.
| # | Location | Change |
|---|---|---|
| 1 | [`byoc/trickle.go:359-403`](https://github.com/livepeer/go-livepeer/blob/master/byoc/trickle.go#L359-L403) — `BYOCGatewayServer.ffmpegOutput` | Wrap the captured `output` log in `if ctx.Err() != nil { debug } else { info }` |
| 2 | [`server/ai_live_video.go:434-449`](https://github.com/livepeer/go-livepeer/blob/master/server/ai_live_video.go#L434-L449) | Duplicate of (1); same change. The byoc/trickle.go header comment notes this file is largely a copy. |
| 3 | [`trickle/trickle_subscriber.go:271`](https://github.com/livepeer/go-livepeer/blob/master/trickle/trickle_subscriber.go#L271) | `if errors.Is(err, context.Canceled) \|\| c.baseCtx.Err() != nil { debug } else { error }` |
| 4 | [`media/rtmp2segment.go:72`](https://github.com/livepeer/go-livepeer/blob/master/media/rtmp2segment.go#L72) | `if ctx.Err() != nil { debug } else { errorf }` |
| 5 | [`trickle/trickle_server.go:588`](https://github.com/livepeer/go-livepeer/blob/master/trickle/trickle_server.go#L588) — `Stream.handleGet` → `sendData` | `if r.Context().Err() != nil { debug } else { error }` — the `client disconnected` error string is constructed at line 542 from the same `r.Context().Done()`. |
## Open question on (1) / (2) — `cmd.Cancel`
A previous attempt (#3923, closed) also flipped `cmd.Cancel = func() error { return nil }` to let ffmpeg drain on stdin EOF instead of SIGTERM. That removes the noise at the *source* but **also removes a guaranteed termination path**: if the subscriber goroutine's `defer outWriter.Close()` ever doesn't fire, ffmpeg has no signal at all and `WaitDelay` doesn't kick in until I/O closes. Reverted.
A safer variant — fire SIGTERM after a short grace period giving stdin EOF a chance to propagate first — is the right end state but out of scope here. For now: just don't surface ffmpeg's stderr when we caused the exit.
## Out of scope
- Multiplexing / replacing ffmpeg with native FLV muxing.
- Real teardown sequencing (covered by #3924 for the data-channel race that *does* lose records).
- Other call sites that capture subprocess stderr verbatim — audit if needed.
## Context
Surfaced while implementing the [Python Pipeline SDK](https://github.com/livepeer/livepeer-python-gateway) — every example's logs include these blocks at every stop. Tracked under #3913 as an implementation-polish sibling.
**Note:** site for the gateway data-channel subscriber teardown race that *also* drops the final `emit_data` record was originally bundled here as site #6. Split out into #3924 — the impact (data loss) and fix (drain logic) are categorically different from these log-cosmetic fixes.
Contributor guide
Research direction
Start by reading the five listed locations: byoc/trickle.go, server/ai_live_video.go, trickle/trickle_subscriber.go, media/rtmp2segment.go, and trickle/trickle_server.go. Trace each teardown path and its context cancellation check, while leaving the cmd.Cancel question out of scope. Done means clean stream stops no longer produce ERROR-level noise, while genuine failures remain at ERROR.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go
- Domain
- backend, observability
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Quiet
- Clarity
- Clearly specified
- Newbie friendliness
- 72/100