livepeer / livepeer/go-livepeer

BYOC: spurious ERROR-level logs at every clean /stream/stop

Open
#3,922 0 comments 0 reactions 0 assignees View on GitHub
status: triage
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

Open the contributing 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.