feat(handler): log tunnel close with destination and duration#238
Conversation
The handler already logs each accepted request at Info ("Request: ... CONNECT
<dst>"), but nothing on teardown — so a tunnel's lifetime and the destination
it closed against are invisible. This makes it hard to diagnose egress issues
where a connection is held open and then cut (e.g. an upstream/proxy response
timeout severing a long LLM request, surfacing to the client as a bare EOF).
Capture the dial time and, in the existing teardown defer, log the client
addr, destination, and rounded duration at Info. No new allocation on the hot
copy path; the line only fires once per tunnel at close.
Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Snawoot
left a comment
Snawoot
left a comment
There was a problem hiding this comment.
Let's have it as Debug() instead of Info().
| s.outboundMux.Lock() | ||
| delete(s.outbound, localAddr) | ||
| s.outboundMux.Unlock() | ||
| s.logger.Info("Tunnel closed: %v => %v dur=%v", |
There was a problem hiding this comment.
Could be useful to put it at debug log level, but having it on default one would be too much of output.
There was a problem hiding this comment.
Thanks, I understand the concern about default log volume.
My thinking behind keeping this at Info was that it is symmetric with the existing CONNECT request log: one line when the tunnel is opened, and one corresponding line when it is closed. This close log is emitted once per tunnel, not per copy/read/write operation, so it completes the lifecycle record rather than adding continuous noise.
The reason I would prefer Info is that the close side is usually the important part when diagnosing production EOF/timeout issues. If it is only available at Debug, users need to enable Debug before reproducing the problem, and the open/close pair ends up split across different log levels.
That said, I understand the desire to keep default output minimal. Would you be open to keeping it at Info since it mirrors the existing CONNECT log, or do you still strongly prefer Debug here?
There was a problem hiding this comment.
The reason I would prefer Info is that the close side is usually the important part when diagnosing production EOF/timeout issues. If it is only available at Debug, users need to enable Debug before reproducing the problem, and the open/close pair ends up split across different log levels.
I understand that, but:
- If you debug, it's normal you need debug log verbosity in advance. That's very reason most verbose level called "debug".
- Majority of users don't debug all the time, it just works for them and for them that log is more like Apache access log -- just requests. The interest of intended audience is to have it very plain.
- Finally, if we add it to Info level, users can't opt-out from that other than going to Error log level and muting all requests at all. But if we add it to Debug level, users can opt-in to these message (along with other debug noise) which is more tolerable and less binding to users.
There was a problem hiding this comment.
That makes sense, thanks for explaining the default-log-volume concern.
I changed the approach in d5e680d. Instead of adding a second Info-level line for tunnel close, the request log is now emitted after request completion and includes the final status and duration. So the default Info output still stays at one access-log-style line per request, but CONNECT requests now also carry the completion information that was missing before.
For example, a CONNECT tunnel now logs as a single line like:
Request: <remote> => <local> "<user>" HTTP/1.1 CONNECT example.com:443 200 OK dur=2m15s
Regular HTTP proxy requests use the same shape and are also logged after the response body forwarding completes. I think this better matches the Apache/nginx access log model you described while still making CONNECT duration visible without requiring a separate close lifecycle message.
Tests: go test ./...
2 participants
The handler logs each accepted request at Info (
Request: ... CONNECT <dst>), but nothing on teardown — so a tunnel's lifetime and the destination it closed against are invisible in the logs.This makes it hard to diagnose egress issues where a connection is held open and then cut: e.g. an upstream/proxy response timeout severing a long-running request, which surfaces to the client only as a bare
EOFwith no indication of which destination or how long the tunnel lived.This change captures the dial time and, in the existing teardown
defer, logs the client address, destination, and rounded duration at Info:Tested against a live deployment (CONNECT through the proxy logs both the open and the new close line with the expected duration).