From 46bba0d134a530bdc2a0e778f0a11077b82452d8 Mon Sep 17 00:00:00 2001 From: mwiegand Date: Wed, 20 May 2026 00:19:50 +0200 Subject: [PATCH] docs(log-streaming): record that L4D2 logaddress UDP emit is dead MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Investigation 2026-05-20: deployed listener captures nothing in production. Diagnostics (strace + tcpdump) prove srcds makes ZERO sendto calls toward registered logaddress destinations even though the cvar API reports "logging to udp" and logaddress_list shows the entry. File and console sinks work fine; the UDP path is silently stubbed at the engine level (same family as broken L4D2 SourceTV). Listener and cfg injection retained for a future SourceMod bridge that uses LogMessage() — that path does reach UDP destinations on other Source 1 games. Also drops mp_logdetail 3 (CS-only; L4D2 prints "Unknown command"). Co-Authored-By: Claude Opus 4.7 (1M context) --- ...6-05-19-log-streaming-and-temp-listener.md | 79 +++++++++++++++++-- l4d2web/l4d2web/services/l4d2_facade.py | 15 ++-- l4d2web/l4d2web/services/log_listener.py | 11 +++ l4d2web/tests/test_l4d2_facade.py | 8 +- 4 files changed, 97 insertions(+), 16 deletions(-) diff --git a/docs/superpowers/plans/2026-05-19-log-streaming-and-temp-listener.md b/docs/superpowers/plans/2026-05-19-log-streaming-and-temp-listener.md index aca7682..e9f158e 100644 --- a/docs/superpowers/plans/2026-05-19-log-streaming-and-temp-listener.md +++ b/docs/superpowers/plans/2026-05-19-log-streaming-and-temp-listener.md @@ -232,13 +232,78 @@ End-to-end smoke test, on the dev box first: filename, that's enough for now. - Long-running stability past a few days — listener is temp. +## Post-deploy verification findings (2026-05-20) + +The plan above describes what we INTENDED to ship; this section +documents what we ACTUALLY learned after deployment. + +Listener was deployed and confirmed bound (`ss -ulnp` showed +`gunicorn:28000`). Servers were re-initialized, `server.cfg` +inspected and confirmed correct — `log on`, `logaddress_add +127.0.0.1:28000` at the bottom, after `rcon_password`. The listener +was proven healthy end-to-end with a local `nc` probe writing a +capture file. **Yet captures stayed empty even during active play.** + +Diagnostic steps: + +1. `logaddress_list` via RCON → `1 entry: 127.0.0.1:28000` ✓ +2. `log` via RCON → `currently logging to: file, console, udp` ✓ +3. Local `.log` files in + `/var/lib/left4me/runtime//merged/left4dead2/logs/` grow + normally; rich gameplay events show in `journalctl -u + left4me-server@` (bot connect, team join, spawn, character + pick — full HL-Log-Standard verbosity) ✓ +4. `tcpdump -i lo udp port 28000` during rcon say/echo/status bursts + → **0 packets** ✗ +5. `tcpdump -i any host 127.0.0.1 and udp` → still 0 ✗ +6. Toggle `log off` / `log on` live → engine confirms cycle, no + effect ✗ +7. `sv_logflush 1` live → no effect ✗ +8. Suspected `SocketBindAllow=udp:27000-27999` was blocking the + implicit ephemeral bind of a separate log socket. Added drop-in + `SocketBindAllow=udp:32768-60999`, daemon-reloaded, restarted + server → still 0 packets ✗. Drop-in rolled back. +9. `strace -p -e sendto,sendmsg` while triggering + events → **zero sendto/sendmsg calls toward 127.0.0.1:28000**. + Only one unrelated TLS sendmsg (Steam) ✗. + +**Verdict:** L4D2's vanilla UDP logaddress emit path is +stubbed/broken at the engine level. The cvar API and registration +paths are intact (data-structure ops); the emit path simply doesn't +make the syscalls. Logs reach the **file** and **console** sinks +(the latter is what `journalctl` captures from srcds_run's stdout) +but never the **udp** sink, despite all three being listed in the +`log` cvar status. Same family of issue as L4D2's broken SourceTV +(see `shqke/sourcetvsupport`). + +**Implications for the roadmap:** + +- The current listener captures nothing in production. The cfg + injection of `log on` / `logaddress_add` does no harm and is kept + for a future bridge to attach to. +- Phase 2 path A (recommended): **SourceMod bridge plugin** in + `l4d2host/`. Subscribes to L4D2 game events and calls + `LogMessage()` from inside srcds. The explicit `LogMessage()` + path is implemented separately from the autonomous engine emit + and DOES reach UDP destinations on every Source 1 game stat + trackers have used in production. This proves out the listener. +- Phase 2 path B (interim, no plugin): **parse the journal**. + `journalctl -u "left4me-server@*.service" -f` already streams + every HL-Log-Standard line as captured srcds stdout. A reducer + that follows journald + matches the `srcds_run[*]: L ...` lines + produces structured events today without any srcds-side change. + Less clean than UDP-to-listener (we'd hop through journald) but + available immediately. +- `mp_logdetail` was removed from the cfg injection: it is a + CS-only cvar (L4D2 prints `Unknown command "mp_logdetail"` at + startup). + ## Follow-ups (separate plans) -Once we have ~3–7 days of capture data: -- Decide event vocabulary based on what L4D2 *actually* emits on our - servers (vs. what specs say). -- Design `RawLogLine` / `LogEvent` / `MatchSession` / `Round` schema. +- **Phase 2:** pick Path A (SourceMod bridge) vs Path B (journald + follower). A is cleaner long-term; B is faster to ship. +- Once events flow somehow: design `RawLogLine` / `LogEvent` / + `MatchSession` / `Round` schema based on what we actually see. - Build a reducer. -- Consider a small SourceMod bridge plugin in `l4d2host/` to surface - `tank_spawn`, `mission_lost`, finale events as `LogMessage()` lines. -- `sv_logsecret` once the listener is reachable beyond loopback. +- `sv_logsecret` becomes relevant only once the listener is + reachable beyond loopback (currently moot). diff --git a/l4d2web/l4d2web/services/l4d2_facade.py b/l4d2web/l4d2web/services/l4d2_facade.py index 07b5f78..27feb02 100644 --- a/l4d2web/l4d2web/services/l4d2_facade.py +++ b/l4d2web/l4d2web/services/l4d2_facade.py @@ -55,13 +55,18 @@ def build_server_spec_payload( # nor hostname can override it (Source's cvar semantics are last-wins). if server.rcon_password: config_lines.append(f'rcon_password "{server.rcon_password}"') - # HL-Log-Standard UDP streaming. Auto-injected (not in user blueprint) so - # the listener in l4d2web/services/log_listener.py reliably receives - # game events from every managed server. logaddress_add is additive and - # safe to re-issue on restart. + # HL-Log-Standard UDP streaming registration. Investigation on 2026-05-20 + # established that L4D2's vanilla logaddress UDP emit path is stubbed/broken: + # `log` cvar reports "logging to: file, console, udp" and `logaddress_list` + # shows the registration, but srcds_linux makes ZERO sendto/sendmsg calls + # toward the destination (proven by strace + tcpdump showing 0 packets). + # Local file logging works fine. So the listener currently captures nothing + # in production. The cvars are kept registered for a future SourceMod + # bridge plugin that will call LogMessage() directly — those messages DO + # flow through logaddress destinations on every Source 1 game including L4D2. + # `mp_logdetail` was removed: it is a CS-only cvar (`Unknown command` on L4D2). if log_listener_addr: config_lines.append("log on") - config_lines.append("mp_logdetail 3") config_lines.append(f"logaddress_add {log_listener_addr}") return { "port": server.port, diff --git a/l4d2web/l4d2web/services/log_listener.py b/l4d2web/l4d2web/services/log_listener.py index 4a7c70c..5bce308 100644 --- a/l4d2web/l4d2web/services/log_listener.py +++ b/l4d2web/l4d2web/services/log_listener.py @@ -6,6 +6,17 @@ server into flat files under LOG_CAPTURE_DIR — one file per source reducer. The goal is to observe what L4D2 actually emits on our servers before we commit to a schema or event vocabulary. +KNOWN-DEAD AS OF 2026-05-20: L4D2's vanilla logaddress UDP emit path +is stubbed/broken at the engine level. srcds reports +"currently logging to: file, console, udp" and logaddress_list shows +our address, but strace + tcpdump confirmed srcds_linux makes ZERO +sendto/sendmsg calls toward the destination. Local file logging works +fine; only UDP broadcast is dead. This matches the broken-SourceTV +pattern in L4D2 — see docs/superpowers/plans/2026-05-19-...md for the +full investigation. The listener is therefore a no-op in production +until a SourceMod bridge plugin is deployed that calls LogMessage() +directly (those messages DO flow through logaddress destinations). + Packet shape (per HL Log Standard): 4 bytes 0xFF | out-of-band marker 1 byte 'R'/'S' | with-secret if 'S' (then 4 bytes LE secret) diff --git a/l4d2web/tests/test_l4d2_facade.py b/l4d2web/tests/test_l4d2_facade.py index 8a3caf0..4222a64 100644 --- a/l4d2web/tests/test_l4d2_facade.py +++ b/l4d2web/tests/test_l4d2_facade.py @@ -424,11 +424,12 @@ def test_build_server_spec_payload_injects_log_cvars() -> None: srv, bp, [], log_listener_addr="127.0.0.1:28000", ) cfg = spec["config"] - # All three log cvars emitted, AFTER rcon_password (so blueprint can't - # override them — Source cvars are last-wins). + # log cvars emitted AFTER rcon_password (so blueprint can't override + # them — Source cvars are last-wins). assert "log on" in cfg - assert "mp_logdetail 3" in cfg assert "logaddress_add 127.0.0.1:28000" in cfg + # mp_logdetail is CS-only; L4D2 rejects it with "Unknown command". + assert "mp_logdetail 3" not in cfg rcon_idx = cfg.index('rcon_password "sekret"') log_idx = cfg.index("log on") assert log_idx > rcon_idx, "log cvars must come after rcon_password" @@ -442,7 +443,6 @@ def test_build_server_spec_payload_omits_log_cvars_when_addr_empty() -> None: spec = build_server_spec_payload(srv, bp, []) # default "" → no inject cfg = spec["config"] assert "log on" not in cfg - assert "mp_logdetail 3" not in cfg assert not any(line.startswith("logaddress_add ") for line in cfg)