Skip to content

feat(handler): log tunnel close with destination and duration #238

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
m11y wants to merge 2 commits into
base: master
Choose a base branch
from
Open

feat(handler): log tunnel close with destination and duration #238

Changes from 1 commit
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
1bd7034
feat(handler): log tunnel close with destination and duration
m11y Jun 17, 2026
d5e680d
feat(handler): log requests after completion
m11y Jun 20, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions handler/handler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,6 +14,7 @@ import (
"strconv"
"strings"
"sync"
"time"

"github.com/SenseUnit/dumbproxy/auth"
"github.com/SenseUnit/dumbproxy/dialer"
Expand Down Expand Up @@ -79,6 +80,7 @@ func NewProxyHandler(config *Config) *ProxyHandler {
}

func (s *ProxyHandler) HandleTunnel(wr http.ResponseWriter, req *http.Request, username string) {
tunnelStart := time.Now()
conn, err := s.dialer.DialContext(req.Context(), "tcp", req.RequestURI)
if err != nil {
var accessErr derrors.ErrAccessDenied
Expand All @@ -101,6 +103,8 @@ func (s *ProxyHandler) HandleTunnel(wr http.ResponseWriter, req *http.Request, u
s.outboundMux.Lock()
delete(s.outbound, localAddr)
s.outboundMux.Unlock()
s.logger.Info("Tunnel closed: %v => %v dur=%v",

@Snawoot Snawoot Jun 18, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could be useful to put it at debug log level, but having it on default one would be too much of output.

@m11y m11y Jun 19, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

@Snawoot Snawoot Jun 19, 2026

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

@m11y m11y Jun 20, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 ./...

req.RemoteAddr, req.RequestURI, time.Since(tunnelStart).Round(time.Millisecond))
}()

if req.ProtoMajor == 0 || req.ProtoMajor == 1 {
Expand Down