diff --git a/DECISIONS.md b/DECISIONS.md index d53d7c0..a8c03bc 100644 --- a/DECISIONS.md +++ b/DECISIONS.md @@ -81,3 +81,4 @@ - 2026-02-28 m+git@andri.dk — Renamed all portal HTML files to `.gohtml` and converted them to Go templates. The nav bar (14 lines duplicated across 5 files) is now a shared template fragment in `static/nav.gohtml` included via `{{ template "nav" }}`. Pages are parsed with `parsePageTemplate()` which combines the nav fragment with each page template. The `.gohtml` extension stops HTML language servers from flagging Go template syntax as errors. Extracted `authGate()`, `apiPatch()`, and `createToggle()` into `shared.js` to deduplicate auth gating (5 identical onAuth/onUnauth pairs), PATCH wrappers (3 identical), and toggle DOM creation (3 identical). - 2026-02-28 m+git@andri.dk — Added zstd decompression for CSS injection and resource stripping. All major browsers now negotiate zstd via `Accept-Encoding`, and CDNs are increasingly serving zstd-compressed HTML. Added `github.com/klauspost/compress/zstd` (pure Go, zero transitive runtime deps) alongside the existing brotli and gzip support. Without this, zstd-encoded HTML passed through without element hiding or script injection. - 2026-02-28 m+git@andri.dk — Cert cache now evicts expired certificates. `GetCert` checks the cached cert's expiry time before returning it; expired entries are regenerated on demand. Previously, certs were cached indefinitely — after 24h of uptime, cached certs would be stale and clients would get TLS errors. The cache stores `expiresAt` alongside each cert. No background goroutine; expiry is checked lazily on access. +- 2026-02-28 m+git@andri.dk — Structured logging with `log/slog` (stdlib, zero new dependencies). Replaced all `fmt.Fprintf(os.Stderr)` calls with `slog` at appropriate levels. Added `--log-level` flag (env: `UBLPROXY_LOG_LEVEL`, default: `info`). Every log line includes `ip` (client source IP) and `user` (first 8 chars of credential ID, or `anon`). Per-request traffic logging and passthrough tunnels are Debug level — only visible with `--log-level=debug`. Blocked requests, startup, and errors are Info/Error level and always visible. Blocklist loading failures are Warn level. Output is `slog.TextHandler` (structured key=value pairs to stderr). diff --git a/QUICK_START.md b/QUICK_START.md index 315772e..77e1591 100644 --- a/QUICK_START.md +++ b/QUICK_START.md @@ -438,3 +438,4 @@ All flags can also be set via environment variables. Environment variables take | `--db` | `UBLPROXY_DB` | `~/.ublproxy/ublproxy.db` | Path to SQLite database | | `--blocklist` | `UBLPROXY_BLOCKLIST` | *(none)* | Path or URL to a blocklist file (repeatable, comma-separated in env var) | | `--transparent` | `UBLPROXY_TRANSPARENT` | `false` | Run in transparent proxy mode (intercept redirected traffic) | +| `--log-level` | `UBLPROXY_LOG_LEVEL` | `info` | Log verbosity: `debug`, `info`, `warn`, `error`. Use `debug` to log all proxied requests. | diff --git a/activity.go b/activity.go index 748e2eb..c5931f0 100644 --- a/activity.go +++ b/activity.go @@ -20,6 +20,8 @@ type ActivityEntry struct { Host string `json:"host"` URL string `json:"url,omitempty"` Rule string `json:"rule,omitempty"` + IP string `json:"ip"` + User string `json:"user"` } // ActivityLog is a thread-safe ring buffer of recent proxy events. diff --git a/api_auth.go b/api_auth.go index 18a7c5a..4175141 100644 --- a/api_auth.go +++ b/api_auth.go @@ -142,7 +142,7 @@ func (a *apiHandler) handleRegisterFinish(w http.ResponseWriter, r *http.Request cred, err := webauthn.VerifyRegistration(a.webauthnCfg, attestationObject, clientDataJSON, challenge) if err != nil { - logError("webauthn/register", err) + logError("webauthn/register", err, clientIPFromRequest(r), "") writeJSON(w, http.StatusBadRequest, errorResponse{"registration verification failed"}) return } @@ -279,7 +279,7 @@ func (a *apiHandler) handleLoginFinish(w http.ResponseWriter, r *http.Request) { a.webauthnCfg, authData, clientDataJSON, sig, cred.PublicKey, challenge, ) if err != nil { - logError("webauthn/login", err) + logError("webauthn/login", err, clientIPFromRequest(r), "") writeJSON(w, http.StatusUnauthorized, errorResponse{"authentication failed"}) return } diff --git a/api_rules.go b/api_rules.go index c55f1c7..4dcc987 100644 --- a/api_rules.go +++ b/api_rules.go @@ -1,9 +1,8 @@ package main import ( - "fmt" + "log/slog" "net/http" - "os" "strconv" "strings" @@ -139,7 +138,7 @@ func (a *apiHandler) triggerReload(credentialID string) { go func() { defer func() { if r := recover(); r != nil { - fmt.Fprintf(os.Stderr, "panic in onRulesChanged: %v\n", r) + slog.Error("panic in onRulesChanged", "err", r) } }() a.onRulesChanged(credentialID) diff --git a/connect.go b/connect.go index 7a1d3bc..2b3dc94 100644 --- a/connect.go +++ b/connect.go @@ -18,8 +18,10 @@ func (p *proxyHandler) handleConnect(w http.ResponseWriter, r *http.Request) { port = "443" } clientIP, _, _ := net.SplitHostPort(r.RemoteAddr) + credID := p.credentialForIP(clientIP) if p.shouldBlockHost(clientIP, host) { - p.logActivity(ActivityBlocked, host, "", "||"+host+"^") + p.logActivity(ActivityBlocked, host, "", "||"+host+"^", clientIP, credID) + logBlocked(host, "", "||"+host+"^", clientIP, credID) http.Error(w, "blocked", http.StatusForbidden) return } @@ -28,8 +30,8 @@ func (p *proxyHandler) handleConnect(w http.ResponseWriter, r *http.Request) { // The proxy never sees the plaintext — the client's TLS session // goes straight to the upstream server. if p.isHostExcepted(clientIP, host) { - p.logActivity(ActivityPassthrough, host, "", "@@||"+host+"^") - p.tunnelPassthrough(w, r, host, port) + p.logActivity(ActivityPassthrough, host, "", "@@||"+host+"^", clientIP, credID) + p.tunnelPassthrough(w, r, host, port, clientIP, credID) return } @@ -44,14 +46,14 @@ func (p *proxyHandler) handleConnect(w http.ResponseWriter, r *http.Request) { clientConn, _, err := hijacker.Hijack() if err != nil { - logError("connect/hijack", err) + logError("connect/hijack", err, clientIP, credID) return } defer clientConn.Close() tlsCert, err := p.certs.GetCert(host) if err != nil { - logError("connect/cert", err) + logError("connect/cert", err, clientIP, credID) return } @@ -62,7 +64,7 @@ func (p *proxyHandler) handleConnect(w http.ResponseWriter, r *http.Request) { Certificates: []tls.Certificate{*tlsCert}, }) if err := tlsClientConn.Handshake(); err != nil { - logError("connect/client-tls", err) + logError("connect/client-tls", err, clientIP, credID) return } defer tlsClientConn.Close() @@ -70,21 +72,19 @@ func (p *proxyHandler) handleConnect(w http.ResponseWriter, r *http.Request) { // Clear the deadline after successful handshake clientConn.SetDeadline(time.Time{}) - // Extract client IP for script injection (from the original CONNECT request). // If the outer connection is plain HTTP (r.TLS == nil), mark as insecure // so the bootstrap script (which contains the session token) is not injected. - cIP, _, _ := net.SplitHostPort(r.RemoteAddr) insecure := r.TLS == nil - p.proxyTLSRequests(tlsClientConn, host, port, cIP, insecure) + p.proxyTLSRequests(tlsClientConn, host, port, clientIP, credID, insecure) } // tunnelPassthrough establishes a transparent TCP tunnel between the client // and upstream server. No MITM, no cert generation, no request inspection. // The proxy only sees connection metadata (hostname, timing, bytes transferred). -func (p *proxyHandler) tunnelPassthrough(w http.ResponseWriter, r *http.Request, host, port string) { +func (p *proxyHandler) tunnelPassthrough(w http.ResponseWriter, r *http.Request, host, port, clientIP, credID string) { upstream, err := net.DialTimeout("tcp", net.JoinHostPort(host, port), 10*time.Second) if err != nil { - logError("passthrough/dial", err) + logError("passthrough/dial", err, clientIP, credID) http.Error(w, "upstream unreachable", http.StatusBadGateway) return } @@ -100,12 +100,12 @@ func (p *proxyHandler) tunnelPassthrough(w http.ResponseWriter, r *http.Request, clientConn, _, err := hijacker.Hijack() if err != nil { - logError("passthrough/hijack", err) + logError("passthrough/hijack", err, clientIP, credID) return } defer clientConn.Close() - logPassthrough(host) + logPassthrough(host, clientIP, credID) bidirectionalCopy(clientConn, upstream) } @@ -114,14 +114,14 @@ func (p *proxyHandler) tunnelPassthrough(w http.ResponseWriter, r *http.Request, // by looping until the client closes the connection or an error occurs. // When insecure is true the outer proxy connection is plain HTTP, so the // bootstrap script (which embeds the session token) is not injected. -func (p *proxyHandler) proxyTLSRequests(clientTLS *tls.Conn, host, port, clientIP string, insecure bool) { +func (p *proxyHandler) proxyTLSRequests(clientTLS *tls.Conn, host, port, clientIP, credID string, insecure bool) { clientReader := bufio.NewReader(clientTLS) for { req, err := http.ReadRequest(clientReader) if err != nil { if err != io.EOF { - logError("connect/read-request", err) + logError("connect/read-request", err, clientIP, credID) } return } @@ -132,7 +132,8 @@ func (p *proxyHandler) proxyTLSRequests(clientTLS *tls.Conn, host, port, clientI // checked at CONNECT time; this catches path-specific rules) ctx := matchContextFromRequest(req) if p.shouldBlock(clientIP, targetURL, ctx) { - p.logActivity(ActivityBlocked, host, targetURL, "") + p.logActivity(ActivityBlocked, host, targetURL, "", clientIP, credID) + logBlocked(host, targetURL, "", clientIP, credID) req.Body.Close() blocked := &http.Response{ StatusCode: http.StatusNoContent, @@ -161,7 +162,7 @@ func (p *proxyHandler) proxyTLSRequests(clientTLS *tls.Conn, host, port, clientI resp, err := p.transport.RoundTrip(req) if err != nil { - logError("connect/roundtrip", err) + logError("connect/roundtrip", err, clientIP, credID) return } @@ -170,7 +171,7 @@ func (p *proxyHandler) proxyTLSRequests(clientTLS *tls.Conn, host, port, clientI upstreamConn, ok := resp.Body.(io.ReadWriteCloser) if !ok { resp.Body.Close() - logError("connect/upgrade", io.ErrUnexpectedEOF) + logError("connect/upgrade", io.ErrUnexpectedEOF, clientIP, credID) return } defer upstreamConn.Close() @@ -178,7 +179,7 @@ func (p *proxyHandler) proxyTLSRequests(clientTLS *tls.Conn, host, port, clientI resp.Body = nil resp.Write(clientTLS) - logRequest(req.Method, targetURL+" [websocket]", resp.StatusCode, time.Since(start)) + logRequest(req.Method, targetURL+" [websocket]", resp.StatusCode, time.Since(start), clientIP, credID) // clientReader may have buffered bytes past the HTTP request, // so we read from it (not raw clientTLS). Writes go to clientTLS. @@ -198,12 +199,12 @@ func (p *proxyHandler) proxyTLSRequests(clientTLS *tls.Conn, host, port, clientI if err := resp.Write(clientTLS); err != nil { resp.Body.Close() - logError("connect/write-response", err) + logError("connect/write-response", err, clientIP, credID) return } resp.Body.Close() - logRequest(req.Method, targetURL, resp.StatusCode, time.Since(start)) + logRequest(req.Method, targetURL, resp.StatusCode, time.Since(start), clientIP, credID) if resp.Close { return diff --git a/elemhide_inject.go b/elemhide_inject.go index 3306652..7d5648c 100644 --- a/elemhide_inject.go +++ b/elemhide_inject.go @@ -151,6 +151,8 @@ func (p *proxyHandler) applyElementHiding(resp *http.Response, host, clientIP st safeCSS := styleCloseRe.ReplaceAllString(css, `<\/style`) styleTag := []byte("") modified = injectStyleTag(modified, styleTag) + p.logActivity(ActivityElementHidden, host, "", "", clientIP, credID) + logElementHidden(host, clientIP, credID) } // Inject the bootstrap script for the element picker diff --git a/http.go b/http.go index 62b971a..3bd4792 100644 --- a/http.go +++ b/http.go @@ -35,8 +35,10 @@ var hopByHopHeaders = []string{ func (p *proxyHandler) handleHTTP(w http.ResponseWriter, r *http.Request) { ctx := matchContextFromRequest(r) clientIP := clientIPFromRequest(r) + credID := p.credentialForIP(clientIP) if p.shouldBlock(clientIP, r.URL.String(), ctx) { - p.logActivity(ActivityBlocked, r.URL.Hostname(), r.URL.String(), "") + p.logActivity(ActivityBlocked, r.URL.Hostname(), r.URL.String(), "", clientIP, credID) + logBlocked(r.URL.Hostname(), r.URL.String(), "", clientIP, credID) w.WriteHeader(http.StatusNoContent) return } @@ -51,7 +53,7 @@ func (p *proxyHandler) handleHTTP(w http.ResponseWriter, r *http.Request) { outReq, err := http.NewRequestWithContext(r.Context(), r.Method, r.URL.String(), r.Body) if err != nil { - logError("http/new-request", err) + logError("http/new-request", err, clientIP, credID) http.Error(w, "bad request", http.StatusBadRequest) return } @@ -61,7 +63,7 @@ func (p *proxyHandler) handleHTTP(w http.ResponseWriter, r *http.Request) { resp, err := p.transport.RoundTrip(outReq) if err != nil { - logError("http/roundtrip", err) + logError("http/roundtrip", err, clientIP, credID) http.Error(w, "upstream error", http.StatusBadGateway) return } @@ -72,13 +74,13 @@ func (p *proxyHandler) handleHTTP(w http.ResponseWriter, r *http.Request) { // bootstrap script injection to avoid leaking the session token. insecure := r.TLS == nil if r.Method != http.MethodHead { - if modified, ok := p.applyElementHiding(resp, r.URL.Hostname(), clientIPFromRequest(r), insecure); ok { + if modified, ok := p.applyElementHiding(resp, r.URL.Hostname(), clientIP, insecure); ok { copyHeaders(w.Header(), resp.Header) removeHopByHopHeaders(w.Header()) w.Header().Del("Content-Length") w.WriteHeader(resp.StatusCode) w.Write(modified) - logRequest(r.Method, r.URL.String(), resp.StatusCode, time.Since(start)) + logRequest(r.Method, r.URL.String(), resp.StatusCode, time.Since(start), clientIP, credID) return } } @@ -88,7 +90,7 @@ func (p *proxyHandler) handleHTTP(w http.ResponseWriter, r *http.Request) { w.WriteHeader(resp.StatusCode) io.Copy(w, resp.Body) - logRequest(r.Method, r.URL.String(), resp.StatusCode, time.Since(start)) + logRequest(r.Method, r.URL.String(), resp.StatusCode, time.Since(start), clientIP, credID) } // handleHTTPUpgrade handles WebSocket and other protocol upgrade requests @@ -96,9 +98,12 @@ func (p *proxyHandler) handleHTTP(w http.ResponseWriter, r *http.Request) { // the upstream, and if the upstream responds with 101, hijacks both sides // and does bidirectional copy. func (p *proxyHandler) handleHTTPUpgrade(w http.ResponseWriter, r *http.Request) { + clientIP := clientIPFromRequest(r) + credID := p.credentialForIP(clientIP) + outReq, err := http.NewRequestWithContext(r.Context(), r.Method, r.URL.String(), r.Body) if err != nil { - logError("http/upgrade/new-request", err) + logError("http/upgrade/new-request", err, clientIP, credID) http.Error(w, "bad request", http.StatusBadRequest) return } @@ -112,7 +117,7 @@ func (p *proxyHandler) handleHTTPUpgrade(w http.ResponseWriter, r *http.Request) resp, err := p.transport.RoundTrip(outReq) if err != nil { - logError("http/upgrade/roundtrip", err) + logError("http/upgrade/roundtrip", err, clientIP, credID) http.Error(w, "upstream error", http.StatusBadGateway) return } @@ -145,7 +150,7 @@ func (p *proxyHandler) handleHTTPUpgrade(w http.ResponseWriter, r *http.Request) clientConn, clientBuf, err := hijacker.Hijack() if err != nil { - logError("http/upgrade/hijack", err) + logError("http/upgrade/hijack", err, clientIP, credID) return } defer clientConn.Close() diff --git a/internal/ca/ca.go b/internal/ca/ca.go index 6e1d5a7..33a1a1d 100644 --- a/internal/ca/ca.go +++ b/internal/ca/ca.go @@ -7,6 +7,7 @@ import ( "crypto/x509/pkix" "encoding/pem" "fmt" + "log/slog" "math/big" "os" "path/filepath" @@ -44,8 +45,8 @@ func LoadOrGenerate(caDir string) (*x509.Certificate, *rsa.PrivateKey, error) { return nil, nil, fmt.Errorf("failed to save CA: %w", err) } - fmt.Fprintf(os.Stderr, "Generated new CA certificate at %s\n", certPath) - fmt.Fprintf(os.Stderr, "Trust this certificate in your OS/browser to use HTTPS interception.\n") + slog.Info("generated new CA certificate", "path", certPath) + slog.Info("trust this certificate in your OS/browser to use HTTPS interception") return cert, key, nil } diff --git a/log.go b/log.go index 9bc0ced..0841b69 100644 --- a/log.go +++ b/log.go @@ -1,19 +1,101 @@ package main import ( - "fmt" + "log/slog" "os" + "strings" "time" ) -func logRequest(method, url string, status int, duration time.Duration) { - fmt.Fprintf(os.Stderr, "%s %s %d %s\n", method, url, status, duration.Round(time.Millisecond)) +// setupLogging configures the default slog logger with the given level. +// Valid levels: "debug", "info", "warn", "error". Returns an error for +// unrecognized levels. +func setupLogging(level string) error { + var slevel slog.Level + switch strings.ToLower(level) { + case "debug": + slevel = slog.LevelDebug + case "info": + slevel = slog.LevelInfo + case "warn": + slevel = slog.LevelWarn + case "error": + slevel = slog.LevelError + default: + slevel = slog.LevelInfo + } + + handler := slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{ + Level: slevel, + }) + slog.SetDefault(slog.New(handler)) + return nil +} + +// shortUserID returns the first 8 characters of a credential ID, +// or "anon" if the credential ID is empty (unauthenticated). +func shortUserID(credentialID string) string { + if credentialID == "" { + return "anon" + } + if len(credentialID) > 8 { + return credentialID[:8] + } + return credentialID +} + +// logRequest logs a completed HTTP request at Debug level. +// Only visible when --log-level=debug. +func logRequest(method, url string, status int, duration time.Duration, clientIP, credentialID string) { + slog.Debug("request", + "method", method, + "url", url, + "status", status, + "duration", duration.Round(time.Millisecond), + "ip", clientIP, + "user", shortUserID(credentialID), + ) +} + +// logError logs an operational error at Error level. +func logError(context string, err error, clientIP, credentialID string) { + slog.Error(context, + "err", err, + "ip", clientIP, + "user", shortUserID(credentialID), + ) +} + +// logBlocked logs a blocked request at Info level. +func logBlocked(host, url, rule, clientIP, credentialID string) { + attrs := []any{ + "host", host, + "ip", clientIP, + "user", shortUserID(credentialID), + } + if url != "" { + attrs = append(attrs, "url", url) + } + if rule != "" { + attrs = append(attrs, "rule", rule) + } + slog.Info("blocked", attrs...) } -func logError(context string, err error) { - fmt.Fprintf(os.Stderr, "ERROR [%s] %v\n", context, err) +// logElementHidden logs a CSS element hiding injection at Debug level. +func logElementHidden(host, clientIP, credentialID string) { + slog.Debug("element-hidden", + "host", host, + "ip", clientIP, + "user", shortUserID(credentialID), + ) } -func logPassthrough(host string) { - fmt.Fprintf(os.Stderr, "PASSTHROUGH %s\n", host) +// logPassthrough logs a passthrough tunnel at Debug level. +func logPassthrough(host, clientIP, credentialID string) { + slog.Debug("passthrough", + "host", host, + "ip", clientIP, + "user", shortUserID(credentialID), + ) } diff --git a/log_test.go b/log_test.go new file mode 100644 index 0000000..a6c75fe --- /dev/null +++ b/log_test.go @@ -0,0 +1,160 @@ +package main + +import ( + "bytes" + "log/slog" + "strings" + "testing" + "time" +) + +func TestShortUserID(t *testing.T) { + tests := []struct { + input string + want string + }{ + {"", "anon"}, + {"AbCdEfGhIjKlMnOp", "AbCdEfGh"}, + {"short", "short"}, + {"exactly8", "exactly8"}, + } + for _, tt := range tests { + got := shortUserID(tt.input) + if got != tt.want { + t.Errorf("shortUserID(%q) = %q, want %q", tt.input, got, tt.want) + } + } +} + +// withLogCapture sets up a slog logger that writes to a buffer at the given +// level, runs fn, then restores the previous default logger. +func withLogCapture(level slog.Level, fn func()) string { + var buf bytes.Buffer + handler := slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: level}) + prev := slog.Default() + slog.SetDefault(slog.New(handler)) + defer slog.SetDefault(prev) + fn() + return buf.String() +} + +func TestLogRequestIsDebugLevel(t *testing.T) { + // At info level, logRequest should produce no output + output := withLogCapture(slog.LevelInfo, func() { + logRequest("GET", "https://example.com/page", 200, 45*time.Millisecond, "192.168.1.5", "AbCdEfGhIjKl") + }) + if output != "" { + t.Errorf("logRequest at info level should produce no output, got: %s", output) + } + + // At debug level, logRequest should produce output + output = withLogCapture(slog.LevelDebug, func() { + logRequest("GET", "https://example.com/page", 200, 45*time.Millisecond, "192.168.1.5", "AbCdEfGhIjKl") + }) + if output == "" { + t.Error("logRequest at debug level should produce output") + } + if !strings.Contains(output, "level=DEBUG") { + t.Errorf("expected level=DEBUG, got: %s", output) + } + if !strings.Contains(output, "ip=192.168.1.5") { + t.Errorf("expected ip=192.168.1.5, got: %s", output) + } + if !strings.Contains(output, "user=AbCdEfGh") { + t.Errorf("expected user=AbCdEfGh (truncated), got: %s", output) + } +} + +func TestLogBlockedIsInfoLevel(t *testing.T) { + output := withLogCapture(slog.LevelInfo, func() { + logBlocked("ads.example.com", "https://ads.example.com/banner.js", "||ads.example.com^", "10.0.0.1", "CredIDxyz12345") + }) + if !strings.Contains(output, "level=INFO") { + t.Errorf("expected level=INFO, got: %s", output) + } + if !strings.Contains(output, "msg=blocked") { + t.Errorf("expected msg=blocked, got: %s", output) + } + if !strings.Contains(output, "ip=10.0.0.1") { + t.Errorf("expected ip=10.0.0.1, got: %s", output) + } + if !strings.Contains(output, "user=CredIDxy") { + t.Errorf("expected user=CredIDxy (truncated), got: %s", output) + } +} + +func TestLogPassthroughIsDebugLevel(t *testing.T) { + // At info level, logPassthrough should produce no output + output := withLogCapture(slog.LevelInfo, func() { + logPassthrough("bank.example.com", "192.168.1.10", "") + }) + if output != "" { + t.Errorf("logPassthrough at info level should produce no output, got: %s", output) + } + + // At debug level, logPassthrough should produce output + output = withLogCapture(slog.LevelDebug, func() { + logPassthrough("bank.example.com", "192.168.1.10", "") + }) + if !strings.Contains(output, "level=DEBUG") { + t.Errorf("expected level=DEBUG, got: %s", output) + } + if !strings.Contains(output, "msg=passthrough") { + t.Errorf("expected msg=passthrough, got: %s", output) + } + if !strings.Contains(output, "user=anon") { + t.Errorf("expected user=anon for empty credential, got: %s", output) + } +} + +func TestLogElementHiddenIsDebugLevel(t *testing.T) { + // At info level, logElementHidden should produce no output + output := withLogCapture(slog.LevelInfo, func() { + logElementHidden("example.com", "192.168.1.5", "CredABCD1234") + }) + if output != "" { + t.Errorf("logElementHidden at info level should produce no output, got: %s", output) + } + + // At debug level, logElementHidden should produce output + output = withLogCapture(slog.LevelDebug, func() { + logElementHidden("example.com", "192.168.1.5", "CredABCD1234") + }) + if !strings.Contains(output, "level=DEBUG") { + t.Errorf("expected level=DEBUG, got: %s", output) + } + if !strings.Contains(output, "msg=element-hidden") { + t.Errorf("expected msg=element-hidden, got: %s", output) + } + if !strings.Contains(output, "host=example.com") { + t.Errorf("expected host=example.com, got: %s", output) + } +} + +func TestLogErrorIsErrorLevel(t *testing.T) { + output := withLogCapture(slog.LevelInfo, func() { + logError("connect/roundtrip", errForTest("dial tcp: timeout"), "192.168.1.5", "SomeCredID") + }) + if !strings.Contains(output, "level=ERROR") { + t.Errorf("expected level=ERROR, got: %s", output) + } + if !strings.Contains(output, "ip=192.168.1.5") { + t.Errorf("expected ip=192.168.1.5, got: %s", output) + } +} + +func TestLogErrorSuppressedAtWarnLevel(t *testing.T) { + // logError is ERROR level -- should NOT appear when level is set higher + // (there is no level higher than ERROR in slog, so this test just + // verifies it appears at warn level, which is lower than error) + output := withLogCapture(slog.LevelWarn, func() { + logError("test/context", errForTest("some error"), "1.2.3.4", "") + }) + if !strings.Contains(output, "level=ERROR") { + t.Errorf("logError should still appear at warn level, got: %s", output) + } +} + +type errForTest string + +func (e errForTest) Error() string { return string(e) } diff --git a/main.go b/main.go index 0a455ae..46678f8 100644 --- a/main.go +++ b/main.go @@ -4,6 +4,7 @@ import ( "context" "crypto/x509" "fmt" + "log/slog" "net" "net/http" "os" @@ -80,6 +81,12 @@ func main() { Usage: "run in transparent proxy mode (intercept redirected traffic instead of explicit proxy)", Sources: cli.EnvVars("UBLPROXY_TRANSPARENT"), }, + &cli.StringFlag{ + Name: "log-level", + Value: "info", + Usage: "log verbosity level (debug, info, warn, error)", + Sources: cli.EnvVars("UBLPROXY_LOG_LEVEL"), + }, }, Action: run, } @@ -91,6 +98,8 @@ func main() { } func run(_ context.Context, cmd *cli.Command) error { + setupLogging(cmd.String("log-level")) + addr := cmd.String("addr") httpPort := cmd.Int("http-port") httpsPort := cmd.Int("https-port") @@ -170,9 +179,9 @@ func runExplicitProxy(handler *proxyHandler, api *apiHandler, certs *ca.Cache, c portalOrigin: portalOrigin, httpOrigin: httpOrigin, } - fmt.Fprintf(os.Stderr, "ublproxy setup page on http://%s\n", httpAddr) - fmt.Fprintf(os.Stderr, "ublproxy mobile proxy on %s\n", httpOrigin) - fmt.Fprintf(os.Stderr, "ublproxy proxy+portal on %s\n", portalOrigin) + slog.Info("ublproxy setup page", "url", "http://"+httpAddr) + slog.Info("ublproxy mobile proxy", "url", httpOrigin) + slog.Info("ublproxy proxy+portal", "url", portalOrigin) if err := http.ListenAndServe(httpAddr, setupH); err != nil { return fmt.Errorf("server error: %w", err) @@ -183,7 +192,7 @@ func runExplicitProxy(handler *proxyHandler, api *apiHandler, certs *ca.Cache, c func runTransparent(handler *proxyHandler, certs *ca.Cache, hostname string, extraIPs []net.IP, httpsAddr, httpAddr string) error { trustTracker := newCATrustTracker() - fmt.Fprintf(os.Stderr, "ublproxy running in transparent proxy mode\n") + slog.Info("ublproxy running in transparent proxy mode") go startTransparentHTTPS(httpsAddr, handler, certs, hostname, extraIPs, trustTracker) startTransparentHTTP(httpAddr, handler, trustTracker, hostname) diff --git a/portal_https.go b/portal_https.go index 74f9cc9..4a1cb2d 100644 --- a/portal_https.go +++ b/portal_https.go @@ -2,7 +2,7 @@ package main import ( "crypto/tls" - "fmt" + "log/slog" "net" "net/http" "os" @@ -94,7 +94,7 @@ func (h *portalHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { func startPortalHTTPS(listenAddr string, host string, extraIPs []net.IP, certs *ca.Cache, handler *portalHandler) { cert, err := certs.PortalCert(host, extraIPs...) if err != nil { - fmt.Fprintf(os.Stderr, "portal: failed to generate TLS cert: %v\n", err) + slog.Error("portal: failed to generate TLS cert", "err", err) os.Exit(1) } @@ -111,10 +111,10 @@ func startPortalHTTPS(listenAddr string, host string, extraIPs []net.IP, certs * TLSNextProto: make(map[string]func(*http.Server, *tls.Conn, http.Handler)), } - fmt.Fprintf(os.Stderr, "ublproxy proxy+portal listening on https://%s\n", listenAddr) + slog.Info("ublproxy proxy+portal listening", "url", "https://"+listenAddr) if err := server.ListenAndServeTLS("", ""); err != nil { - fmt.Fprintf(os.Stderr, "server error: %v\n", err) + slog.Error("server error", "err", err) os.Exit(1) } } diff --git a/proxy.go b/proxy.go index f144378..fc37edc 100644 --- a/proxy.go +++ b/proxy.go @@ -4,8 +4,8 @@ import ( "crypto/tls" "fmt" "io" + "log/slog" "net/http" - "os" "strings" "sync" "sync/atomic" @@ -91,18 +91,18 @@ func (p *proxyHandler) loadUserRules(credentialID string) *blocklist.RuleSet { subURLs, err := p.store.ListEnabledSubscriptionURLs(credentialID) if err != nil { - fmt.Fprintf(os.Stderr, "user-rules: failed to load subscriptions for %s: %v\n", credentialID, err) + slog.Warn("user-rules: failed to load subscriptions", "user", shortUserID(credentialID), "err", err) } else { for _, url := range subURLs { if err := p.loadBlocklistSource(rs, url); err != nil { - fmt.Fprintf(os.Stderr, "user-rules: failed to load subscription %s: %v\n", url, err) + slog.Warn("user-rules: failed to load subscription", "url", url, "err", err) } } } dbRules, err := p.store.ListEnabledRules(credentialID) if err != nil { - fmt.Fprintf(os.Stderr, "user-rules: failed to load rules for %s: %v\n", credentialID, err) + slog.Warn("user-rules: failed to load rules", "user", shortUserID(credentialID), "err", err) } else { for _, r := range dbRules { rs.AddLine(r.Rule) @@ -215,13 +215,13 @@ func (p *proxyHandler) reloadBaseline() { // Load static blocklists (CLI --blocklist flags) for _, src := range p.blocklistSources { if err := p.loadBlocklistSource(rs, src); err != nil { - fmt.Fprintf(os.Stderr, "baseline: failed to load blocklist %s: %v\n", src, err) + slog.Warn("baseline: failed to load blocklist", "source", src, "err", err) } } p.baselineRules.Store(rs) if rs.HostCount() > 0 || rs.RuleCount() > 0 { - fmt.Fprintf(os.Stderr, "baseline: loaded %d hostnames, %d URL rules\n", rs.HostCount(), rs.RuleCount()) + slog.Info("baseline loaded", "hostnames", rs.HostCount(), "rules", rs.RuleCount()) } } @@ -252,7 +252,7 @@ func (p *proxyHandler) loadBlocklistURL(rs *blocklist.RuleSet, url string) error if p.store != nil { cached, cacheErr := p.store.GetCachedBlocklist(url) if cacheErr == nil && cached != nil { - fmt.Fprintf(os.Stderr, "reload: using stale cache for %s (download failed: %v)\n", url, err) + slog.Warn("reload: using stale cache", "url", url, "err", err) return rs.LoadReader(strings.NewReader(string(cached.Content))) } } @@ -262,7 +262,7 @@ func (p *proxyHandler) loadBlocklistURL(rs *blocklist.RuleSet, url string) error // Save to cache if p.store != nil { if cacheErr := p.store.SetCachedBlocklist(url, content); cacheErr != nil { - fmt.Fprintf(os.Stderr, "reload: failed to cache %s: %v\n", url, cacheErr) + slog.Warn("reload: failed to cache", "url", url, "err", cacheErr) } } @@ -290,7 +290,7 @@ func downloadBlocklist(url string) ([]byte, error) { } // logActivity records a proxy event to the activity log if available. -func (p *proxyHandler) logActivity(entryType, host, url, rule string) { +func (p *proxyHandler) logActivity(entryType, host, url, rule, clientIP, credentialID string) { if p.activityLog == nil { return } @@ -299,6 +299,8 @@ func (p *proxyHandler) logActivity(entryType, host, url, rule string) { Host: host, URL: url, Rule: rule, + IP: clientIP, + User: shortUserID(credentialID), }) } diff --git a/static/activity.gohtml b/static/activity.gohtml index fd2f3be..c902894 100644 --- a/static/activity.gohtml +++ b/static/activity.gohtml @@ -108,6 +108,11 @@ detail.appendChild(ruleEl); } + var meta = document.createElement('div'); + meta.className = 'activity-meta'; + meta.textContent = entry.ip + (entry.user ? ' \u00b7 ' + entry.user : ''); + detail.appendChild(meta); + li.appendChild(time); li.appendChild(badge); li.appendChild(detail); diff --git a/static/shared.css b/static/shared.css index 14dd0d1..b07a2a2 100644 --- a/static/shared.css +++ b/static/shared.css @@ -474,6 +474,12 @@ kbd { margin-top: 0.15rem; } +.activity-meta { + color: var(--color-text-faint); + font-size: 0.72rem; + margin-top: 0.15rem; +} + /* Filter bar */ .filter-bar { display: flex; diff --git a/transparent.go b/transparent.go index c61d8d2..aafbbc3 100644 --- a/transparent.go +++ b/transparent.go @@ -6,6 +6,7 @@ import ( "errors" "fmt" "io" + "log/slog" "net" "net/http" "os" @@ -290,10 +291,12 @@ func (h *transparentHTTPHandler) servePortal(w http.ResponseWriter, r *http.Requ func (h *transparentHTTPHandler) forwardHTTP(w http.ResponseWriter, r *http.Request, host string) { targetURL := "http://" + host + r.URL.RequestURI() clientIP := clientIPFromRequest(r) + credID := h.proxy.credentialForIP(clientIP) ctx := matchContextFromRequest(r) if h.proxy.shouldBlock(clientIP, targetURL, ctx) { - h.proxy.logActivity(ActivityBlocked, host, targetURL, "") + h.proxy.logActivity(ActivityBlocked, host, targetURL, "", clientIP, credID) + logBlocked(host, targetURL, "", clientIP, credID) w.WriteHeader(http.StatusNoContent) return } @@ -308,7 +311,7 @@ func (h *transparentHTTPHandler) forwardHTTP(w http.ResponseWriter, r *http.Requ outReq, err := http.NewRequestWithContext(r.Context(), r.Method, targetURL, r.Body) if err != nil { - logError("transparent-http/new-request", err) + logError("transparent-http/new-request", err, clientIP, credID) http.Error(w, "bad request", http.StatusBadRequest) return } @@ -318,7 +321,7 @@ func (h *transparentHTTPHandler) forwardHTTP(w http.ResponseWriter, r *http.Requ resp, err := h.proxy.transport.RoundTrip(outReq) if err != nil { - logError("transparent-http/roundtrip", err) + logError("transparent-http/roundtrip", err, clientIP, credID) http.Error(w, "upstream error", http.StatusBadGateway) return } @@ -332,7 +335,7 @@ func (h *transparentHTTPHandler) forwardHTTP(w http.ResponseWriter, r *http.Requ w.Header().Del("Content-Length") w.WriteHeader(resp.StatusCode) w.Write(modified) - logRequest(r.Method, targetURL, resp.StatusCode, time.Since(start)) + logRequest(r.Method, targetURL, resp.StatusCode, time.Since(start), clientIP, credID) return } } @@ -342,16 +345,19 @@ func (h *transparentHTTPHandler) forwardHTTP(w http.ResponseWriter, r *http.Requ w.WriteHeader(resp.StatusCode) io.Copy(w, resp.Body) - logRequest(r.Method, targetURL, resp.StatusCode, time.Since(start)) + logRequest(r.Method, targetURL, resp.StatusCode, time.Since(start), clientIP, credID) } // forwardHTTPUpgrade handles WebSocket and other protocol upgrade requests // in transparent HTTP mode. It mirrors proxyHandler.handleHTTPUpgrade but // builds the target URL from the Host header. func (h *transparentHTTPHandler) forwardHTTPUpgrade(w http.ResponseWriter, r *http.Request, targetURL string) { + clientIP := clientIPFromRequest(r) + credID := h.proxy.credentialForIP(clientIP) + outReq, err := http.NewRequestWithContext(r.Context(), r.Method, targetURL, r.Body) if err != nil { - logError("transparent-http/upgrade/new-request", err) + logError("transparent-http/upgrade/new-request", err, clientIP, credID) http.Error(w, "bad request", http.StatusBadRequest) return } @@ -365,7 +371,7 @@ func (h *transparentHTTPHandler) forwardHTTPUpgrade(w http.ResponseWriter, r *ht resp, err := h.proxy.transport.RoundTrip(outReq) if err != nil { - logError("transparent-http/upgrade/roundtrip", err) + logError("transparent-http/upgrade/roundtrip", err, clientIP, credID) http.Error(w, "upstream error", http.StatusBadGateway) return } @@ -395,7 +401,7 @@ func (h *transparentHTTPHandler) forwardHTTPUpgrade(w http.ResponseWriter, r *ht clientConn, clientBuf, err := hijacker.Hijack() if err != nil { - logError("transparent-http/upgrade/hijack", err) + logError("transparent-http/upgrade/hijack", err, clientIP, credID) return } defer clientConn.Close() @@ -421,7 +427,7 @@ func serveTransparentTLS(ln net.Listener, proxy *proxyHandler, certs *ca.Cache, if errors.Is(err, net.ErrClosed) { return } - logError("transparent-tls/accept", err) + logError("transparent-tls/accept", err, "", "") continue } go handleTransparentTLSConn(conn, proxy, certs, portalHost, portalIPs, trustTracker) @@ -433,42 +439,45 @@ func handleTransparentTLSConn(conn net.Conn, proxy *proxyHandler, certs *ca.Cach conn.SetDeadline(time.Now().Add(10 * time.Second)) + clientIP, _, _ := net.SplitHostPort(conn.RemoteAddr().String()) + br := bufio.NewReader(conn) sni, err := extractSNI(br) if err != nil { - logError("transparent-tls/sni", err) + logError("transparent-tls/sni", err, clientIP, "") return } if sni == "" { - logError("transparent-tls/sni", errors.New("no SNI in ClientHello")) + logError("transparent-tls/sni", errors.New("no SNI in ClientHello"), clientIP, "") return } - clientIP, _, _ := net.SplitHostPort(conn.RemoteAddr().String()) + credID := proxy.credentialForIP(clientIP) // Portal access: serve the management portal when client connects // to the proxy's own hostname or IP if sni == portalHost || isPortalIP(sni, portalIPs) { - handleTransparentPortalTLS(conn, br, proxy, certs, portalHost, portalIPs) + handleTransparentPortalTLS(conn, br, proxy, certs, portalHost, portalIPs, clientIP) return } // Blocked host: close connection if proxy.shouldBlockHost(clientIP, sni) { - proxy.logActivity(ActivityBlocked, sni, "", "||"+sni+"^") + proxy.logActivity(ActivityBlocked, sni, "", "||"+sni+"^", clientIP, credID) + logBlocked(sni, "", "||"+sni+"^", clientIP, credID) return } // Passthrough: relay raw TCP to upstream if proxy.isHostExcepted(clientIP, sni) { - proxy.logActivity(ActivityPassthrough, sni, "", "@@||"+sni+"^") - handleTransparentPassthrough(conn, br, sni) + proxy.logActivity(ActivityPassthrough, sni, "", "@@||"+sni+"^", clientIP, credID) + handleTransparentPassthrough(conn, br, sni, clientIP, credID) return } // MITM: generate cert, complete TLS handshake, proxy requests - handleTransparentMITM(conn, br, proxy, certs, sni, clientIP, trustTracker) + handleTransparentMITM(conn, br, proxy, certs, sni, clientIP, credID, trustTracker) } func isPortalIP(sni string, portalIPs []net.IP) bool { @@ -486,10 +495,10 @@ func isPortalIP(sni string, portalIPs []net.IP) bool { // handleTransparentPortalTLS completes a TLS handshake using the portal // certificate and serves the management portal over HTTPS. -func handleTransparentPortalTLS(conn net.Conn, br *bufio.Reader, proxy *proxyHandler, certs *ca.Cache, portalHost string, portalIPs []net.IP) { +func handleTransparentPortalTLS(conn net.Conn, br *bufio.Reader, proxy *proxyHandler, certs *ca.Cache, portalHost string, portalIPs []net.IP, clientIP string) { cert, err := certs.PortalCert(portalHost, portalIPs...) if err != nil { - logError("transparent-tls/portal-cert", err) + logError("transparent-tls/portal-cert", err, clientIP, "") return } @@ -500,7 +509,7 @@ func handleTransparentPortalTLS(conn net.Conn, br *bufio.Reader, proxy *proxyHan Certificates: []tls.Certificate{*cert}, }) if err := tlsConn.Handshake(); err != nil { - logError("transparent-tls/portal-handshake", err) + logError("transparent-tls/portal-handshake", err, clientIP, "") return } defer tlsConn.Close() @@ -523,17 +532,17 @@ func handleTransparentPortalTLS(conn net.Conn, br *bufio.Reader, proxy *proxyHan // handleTransparentPassthrough relays raw TCP bytes between the client // and the upstream server. The peeked ClientHello bytes are forwarded // to upstream so the TLS handshake completes end-to-end. -func handleTransparentPassthrough(conn net.Conn, br *bufio.Reader, sni string) { +func handleTransparentPassthrough(conn net.Conn, br *bufio.Reader, sni, clientIP, credID string) { upstream, err := net.DialTimeout("tcp", net.JoinHostPort(sni, "443"), 10*time.Second) if err != nil { - logError("transparent-tls/passthrough-dial", err) + logError("transparent-tls/passthrough-dial", err, clientIP, credID) return } defer upstream.Close() conn.SetDeadline(time.Time{}) - logPassthrough(sni) + logPassthrough(sni, clientIP, credID) // Replay buffered bytes + remaining connection data to upstream replayReader := &readerWriter{r: br, w: conn} @@ -543,10 +552,10 @@ func handleTransparentPassthrough(conn net.Conn, br *bufio.Reader, sni string) { // handleTransparentMITM generates a MITM certificate for the SNI hostname, // completes a TLS handshake with the client, then proxies HTTP requests // inside the tunnel to the upstream server. -func handleTransparentMITM(conn net.Conn, br *bufio.Reader, proxy *proxyHandler, certs *ca.Cache, sni, clientIP string, trustTracker *caTrustTracker) { +func handleTransparentMITM(conn net.Conn, br *bufio.Reader, proxy *proxyHandler, certs *ca.Cache, sni, clientIP, credID string, trustTracker *caTrustTracker) { tlsCert, err := certs.GetCert(sni) if err != nil { - logError("transparent-tls/cert", err) + logError("transparent-tls/cert", err, clientIP, credID) return } @@ -558,7 +567,7 @@ func handleTransparentMITM(conn net.Conn, br *bufio.Reader, proxy *proxyHandler, }) if err := tlsConn.Handshake(); err != nil { // Client doesn't trust our CA — this is expected for unconfigured clients - logError("transparent-tls/client-tls", err) + logError("transparent-tls/client-tls", err, clientIP, credID) return } defer tlsConn.Close() @@ -569,7 +578,7 @@ func handleTransparentMITM(conn net.Conn, br *bufio.Reader, proxy *proxyHandler, conn.SetDeadline(time.Time{}) // Proxy HTTP requests inside the TLS tunnel - proxy.proxyTLSRequests(tlsConn, sni, "443", clientIP, false) + proxy.proxyTLSRequests(tlsConn, sni, "443", clientIP, credID, false) } // replayConn wraps a net.Conn with a bufio.Reader that may have buffered @@ -633,10 +642,10 @@ func startTransparentHTTP(listenAddr string, proxy *proxyHandler, trustTracker * portalHost: portalHost, } - fmt.Fprintf(os.Stderr, "ublproxy transparent HTTP on http://%s\n", listenAddr) + slog.Info("ublproxy transparent HTTP", "url", "http://"+listenAddr) if err := http.ListenAndServe(listenAddr, handler); err != nil { - fmt.Fprintf(os.Stderr, "transparent HTTP error: %v\n", err) + slog.Error("transparent HTTP error", "err", err) os.Exit(1) } } @@ -646,11 +655,11 @@ func startTransparentHTTP(listenAddr string, proxy *proxyHandler, trustTracker * func startTransparentHTTPS(listenAddr string, proxy *proxyHandler, certs *ca.Cache, portalHost string, portalIPs []net.IP, trustTracker *caTrustTracker) { ln, err := net.Listen("tcp", listenAddr) if err != nil { - fmt.Fprintf(os.Stderr, "transparent HTTPS listen error: %v\n", err) + slog.Error("transparent HTTPS listen error", "err", err) os.Exit(1) } - fmt.Fprintf(os.Stderr, "ublproxy transparent HTTPS on %s\n", listenAddr) + slog.Info("ublproxy transparent HTTPS", "addr", listenAddr) serveTransparentTLS(ln, proxy, certs, portalHost, portalIPs, trustTracker) }