TELCORE-353: keep recorder stalls off the media path - #644
Draft
dev-ryanc wants to merge 10 commits into
Draft
Conversation
Adds three avformat.conf settings for network outputs (rtmp/rtmps/rtsp),
all defaulting to 0 (disabled) so this commit is a no-op at runtime:
network-rw-timeout default applied when the record command carries
no rw_timeout file parameter of its own
network-max-rw-timeout upper bound on a caller-supplied rw_timeout
network-connect-timeout connection establishment timeout
Settings are in milliseconds and converted to microseconds internally,
since the pre-existing rw_timeout file parameter is passed straight to
ffmpeg in its own units. Unparseable or negative values leave the
timeout disabled, so a bad config can never be more aggressive than the
current unbounded behaviour.
An unreachable or overloaded RTMP recorder could block the thread calling switch_core_file_open() for a long time: avio_open() performs the TCP connect and the full RTMP handshake synchronously. Production record commands do carry an rw_timeout, but at 15s, and that parameter governs reads and writes only -- it does not bound the connect, which falls back to ffmpeg's own 5s tcp default. Resolve an effective rw_timeout -- caller value if given, clamped by network-max-rw-timeout, otherwise the configured default -- and enforce network-connect-timeout ourselves through the interrupt callback rather than relying on ffmpeg, whose rw_timeout handling of the connect and handshake varies by protocol and version. This finishes the guard that TEL-5477 left half-written: connect_start_time was set but never read. Both the clamp and the default apply to network outputs only; local files keep their blocking semantics. Caller-supplied values are passed through verbatim so ffmpeg's suffixed forms keep working, and are only rewritten when clamped. Any option left in the dict after a successful open is logged, since that means the timeout is not actually in force on this ffmpeg build. Still off by default: all three settings default to 0. Also fixes a pre-existing leak of the options dict on the success path, which returns before the end: label where it was freed.
The connect was bounded, but everything after it still relied on ffmpeg's
rw_timeout -- the very mechanism whose handling we could not rely on across
protocols and versions. A recorder that accepts the connection and then
stops draining could still block the writing thread indefinitely.
Resolve the timeouts once at open and store them on the context, then arm
the same interrupt-callback deadline around the header write and each
frame write. Report the first timeout per handle and stay quiet after it,
since a stalled recorder would otherwise repeat the line every frame.
Scoped to audio RTMP, which is where recorder stalls have hurt:
- RTSP is excluded. Its muxer is AVFMT_NOFILE and connects from a
different place, and there is no recording traffic on it to justify
changing that path.
- Frame writes are bounded only when no video is present. With video,
the video thread writes to the same muxer under a different mutex
(eh.mutex vs mutex, eh.fc == fc), so a context-wide deadline would be
armed and disarmed by both threads. A bound that silently races is
worse than a documented gap; video keeps ffmpeg's rw_timeout, which is
still set on the handle.
The connect and header write are armed unconditionally: both run before
the video thread is created.
Covering RTSP and video is a follow-up, not a prerequisite.
thread_buffer is created with no maximum (switch_buffer_create_dynamic with max 0), so when the recording thread stalls -- typically blocked writing to an unresponsive recorder -- the queue grows for the remainder of the call. At roughly 16KB/s per recorded leg, a fleet-wide recorder stall turns a per-call problem into a per-box one. Cap it and discard the oldest audio on overflow. The recording is already damaged at that point, so keeping the live end is more useful than preserving a stale prefix, and the buffer settles at the ceiling instead of growing without limit. The discard is rounded up to a whole sample frame: dropping a partial one would byte-shift every sample after it and swap the channels in stereo, which is corruption rather than a gap. Configured by RECORD_BUFFER_MAX_MS per recording, falling back to the global record_buffer_max_ms so it can be set fleet-wide without every caller having to know about it. Unset means unbounded, as before. The value is parsed strictly and floored at 100ms, because a typo such as "2s" would otherwise yield a 2ms ceiling that discards audio on every frame while still looking like a working recording. The global is read with _pdup, since the plain getter returns the pointer after releasing the lock.
record_callback(SWITCH_ABC_TYPE_CLOSE) joins the recording thread with no timeout. When that thread is blocked writing to an unresponsive recorder, the session thread waits for as long as the write does, so a stalled recorder holds the channel up instead of just losing its recording. Add SCFC_ABORT_IO to switch_file_command_t, implemented in mod_av by setting a flag that interrupt_cb reports from whichever thread is blocked inside ffmpeg, and make av_file_write fail fast once it is set. The join itself is what lets the recording thread flush whatever is still queued, so it is not simply cut short: aborting unconditionally before it would truncate the tail of every healthy recording. Instead the close path signals the thread, waits up to a budget for it to finish on its own, and only aborts its I/O if it overruns -- so healthy recordings are untouched and only a wedged one is cut. Configured by RECORD_CLOSE_TIMEOUT_MS, falling back to the global record_close_timeout_ms. Unset means the previous untimed join. A dedicated abort_io flag is used rather than context->closed, which also drives read and video-ready logic in mod_av and is reset mid-life. Both this value and RECORD_BUFFER_MAX_MS are now bounded above as well as below: past INT_MAX a value truncates into an int and can land on a small positive number, which would turn a mistyped setting into an aggressively short timeout rather than a disabled one.
This is the change that stops recorder stalls from causing dead air. avio_open() performs the TCP connect and the RTMP handshake, and av_file_open ran it on whichever thread called switch_core_file_open. For a recording that is the session thread, so an unresponsive recorder stopped that call's media for as long as the connect took. The earlier commits bound how long that is; this one moves it off the media path. When the caller tells us a dedicated writer thread will drive the writes, av_file_open now records the target and returns immediately, and the connect happens on the first muxer write -- which runs on the recording thread. The session thread keeps forwarding RTP, and audio queues in the recording buffer (bounded by RECORD_BUFFER_MAX_MS) while the connection is established. The core states only what it knows -- that writes will be driven by a writer thread, using the same condition record_callback uses to decide whether to create one -- and mod_av decides whether to defer. The param is kept out of file_open_path so logs and events still name the recording as the caller wrote it. A deferred connect never runs on the way out: av_file_close sets closed before flushing, and ensure_output_open refuses in that state rather than dialling a recorder we are about to abandon. Also fixes the close path from the previous commit, which signalled the recording thread with a blocking mutex acquire. That thread holds cond_mutex across its writes, so the acquire waited out the very write the budget was meant to bound. trylock instead: failing to acquire means the thread is working rather than waiting, so there is nothing to wake. Off by default: network-async-open.
Found by end-to-end test against a black-hole recorder. Once a destination fails fast rather than blocking -- which is what the earlier commits make happen -- the recording thread loops: write fails instantly, log an error, repeat on the next frame. Measured at about fifty ERR lines per second per affected recording, for the remainder of the call. At the scale of the incident that is its own outage. Before these changes the same loop simply blocked, so the spin was unreachable; the pre-existing TODO here anticipated needing a threshold. Count consecutive write failures, rate limit the log, and abandon the recording once the failures have persisted past a grace period, since a destination that has been failing for a full second is not coming back within the call. A successful write clears the tally, so a brief hiccup still rides through. RECORD_STOP_WRITE_ON_ERROR keeps its meaning: stop on the first failure rather than waiting out the grace period. Verified against a stalled recorder: 500 error lines became 1, and the recording is dropped 1.0s after the first failure while the call keeps its media.
Two automated tests plus the rig for the case that needs a live call. avformat_network_connect_timeout_bounds_open opens an address in TEST-NET-1, which is guaranteed not routable, and asserts the open gives up inside the configured budget. Without a connect budget this runs to ffmpeg's own 5s tcp default, so the test fails if the guard regresses. It needs no server and does not depend on timing beyond that margin. avformat_local_file_unaffected_by_network_timeouts writes a local file for well past the configured network budget, covering the gating that keeps local recordings out of it -- a slow disk is not a stuck peer. The incident shape itself, a recorder that accepts the connection and then never answers, needs a call to observe, so it ships as a stand-in server and a written procedure rather than an automated test. The measurement is a local probe recording driven by the same session thread: its shortfall against wall clock is the media the call did not process.
Whole-branch review of the eight commits. Crash: a deferred connect that fails leaves fc->pb NULL, but av_file_write_video sets has_video before the header write that performs that connect, so av_file_close saw has_video and called av_write_trailer on a muxer with no output. Guard the trailer on the output existing. Timed-out writes surfaced far too late. The existing fast-fail shortcut only recognises EIO and ECONNRESET, while a write we abort ourselves returns AVERROR_EXIT, so a stalled recorder was reported as successful for another thousand frames -- around twenty seconds of a call -- before the error counter tripped. Treat our own timeout or abort as fatal at once. Video RTMP writes are now bounded too. They were skipped on the grounds that the video thread writes under a different mutex, which is wrong: av_file_write_video points eh.mutex at the same mutex the audio path uses, so the two writers are already serialised. The close budget now measures lack of progress rather than elapsed time. A thread draining a backlog to a slow but working recorder is doing exactly what the join exists to allow, and cutting it off discarded audio already captured; only a queue that has stopped shrinking means the writer is wedged. An overall cap keeps trickling progress from holding the channel up. The interrupt callback is no longer installed for plain local files, restoring what upstream did there. The corruption this was predicted to cause did not reproduce, but the callback has nothing to offer a local file and reporting closed during close is a hazard worth not carrying. Also: paced the local-file test so it genuinely outlasts the configured budget, and explained why an explicit abort deliberately applies to local handles when deadlines do not.
The give-up added with the retry fix was the one behaviour on this branch with no lever: every recording got a fixed 1s of tolerance for consecutive write failures. Expose it as RECORD_WRITE_ERROR_GRACE_MS per recording, falling back to the global record_write_error_grace_ms, defaulting to the same 1s. 0 gives up on the first failure; a value longer than any call effectively never gives up, which restores the previous behaviour for anyone who needs it. Unlike the other settings this one defaults to on, because the alternative default is retrying a dead destination on every frame. The give-up log now reports the elapsed time and the grace in force, since with a configurable value the error count alone does not say which setting produced it.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Recorder stalls should not cost a call its media.
The problem
Recordings are started from
execute_on_*, sorecord_sessionruns on the session thread:avio_open()performs the TCP connect and the full RTMP handshake synchronously, so while therecorder is unresponsive that thread is not forwarding RTP. The
rw_timeoutabove bounds the handshakeat 15s but does not bound the connect — measured against an unroutable address it made no difference
(5008ms vs 5009ms) and the connect fell back to ffmpeg's own 5s tcp default. So a stalled recorder cost
up to ~15s of dead air per call, and hangup could block for as long as a write did.
Three further sites made it worse: the untimed
switch_thread_join()at close, the drain loop thatfollows it, and
thread_buffer, which is created with no maximum and so grows for the rest of the call.What this does
Bound every recorder interaction, then move the one that matters off the media path:
rw_timeoutdoes not cover the connect and its handling of the handshake varies by buildrw_timeoutthread_bufferSCFC_ABORT_IOfile command when it really is wedgedEverything is off by default.
network-rw-timeout,network-max-rw-timeout,network-connect-timeoutand
network-async-openall default to 0/false inavformat.conf;record_buffer_max_msandrecord_close_timeout_msmean unbounded/wait-forever when unset. The one exception isrecord_write_error_grace_ms, which defaults to 1s rather than off, because the alternative default isretrying a dead destination on every frame — it is configurable, and a value longer than any call
restores the previous behaviour.
Measured
Against a stand-in recorder that accepts the TCP connection and never answers the handshake (the
incident's shape), with a probe recording on the same channel so any shortfall against wall clock is
media the call did not process:
Scope
AVFMT_NOFILE, it connects from a differentplace, and there is no recording traffic on it to justify changing that path.
local write would damage a good recording. An explicit
SCFC_ABORT_IOdoes still apply to them, sincerefusing it would leave a genuinely hung write with nothing to interrupt it and the caller waiting
forever.
Testing
test_avformatgains two cases: an unreachable recorder must give up inside the configured budget(measured 1002ms against a 1000ms setting; without the budget this runs to ffmpeg's 5s default), and a
local recording must be unaffected by the network settings. Suite passes 7/7.
(
test/blackhole_rtmp.py,test/README.stall-testing.md) rather than an automated test.case.
Rollback
Config only:
network-async-open=falseand the timeouts to 0 restores current behaviour withoutredeploying a binary.
Follow-ups
RTSP coverage, per-recorder timeout metrics and events (input to the alerting and CDR detection tickets),
and a per-recorder circuit breaker so not every call pays the timeout during an outage.