docs(log-streaming): record that L4D2 logaddress UDP emit is dead

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) <noreply@anthropic.com>
This commit is contained in:
mwiegand 2026-05-20 00:19:50 +02:00
parent 730ef09967
commit 46bba0d134
No known key found for this signature in database
4 changed files with 97 additions and 16 deletions

View file

@ -232,13 +232,78 @@ End-to-end smoke test, on the dev box first:
filename, that's enough for now. filename, that's enough for now.
- Long-running stability past a few days — listener is temp. - 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/<n>/merged/left4dead2/logs/` grow
normally; rich gameplay events show in `journalctl -u
left4me-server@<n>` (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 <srcds_linux> -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) ## Follow-ups (separate plans)
Once we have ~37 days of capture data: - **Phase 2:** pick Path A (SourceMod bridge) vs Path B (journald
- Decide event vocabulary based on what L4D2 *actually* emits on our follower). A is cleaner long-term; B is faster to ship.
servers (vs. what specs say). - Once events flow somehow: design `RawLogLine` / `LogEvent` /
- Design `RawLogLine` / `LogEvent` / `MatchSession` / `Round` schema. `MatchSession` / `Round` schema based on what we actually see.
- Build a reducer. - Build a reducer.
- Consider a small SourceMod bridge plugin in `l4d2host/` to surface - `sv_logsecret` becomes relevant only once the listener is
`tank_spawn`, `mission_lost`, finale events as `LogMessage()` lines. reachable beyond loopback (currently moot).
- `sv_logsecret` once the listener is reachable beyond loopback.

View file

@ -55,13 +55,18 @@ def build_server_spec_payload(
# nor hostname can override it (Source's cvar semantics are last-wins). # nor hostname can override it (Source's cvar semantics are last-wins).
if server.rcon_password: if server.rcon_password:
config_lines.append(f'rcon_password "{server.rcon_password}"') config_lines.append(f'rcon_password "{server.rcon_password}"')
# HL-Log-Standard UDP streaming. Auto-injected (not in user blueprint) so # HL-Log-Standard UDP streaming registration. Investigation on 2026-05-20
# the listener in l4d2web/services/log_listener.py reliably receives # established that L4D2's vanilla logaddress UDP emit path is stubbed/broken:
# game events from every managed server. logaddress_add is additive and # `log` cvar reports "logging to: file, console, udp" and `logaddress_list`
# safe to re-issue on restart. # 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: if log_listener_addr:
config_lines.append("log on") config_lines.append("log on")
config_lines.append("mp_logdetail 3")
config_lines.append(f"logaddress_add {log_listener_addr}") config_lines.append(f"logaddress_add {log_listener_addr}")
return { return {
"port": server.port, "port": server.port,

View file

@ -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 reducer. The goal is to observe what L4D2 actually emits on our
servers before we commit to a schema or event vocabulary. 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): Packet shape (per HL Log Standard):
4 bytes 0xFF | out-of-band marker 4 bytes 0xFF | out-of-band marker
1 byte 'R'/'S' | with-secret if 'S' (then 4 bytes LE secret) 1 byte 'R'/'S' | with-secret if 'S' (then 4 bytes LE secret)

View file

@ -424,11 +424,12 @@ def test_build_server_spec_payload_injects_log_cvars() -> None:
srv, bp, [], log_listener_addr="127.0.0.1:28000", srv, bp, [], log_listener_addr="127.0.0.1:28000",
) )
cfg = spec["config"] cfg = spec["config"]
# All three log cvars emitted, AFTER rcon_password (so blueprint can't # log cvars emitted AFTER rcon_password (so blueprint can't override
# override them — Source cvars are last-wins). # them — Source cvars are last-wins).
assert "log on" in cfg assert "log on" in cfg
assert "mp_logdetail 3" in cfg
assert "logaddress_add 127.0.0.1:28000" 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"') rcon_idx = cfg.index('rcon_password "sekret"')
log_idx = cfg.index("log on") log_idx = cfg.index("log on")
assert log_idx > rcon_idx, "log cvars must come after rcon_password" 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 spec = build_server_spec_payload(srv, bp, []) # default "" → no inject
cfg = spec["config"] cfg = spec["config"]
assert "log on" not in cfg assert "log on" not in cfg
assert "mp_logdetail 3" not in cfg
assert not any(line.startswith("logaddress_add ") for line in cfg) assert not any(line.startswith("logaddress_add ") for line in cfg)