From 1bd7034dfecdadf0e25b06e2150583425bf33132 Mon Sep 17 00:00:00 2001 From: wangjunwei Date: Wed, 17 Jun 2026 12:55:41 +0800 Subject: [PATCH 1/2] feat(handler): log tunnel close with destination and duration MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The handler already logs each accepted request at Info ("Request: ... CONNECT "), 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 --- handler/handler.go | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/handler/handler.go b/handler/handler.go index 2bedce1..6187354 100644 --- a/handler/handler.go +++ b/handler/handler.go @@ -14,6 +14,7 @@ import ( "strconv" "strings" "sync" + "time" "github.com/SenseUnit/dumbproxy/auth" "github.com/SenseUnit/dumbproxy/dialer" @@ -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 @@ -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", + req.RemoteAddr, req.RequestURI, time.Since(tunnelStart).Round(time.Millisecond)) }() if req.ProtoMajor == 0 || req.ProtoMajor == 1 { From d5e680d3779968a51aa1940015d738b630d1509b Mon Sep 17 00:00:00 2001 From: wangjunwei Date: Sat, 20 Jun 2026 12:07:00 +0800 Subject: [PATCH 2/2] feat(handler): log requests after completion --- handler/accesslog.go | 83 ++++++++++++++++++++++++++++++++++++++++++ handler/direct_test.go | 14 +++++++ handler/handler.go | 18 ++++++--- 3 files changed, 110 insertions(+), 5 deletions(-) create mode 100644 handler/accesslog.go diff --git a/handler/accesslog.go b/handler/accesslog.go new file mode 100644 index 0000000..c11b241 --- /dev/null +++ b/handler/accesslog.go @@ -0,0 +1,83 @@ +package handler + +import ( + "bufio" + "fmt" + "net" + "net/http" + "strconv" + "time" +) + +type accessLogResponseWriter struct { + http.ResponseWriter + status int +} + +func newAccessLogResponseWriter(w http.ResponseWriter) *accessLogResponseWriter { + return &accessLogResponseWriter{ResponseWriter: w} +} + +func (w *accessLogResponseWriter) WriteHeader(status int) { + if w.status == 0 { + w.status = status + w.ResponseWriter.WriteHeader(status) + } +} + +func (w *accessLogResponseWriter) Write(p []byte) (int, error) { + if w.status == 0 { + w.status = http.StatusOK + } + return w.ResponseWriter.Write(p) +} + +func (w *accessLogResponseWriter) Flush() { + if f, ok := w.ResponseWriter.(http.Flusher); ok { + f.Flush() + } +} + +func (w *accessLogResponseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) { + hj, ok := w.ResponseWriter.(http.Hijacker) + if !ok { + return nil, nil, fmt.Errorf("connection doesn't support hijacking") + } + return hj.Hijack() +} + +func markAccessLogStatus(w http.ResponseWriter, status int) { + if lw, ok := w.(*accessLogResponseWriter); ok && lw.status == 0 { + lw.status = status + } +} + +func accessLogTarget(req *http.Request) string { + if req.Method == http.MethodConnect { + if req.RequestURI != "" { + return req.RequestURI + } + if req.URL != nil && req.URL.Host != "" { + return req.URL.Host + } + } + if req.URL == nil { + return "" + } + return req.URL.String() +} + +func accessLogStatus(status int) string { + if status == 0 { + return "-" + } + text := http.StatusText(status) + if text == "" { + return strconv.Itoa(status) + } + return fmt.Sprintf("%d %s", status, text) +} + +func accessLogDuration(start time.Time) time.Duration { + return time.Since(start).Round(time.Millisecond) +} diff --git a/handler/direct_test.go b/handler/direct_test.go index 0d549b4..d8b61a5 100644 --- a/handler/direct_test.go +++ b/handler/direct_test.go @@ -1,15 +1,19 @@ package handler import ( + "bytes" "context" "errors" + "log" "net" "net/http" "net/http/httptest" "net/url" + "strings" "testing" derrors "github.com/SenseUnit/dumbproxy/dialer/errors" + clog "github.com/SenseUnit/dumbproxy/log" ) type staticReject struct { @@ -109,9 +113,11 @@ func TestDirectResponse(t *testing.T) { } func TestAccessReject(t *testing.T) { + var logBuf bytes.Buffer proxy := NewProxyHandler(&Config{ Dialer: deniedDialer{}, AccessReject: staticReject{status: http.StatusTeapot, body: "access response"}, + Logger: clog.NewCondLogger(log.New(&logBuf, "", 0), clog.INFO), }) rr := httptest.NewRecorder() req := &http.Request{ @@ -131,4 +137,12 @@ func TestAccessReject(t *testing.T) { if rr.Body.String() != "access response" { t.Fatalf("body = %q, want access response", rr.Body.String()) } + + logOutput := logBuf.String() + if got := strings.Count(logOutput, "INFO Request:"); got != 1 { + t.Fatalf("INFO Request log count = %d, want 1\nlogs:\n%s", got, logOutput) + } + if !strings.Contains(logOutput, "CONNECT openrouter.ai:443 418 I'm a teapot dur=") { + t.Fatalf("access log is missing status or duration\nlogs:\n%s", logOutput) + } } diff --git a/handler/handler.go b/handler/handler.go index 6187354..9d544df 100644 --- a/handler/handler.go +++ b/handler/handler.go @@ -80,7 +80,6 @@ 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 @@ -103,8 +102,6 @@ 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", - req.RemoteAddr, req.RequestURI, time.Since(tunnelStart).Round(time.Millisecond)) }() if req.ProtoMajor == 0 || req.ProtoMajor == 1 { @@ -116,6 +113,7 @@ func (s *ProxyHandler) HandleTunnel(wr http.ResponseWriter, req *http.Request, u return } defer localconn.Close() + markAccessLogStatus(wr, http.StatusOK) if buffered := rw.Reader.Buffered(); buffered > 0 { s.logger.Debug("saving %d bytes buffered in bufio.ReadWriter", buffered) @@ -195,7 +193,6 @@ func (s *ProxyHandler) HandleRequest(wr http.ResponseWriter, req *http.Request, return } defer resp.Body.Close() - s.logger.Info("%v %v %v %v", req.RemoteAddr, req.Method, req.URL, resp.Status) delHopHeaders(resp.Header) copyHeader(wr.Header(), resp.Header) wr.WriteHeader(resp.StatusCode) @@ -242,10 +239,21 @@ func (s *ProxyHandler) ServeHTTP(wr http.ResponseWriter, req *http.Request) { return } + start := time.Now() + wr = newAccessLogResponseWriter(wr) ctx := req.Context() username, ok := s.auth.Validate(ctx, wr, req) localAddr := getLocalAddr(req.Context()) - s.logger.Info("Request: %v => %v %q %v %v %v", req.RemoteAddr, localAddr, username, req.Proto, req.Method, req.URL) + target := accessLogTarget(req) + defer func() { + status := 0 + if lw, ok := wr.(*accessLogResponseWriter); ok { + status = lw.status + } + s.logger.Info("Request: %v => %v %q %v %v %v %s dur=%v", + req.RemoteAddr, localAddr, username, req.Proto, req.Method, target, + accessLogStatus(status), accessLogDuration(start)) + }() if !ok { return