fix(plugins): servo host logging, bounded reply waits, first-frame instrumentation - #668
Conversation
…ts, add first-frame instrumentation Signed-off-by: streamkit-devin <devin@streamkit.dev>
🤖 Devin AI EngineerI'll be helping with this pull request! Here's what you should know: ✅ I will automatically:
Note: I can only respond to comments from users who have write access to this repository. ⚙️ Control Options:
|
![staging-devin-ai-integration[bot]](https://avatars.githubusercontent.com/in/870844?s=60&v=4){kind=small}
| fn recv_reply_within( | ||
| result_rx: &std::sync::mpsc::Receiver<ServoThreadResult>, | ||
| timeout: Duration, | ||
| ) -> Result<ServoThreadResult, String> { | ||
| match result_rx.recv_timeout(timeout) { | ||
| Ok(result) => Ok(result), | ||
| Err(std::sync::mpsc::RecvTimeoutError::Timeout) => Err(format!( | ||
| "No reply from Servo thread within {timeout:?} — a reply was likely dropped" | ||
| )), | ||
| Err(std::sync::mpsc::RecvTimeoutError::Disconnected) => { | ||
| Err("Servo thread result channel closed".to_string()) | ||
| }, | ||
| } | ||
| } |
There was a problem hiding this comment.
📝 Info: Timed-out replies stay queued and shift subsequent replies by one
recv_reply returns an error on timeout but the dropped/late reply is not drained, so a delayed Frame/Status stays in the 2-slot channel. In practice this is harmless because the host treats a tick error as fatal (crates/plugin-native/src/wrapper.rs:2090-2106 sets NodeState::Failed and breaks the tick loop), so no further requests are issued on that receiver. Worth being aware of if tick errors ever become non-fatal: the node would then consume the previous request's reply.
Was this helpful? React with 👍 or 👎 to provide feedback.
Debug
There was a problem hiding this comment.
Acknowledged — a timed-out reply stays queued, which is safe today because the host treats a tick error as fatal and stops issuing requests on that receiver. If tick errors ever become non-fatal, the receiver would need draining (or a request/reply correlation id) first.
| let mut instances: HashMap<NodeId, InstanceState> = HashMap::new(); | ||
| // Fallback for diagnostics when the instance is gone (or was never | ||
| // created): the most recently registered instance's logger. | ||
| let mut thread_logger: Option<Logger> = None; |
There was a problem hiding this comment.
📝 Info: Cloned Logger crossing to the shared thread is safe with current hosts
The Logger moved into ServoWorkItem::Register outlives the node instance (the shared thread keeps it in InstanceState and as thread_logger fallback, never cleared on Unregister). This is safe only because the native host passes a null user_data (crates/plugin-native/src/wrapper.rs:1180) and the callback routes to the process-global tracing dispatcher; if a future host ever passes an instance-scoped user_data, the retained fallback logger becomes a use-after-free. Also note the SDK's clone caveat (sdks/plugin-sdk/native/src/lib.rs:601-615): these clones never receive the log-enabled callback, so plugin_debug! on the shared thread always formats before the host filters — a minor cost on the per-300-frame metrics line only.
Was this helpful? React with 👍 or 👎 to provide feedback.
Debug
There was a problem hiding this comment.
Correct — this relies on the native host passing null user_data and routing to the process-global tracing dispatcher. If a host ever passes instance-scoped user_data, retained loggers would need lifecycle management (e.g. dropping them on Unregister). The missing enabled-callback on clones only affects the per-300-frame debug line's formatting cost.
| /// Upper bound on waiting for a reply from the shared Servo thread. The | ||
| /// thread answers every request in bounded time (renders take milliseconds; | ||
| /// registration defers the page load), so hitting this means a reply was | ||
| /// dropped — fail the call instead of parking the tick thread forever. | ||
| const REPLY_TIMEOUT: Duration = Duration::from_secs(30); |
There was a problem hiding this comment.
🔍 30s reply timeout converts shared-thread saturation into a hard node failure
A tick error from request_frame/request_status is fatal on the host side: the source loop emits NodeState::Failed and breaks (crates/plugin-native/src/wrapper.rs:2090-2106). Because all instances share a single renderer thread with an unbounded work queue, sustained multi-instance load that pushes reply latency past REPLY_TIMEOUT would kill capture nodes that previously merely ran slow. The host's own backstop is 5 minutes (crates/plugin-native/src/wrapper.rs:165), so 30s is the binding limit here — this matches the PR's own review checklist item.
Was this helpful? React with 👍 or 👎 to provide feedback.
Debug
There was a problem hiding this comment.
Yes — 30s is deliberately generous (renders are milliseconds; the previous behavior was an unbounded hang) but it does turn extreme shared-thread saturation into a node failure. If that ever bites, the constant can be raised toward the host's 5-minute backstop or made config-driven; flagged in the PR checklist for reviewer judgment.
…e first-frame log on page_painted Signed-off-by: streamkit-devin <devin@streamkit.dev>
| if page_painted(state) && !state.content_frame_logged { | ||
| state.content_frame_logged = true; | ||
| // A painted-but-blank surface distinguishes an early/empty paint | ||
| // signal from a late paint when diagnosing black capture starts. | ||
| let blank = frame.iter().all(|&b| b == 0); | ||
| plugin_info!( | ||
| state.logger, | ||
| "[{node_id}] First painted frame read: pre_paint_frames = {}, since_first_render = {:?}, blank_surface = {blank}", | ||
| state.pre_paint_frames, | ||
| state.first_render_at.map(|at| at.elapsed()).unwrap_or_default() | ||
| ); | ||
| } |
There was a problem hiding this comment.
📝 Info: Blank-surface scan is one-shot per page and bounded by frame size
frame.iter().all(|&b| b == 0) scans the entire RGBA buffer, but it only runs once per page (guarded by content_frame_logged, which is reset on URL change and viewport resize), so the cost is not on the steady-state per-frame path. Note the scan runs unconditionally at the host's info level regardless of whether the log level is enabled, which for very large output sizes is a one-time multi-megabyte read — acceptable, but not free.
Was this helpful? React with 👍 or 👎 to provide feedback.
Debug
There was a problem hiding this comment.
Acknowledged — the scan is one-shot per page, so the cost was accepted for diagnostic value. Could be gated on logger.enabled(Info) if it ever matters, but clones currently lack the enabled callback anyway.
| /// Logger for diagnostics about `node_id`: the instance's own logger, or | ||
| /// the most recently registered instance's as a fallback. | ||
| fn node_logger<'a>( | ||
| instances: &'a HashMap<NodeId, InstanceState>, | ||
| fallback: Option<&'a Logger>, | ||
| node_id: &NodeId, | ||
| ) -> Option<&'a Logger> { | ||
| instances.get(node_id).map(|s| &s.logger).or(fallback) | ||
| } |
There was a problem hiding this comment.
📝 Info: Thread-wide fallback logger attributes diagnostics to the last registered node
thread_logger keeps the most recently registered instance's Logger, and node_logger falls back to it when the instance is gone. Since each host Logger carries the registering node's target/context, diagnostics for an unknown or removed node will be emitted under an unrelated node's log target. The [{node_id}] prefix mitigates confusion, but log filtering/routing per node will still attribute these lines to the wrong node.
Was this helpful? React with 👍 or 👎 to provide feedback.
Debug
There was a problem hiding this comment.
True — the fallback logger only fires for events with no live instance (panics for unknown/removed nodes, thread shutdown), where per-node attribution is impossible by definition; the [{node_id}] prefix carries the real identity. All normal-path diagnostics use the instance's own logger.
…ions emit transparent frames Signed-off-by: streamkit-devin <devin@streamkit.dev>
Signed-off-by: streamkit-devin <devin@streamkit.dev>
| "id": "servo", | ||
| "name": "Servo Web Renderer", | ||
| "version": "0.2.3", | ||
| "version": "0.2.4", |
There was a problem hiding this comment.
📝 Info: Version bump now consistent across manifest and marketplace
The marketplace entry for the servo plugin is bumped to 0.2.4, matching plugins/native/servo/plugin.yml:7 and plugins/native/servo/Cargo.toml:7, so the three version declarations stay in sync.
Was this helpful? React with 👍 or 👎 to provide feedback.
Debug
|
Tested at 86f01d5 via the web-capture gateway (plugin rebuilt + skit restarted). Devin session: https://staging.itsdev.in/sessions/f29bf33bf0184c92a23f81e695642b4a Results
URL tune before/after + theverge.com post-paint branch
Notes
|
2 participants
Summary
Loggerinstead oftracing(the plugin dylib has no subscriber, so all its diagnostics were silently dropped).ServoWorkItem::Registercarries the instance's logger; the thread keeps the most recently registered logger as a fallback for events with no live instance.request_frame/request_status/init now use a boundedrecv_timeout(30s) instead of a blockingrecv(), so a dropped reply degrades to a tick error instead of parking the node's tick thread forever. The one path that structurally cannot reply (render/status for an unknown instance) now logs an error instead of being silent.blank_surface) — distinguishing an "early paint signal on an empty surface" from a late paint. Combined with Expose shared Servo thread logs to skit host logging #665, the node-side gate-branch logs (load-complete / post-paint-settle / timeout) are now actually visible in the skit log.Review & Validation
just lint-plugins(servo crate: fmt + clippy-D warnings) — passing locally.cross_session_leakintegration test (real engine, software rendering) pass locally.REPLY_TIMEOUTis comfortably above worst-case shared-thread latency under multi-instance load.[<node_id>]-prefixed servo logs now appear in the skit log, including the "First painted frame read" line.Notes
Link to Devin session: https://staging.itsdev.in/sessions/f29bf33bf0184c92a23f81e695642b4a
Requested by: @streamer45
Devin Review
3284555