|
| 1 | +# Logging |
| 2 | + |
| 3 | +This page explains how `livekit-portal` logs and what each message means. |
| 4 | +Warnings and errors carry a short reference tag in square brackets. Find the |
| 5 | +tag below for the cause and the fix. |
| 6 | + |
| 7 | +## How logging works |
| 8 | + |
| 9 | +The library logs through the Rust [`log`](https://docs.rs/log) facade. The |
| 10 | +FFI layer initializes [`env_logger`](https://docs.rs/env_logger) once when |
| 11 | +the module loads. The default level is `info`. Timestamps print with |
| 12 | +millisecond precision. |
| 13 | + |
| 14 | +Set verbosity with the `RUST_LOG` environment variable before importing the |
| 15 | +library. |
| 16 | + |
| 17 | +```bash |
| 18 | +RUST_LOG=info python robot.py # default: lifecycle + warnings |
| 19 | +RUST_LOG=warn python robot.py # warnings and errors only |
| 20 | +RUST_LOG=livekit_portal=debug python ... # everything from this crate |
| 21 | +RUST_LOG=off python robot.py # silence the library |
| 22 | +``` |
| 23 | + |
| 24 | +The target name is the crate path. Use `livekit_portal` to scope a level to |
| 25 | +this library and leave other crates alone. |
| 26 | + |
| 27 | +## Log levels |
| 28 | + |
| 29 | +| Level | What you get | |
| 30 | +|-------|--------------| |
| 31 | +| `error` | A user callback panicked, or a send failed outright. The loop keeps running. | |
| 32 | +| `warn` | Something was dropped or ignored. The session continues, but quality or completeness suffered. | |
| 33 | +| `info` | Connection lifecycle. Connect, disconnect, track published, publisher ready. | |
| 34 | +| `debug` | Per-event detail. Off by default. | |
| 35 | + |
| 36 | +A healthy session at `info` is quiet after the startup lines. A steady run |
| 37 | +of `warn` lines means a stream or a buffer is under pressure. |
| 38 | + |
| 39 | +## Reference tags |
| 40 | + |
| 41 | +Every warning and error starts with a tag like `[sync-drop]`. The tag names |
| 42 | +the root cause, not the call site. Several messages can share one tag. |
| 43 | + |
| 44 | +To troubleshoot, copy the tag and find its section on this page. Each |
| 45 | +section is anchored by its tag. For `[sync-drop]`, that is |
| 46 | +`docs/logging.md#sync-drop`. |
| 47 | + |
| 48 | +Lifecycle `info` lines are not tagged. They are listed under |
| 49 | +[Connection lifecycle](#connection-lifecycle). |
| 50 | + |
| 51 | +## Logs vs metrics |
| 52 | + |
| 53 | +Logs tell you that something happened. Metrics tell you how much and how |
| 54 | +often. Every drop logged here is also counted in `portal.metrics()`, and |
| 55 | +that counter never throttles. When a warning is rate-limited, the metric is |
| 56 | +the source of truth for the exact total. |
| 57 | + |
| 58 | +Reach for `metrics()` when you want a number. Reach for the tag when you want |
| 59 | +the cause and the fix. See [Tuning](06-tuning.md) for the counters and the |
| 60 | +knobs they map to. |
| 61 | + |
| 62 | +## Tag reference |
| 63 | + |
| 64 | +### sync-drop |
| 65 | + |
| 66 | +``` |
| 67 | +[sync-drop] dropping states: no frame within ±10ms of the state timestamp (video 47ms ahead). Throttling further [sync-drop] warnings to once per 5s. |
| 68 | +[sync-drop] dropped 33 more states in 5s: no frame within ±10ms (video up to 51ms ahead). |
| 69 | +``` |
| 70 | + |
| 71 | +A state was dropped because no video frame landed inside its match window. |
| 72 | +The window is `±tolerance` ticks wide. The "video ahead" number is how far |
| 73 | +the video stream had already moved past the dropped state, which is why |
| 74 | +nothing matched. |
| 75 | + |
| 76 | +The first drop in a burst logs at once. Further drops fold into a summary |
| 77 | +emitted at most once every 5 seconds. `metrics.sync.states_dropped` counts |
| 78 | +every one. |
| 79 | + |
| 80 | +**Cause.** Video arrived later than state, stalled, or jittered by more than |
| 81 | +the match window. State kept flowing while video did not. |
| 82 | + |
| 83 | +**Fix.** |
| 84 | +- Raise `tolerance` to widen the match window. Aim for `tolerance ≥ 1` tick. |
| 85 | +- Raise `slack` to buffer through longer stalls. |
| 86 | +- Enable `reuse_stale_frames` to freeze on the last good frame instead of dropping. Use this for data collection. Leave it off for real-time control. |
| 87 | +- Check `metrics.sync.last_blocker_track` to see which camera is behind. |
| 88 | + |
| 89 | +See [Choosing `tolerance`](06-tuning.md#choosing-tolerance). |
| 90 | + |
| 91 | +### state-overflow |
| 92 | + |
| 93 | +``` |
| 94 | +[state-overflow] state buffer full (5), dropped 2 oldest. Further drops in this burst won't be re-logged. |
| 95 | +``` |
| 96 | + |
| 97 | +The state buffer hit its cap and shed its oldest entries. States piled up |
| 98 | +with no video frame to match against. This usually means a video track has |
| 99 | +stalled completely. It logs once per burst, not once per drop. |
| 100 | + |
| 101 | +**Fix.** Raise `slack` to tolerate longer stalls. Enable `reuse_stale_frames` |
| 102 | +if a frozen frame is acceptable. If video stopped entirely, the fix is at the |
| 103 | +robot, not in the buffer. |
| 104 | + |
| 105 | +### video-overflow |
| 106 | + |
| 107 | +``` |
| 108 | +[video-overflow] 'front' buffer full, evicted 3 frame(s) |
| 109 | +``` |
| 110 | + |
| 111 | +A video track's buffer hit its cap and dropped its oldest frames. This is |
| 112 | +normal when video arrives faster than state. The newest frames are kept, so |
| 113 | +sync still works. |
| 114 | + |
| 115 | +**Fix.** Usually nothing. If it pairs with `[sync-drop]`, the buffer is too |
| 116 | +shallow to bridge the two rates. Raise `slack`. The cumulative count is |
| 117 | +`metrics.buffers.evictions`. |
| 118 | + |
| 119 | +### publish-full |
| 120 | + |
| 121 | +``` |
| 122 | +[publish-full] topic 'state' queue full (cap=1024), dropping packet |
| 123 | +[publish-full] frame_video 'front' queue full (cap=1024), dropping frame |
| 124 | +``` |
| 125 | + |
| 126 | +The outbound queue for a topic, chunk, or frame-video track filled up and a |
| 127 | +packet was dropped before it left the machine. The link cannot ship data as |
| 128 | +fast as you are producing it. |
| 129 | + |
| 130 | +**Fix.** Lower the publish rate, the resolution, or the frame rate. Check the |
| 131 | +network. A persistent warning is sustained backpressure, not a spike. For |
| 132 | +frame video, track it with `metrics.transport.frames_dropped_publisher_full`. |
| 133 | +For lossy transport that sheds load instead of queuing, use a WebRTC video |
| 134 | +track. See [Frame video](05-frame-video.md). |
| 135 | + |
| 136 | +### publish-failed |
| 137 | + |
| 138 | +``` |
| 139 | +[publish-failed] data publish failed: <error> |
| 140 | +[publish-failed] chunk 'grip' byte stream failed: <error> |
| 141 | +[publish-failed] rtt publish failed: <error> |
| 142 | +``` |
| 143 | + |
| 144 | +A publish call returned an error from the transport. The room is |
| 145 | +disconnected, or the participant is gone. |
| 146 | + |
| 147 | +**Fix.** Expect these around a reconnect. If they persist, the session is not |
| 148 | +connected. Check connectivity and the token. |
| 149 | + |
| 150 | +### schema-mismatch |
| 151 | + |
| 152 | +``` |
| 153 | +[schema-mismatch] topic 'state': peer schema 0xAABBCCDD != ours 0x11223344, dropping packet |
| 154 | +``` |
| 155 | + |
| 156 | +The sender and receiver declared different schemas for the same topic. The |
| 157 | +packet is dropped because the layout cannot be trusted. Logged once per |
| 158 | +unique mismatch. |
| 159 | + |
| 160 | +**Fix.** Make the robot and operator declare the same fields, in the same |
| 161 | +order, with the same dtypes. A shared YAML config is the reliable way. See |
| 162 | +[Config from YAML](04-config-file.md). |
| 163 | + |
| 164 | +### unknown-field |
| 165 | + |
| 166 | +``` |
| 167 | +[unknown-field] topic 'state': field 'gripper2' not in schema, ignored |
| 168 | +``` |
| 169 | + |
| 170 | +You sent a field the schema does not declare. The field is dropped. The rest |
| 171 | +of the packet is sent. Logged once per offending key. |
| 172 | + |
| 173 | +**Fix.** Add the field to the schema, or stop sending it. Check for a typo in |
| 174 | +the field name. |
| 175 | + |
| 176 | +### saturated |
| 177 | + |
| 178 | +``` |
| 179 | +[saturated] topic 'state': field 'angle' clamped to U8 range |
| 180 | +``` |
| 181 | + |
| 182 | +A value did not fit the field's declared dtype and was clamped to the dtype |
| 183 | +range. For example, a value above 255 sent as a `U8`. Logged once per field. |
| 184 | + |
| 185 | +**Fix.** Widen the dtype, or scale the value before sending. |
| 186 | + |
| 187 | +### unknown-chunk |
| 188 | + |
| 189 | +``` |
| 190 | +[unknown-chunk] on_action_chunk: chunk 'grip' not declared, callback ignored |
| 191 | +[unknown-chunk] topic 'portal_action_chunk': unknown fingerprint 0x1A2B3C4D, dropping byte stream |
| 192 | +``` |
| 193 | + |
| 194 | +A chunk name or fingerprint does not match any declared chunk. Either you |
| 195 | +registered a callback for a chunk that was never declared, or a byte stream |
| 196 | +arrived for a chunk the receiver does not know. Receive-side warnings are |
| 197 | +capped at 256 unique fingerprints, then suppressed. |
| 198 | + |
| 199 | +**Fix.** Declare the chunk with the same name on both ends before registering |
| 200 | +the callback or sending. |
| 201 | + |
| 202 | +### unknown-track |
| 203 | + |
| 204 | +``` |
| 205 | +[unknown-track] on_video_frame: track 'side' not registered, callback ignored |
| 206 | +[unknown-track] frame_video: track 'side' not declared, dropping frame |
| 207 | +``` |
| 208 | + |
| 209 | +A video track name does not match any declared track. Either you registered |
| 210 | +a callback for an unknown track, or a frame arrived for a track the receiver |
| 211 | +does not know. |
| 212 | + |
| 213 | +**Fix.** Declare the track with `add_video` using the same name on both ends. |
| 214 | + |
| 215 | +### codec-mismatch |
| 216 | + |
| 217 | +``` |
| 218 | +[codec-mismatch] frame_video 'front': declared Mjpeg, got Png, dropping frame |
| 219 | +``` |
| 220 | + |
| 221 | +A frame arrived encoded with a codec that does not match the track's declared |
| 222 | +codec. The frame is dropped. |
| 223 | + |
| 224 | +**Fix.** Declare the same codec on both ends with `add_video`. |
| 225 | + |
| 226 | +### decode-failed |
| 227 | + |
| 228 | +``` |
| 229 | +[decode-failed] frame_video 'front': decode failed: <error> |
| 230 | +``` |
| 231 | + |
| 232 | +A frame's payload could not be decoded with the declared codec. The payload |
| 233 | +is malformed or truncated. The frame is dropped and the loop continues. |
| 234 | + |
| 235 | +**Fix.** A few of these around a reconnect are harmless. A steady stream |
| 236 | +points at a codec or encoder problem on the sender. |
| 237 | + |
| 238 | +### bad-payload |
| 239 | + |
| 240 | +``` |
| 241 | +[bad-payload] frame_video: bad header (<error>) |
| 242 | +[bad-payload] state deserialize failed: <error> |
| 243 | +[bad-payload] failed to read chunk byte stream: <error> |
| 244 | +``` |
| 245 | + |
| 246 | +A received payload could not be parsed. The header was malformed, the body |
| 247 | +failed to deserialize, or a byte stream read errored. The packet or frame is |
| 248 | +dropped and the loop continues. |
| 249 | + |
| 250 | +**Fix.** Usually a transport hiccup or a version skew between peers. If it |
| 251 | +persists, confirm both ends run the same portal version and the same schema. |
| 252 | + |
| 253 | +### callback-panic |
| 254 | + |
| 255 | +``` |
| 256 | +[callback-panic] observation callback panicked, event loop continues |
| 257 | +``` |
| 258 | + |
| 259 | +One of your registered callbacks raised. The library catches the panic so it |
| 260 | +does not take down the event loop, logs it, and keeps running. This covers |
| 261 | +`on_observation`, `on_drop`, `on_state`, `on_action`, the video-frame |
| 262 | +callbacks, and the operator-roster callbacks. |
| 263 | + |
| 264 | +**Fix.** Fix the exception in your callback. The library cannot report the |
| 265 | +line, so wrap the callback body in `try`/`except` and print a traceback to |
| 266 | +find it. |
| 267 | + |
| 268 | +## Connection lifecycle |
| 269 | + |
| 270 | +These `info` lines are not problems. They confirm the session is wired up. |
| 271 | +They are not tagged. |
| 272 | + |
| 273 | +| Message | Meaning | |
| 274 | +|---------|---------| |
| 275 | +| `[SESSION] connecting as ROLE to URL` | Connection attempt started. | |
| 276 | +| `[SESSION] connected as ROLE` | Connection succeeded. | |
| 277 | +| `[SESSION] published video track 'TRACK'` | A robot video track went live. | |
| 278 | +| `[SESSION] ready to publish state via MODE data (N fields)` | The state publisher is set up. | |
| 279 | +| `[SESSION] subscribed to video track 'TRACK'` | The operator is receiving a robot track. | |
| 280 | +| `disconnecting` | Disconnect started. | |
| 281 | + |
| 282 | +`SESSION` here is the session id, not a reference tag. If you connect and |
| 283 | +then see no `subscribed` or `ready` lines, the two peers are not seeing each |
| 284 | +other. Check the room name and the token. |
| 285 | +</content> |
0 commit comments