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:
parent
730ef09967
commit
46bba0d134
4 changed files with 97 additions and 16 deletions
|
|
@ -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/<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)
|
||||
|
||||
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).
|
||||
|
|
|
|||
|
|
@ -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,
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
||||
|
||||
|
|
|
|||
Loading…
Reference in a new issue