From 0069b8dd38114fc161baf8d06091fde787ce8a1d Mon Sep 17 00:00:00 2001 From: Kristoffer Dalby Date: Sat, 17 Oct 2026 09:14:21 +0000 Subject: [PATCH] hscontrol: bound client-chosen text in request logs Clip at the sinks: handler errors, the request line, SSH local_user. --- hscontrol/app.go | 4 +- hscontrol/handlers.go | 39 +++++- hscontrol/handlers_test.go | 211 +++++++++++++++++++++++++++++++ hscontrol/noise.go | 3 +- hscontrol/util/zlog/zf/fields.go | 1 + 5 files changed, 251 insertions(+), 7 deletions(-) diff --git a/hscontrol/app.go b/hscontrol/app.go index 90580c8f1..ac724db38 100644 --- a/hscontrol/app.go +++ b/hscontrol/app.go @@ -1370,8 +1370,8 @@ func (z *zerologRequestLogger) NewLogEntry( r *http.Request, ) middleware.LogEntry { return &zerologLogEntry{ - method: r.Method, - path: r.URL.Path, + method: clipForLog(r.Method), + path: clipForLog(r.URL.Path), proto: r.Proto, remote: r.RemoteAddr, } diff --git a/hscontrol/handlers.go b/hscontrol/handlers.go index a4c981a22..e34c67d5c 100644 --- a/hscontrol/handlers.go +++ b/hscontrol/handlers.go @@ -13,22 +13,51 @@ import ( "github.com/juanfont/headscale/hscontrol/assets" "github.com/juanfont/headscale/hscontrol/templates" "github.com/juanfont/headscale/hscontrol/types" + "github.com/juanfont/headscale/hscontrol/util/zlog/zf" "github.com/rs/zerolog/log" "tailscale.com/tailcfg" + "tailscale.com/util/truncate" ) const ( reservedResponseHeaderSize = 4 ) +// logTextLimit bounds the client-chosen text copied into one log field. +// Inside the Noise tunnel, header compression makes resending a long +// request target nearly free for the client. +const logTextLimit = 512 + +// clipForLog cuts client-chosen text to [logTextLimit] for a log field. +func clipForLog(s string) string { + if len(s) <= logTextLimit { + return s + } + + return truncate.String(s, logTextLimit) + "..." +} + +// errForLog clips an error's text for logging, as parse errors quote the +// request. What the caller handles and the client is sent is unchanged. +func errForLog(err error) error { + if err == nil || len(err.Error()) <= logTextLimit { + return err + } + + return errors.New(clipForLog(err.Error())) //nolint:err113 // log-only copy +} + // httpError logs an error and sends an HTTP error response with the given. func httpError(w http.ResponseWriter, err error) { if herr, ok := errors.AsType[HTTPError](err); ok { http.Error(w, herr.Msg, herr.Code) - log.Error().Err(herr.Err).Int("code", herr.Code).Msgf("user msg: %s", herr.Msg) + log.Error().Err(errForLog(herr.Err)).Int(zf.Code, herr.Code). + Msgf("user msg: %s", herr.Msg) } else { http.Error(w, "internal server error", http.StatusInternalServerError) - log.Error().Err(err).Int("code", http.StatusInternalServerError).Msg("http internal server error") + log.Error().Err(errForLog(err)). + Int(zf.Code, http.StatusInternalServerError). + Msg("http internal server error") } } @@ -48,9 +77,11 @@ func httpUserError(w http.ResponseWriter, err error) { userMsg = herr.UserMsg - log.Error().Err(herr.Err).Int("code", code).Msgf("user msg: %s", herr.Msg) + log.Error().Err(errForLog(herr.Err)).Int(zf.Code, code). + Msgf("user msg: %s", herr.Msg) } else { - log.Error().Err(err).Int("code", code).Msg("http internal server error") + log.Error().Err(errForLog(err)).Int(zf.Code, code). + Msg("http internal server error") } if userMsg == "" { diff --git a/hscontrol/handlers_test.go b/hscontrol/handlers_test.go index 4433f16ed..4777e7d37 100644 --- a/hscontrol/handlers_test.go +++ b/hscontrol/handlers_test.go @@ -9,12 +9,17 @@ import ( "net/http" "net/http/httptest" "net/netip" + "net/url" "strings" + "sync" "testing" "time" + "github.com/go-chi/chi/v5" "github.com/juanfont/headscale/hscontrol/capver" "github.com/juanfont/headscale/hscontrol/types" + "github.com/rs/zerolog" + "github.com/rs/zerolog/log" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "tailscale.com/tailcfg" @@ -350,3 +355,209 @@ func TestHttpUserError(t *testing.T) { }) } } + +// logBuffer collects log lines; the global logger may be written from more +// than one goroutine. +type logBuffer struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (b *logBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + + return b.buf.Write(p) +} + +// entries returns the logged lines whose message is msg. +func (b *logBuffer) entries(t *testing.T, msg string) []map[string]any { + t.Helper() + + b.mu.Lock() + defer b.mu.Unlock() + + var out []map[string]any + + for line := range strings.Lines(b.buf.String()) { + var entry map[string]any + require.NoError(t, json.Unmarshal([]byte(line), &entry), "line=%q", line) + + if entry[zerolog.MessageFieldName] == msg { + entry["line.len"] = len(line) + out = append(out, entry) + } + } + + return out +} + +// captureLog sends the global logger to a buffer at level until the test +// ends. It changes process-wide state, so callers must not run in parallel, +// and must call it before starting anything that logs. +func captureLog(t *testing.T, level zerolog.Level) *logBuffer { + t.Helper() + + buf := &logBuffer{} + prevLogger, prevLevel := log.Logger, zerolog.GlobalLevel() + + log.Logger = zerolog.New(buf) + + zerolog.SetGlobalLevel(level) + + t.Cleanup(func() { + log.Logger = prevLogger + + zerolog.SetGlobalLevel(prevLevel) + }) + + return buf +} + +// requireClipped checks that logged is original cut to the log text limit. +func requireClipped(t *testing.T, original, logged string) { + t.Helper() + + require.LessOrEqual(t, len(logged), logTextLimit+len("...")) + require.True(t, strings.HasSuffix(logged, "..."), "clipped text must say so") + require.True(t, strings.HasPrefix(original, strings.TrimSuffix(logged, "...")), + "clipped text must be a prefix of the original") +} + +// TestClientTextIsClippedInLogs pins that text a client chooses is cut before +// it reaches a log line, while the response it is sent stays as it was. +// +//nolint:paralleltest // captureLog swaps the global logger. +func TestClientTextIsClippedInLogs(t *testing.T) { + t.Run("error detail", func(t *testing.T) { + buf := captureLog(t, zerolog.ErrorLevel) + + version := strings.Repeat("x", 4000) + req := httptest.NewRequestWithContext( + context.Background(), http.MethodGet, "/key?v="+version, nil, + ) + rec := httptest.NewRecorder() + + (&Headscale{}).KeyHandler(rec, req) + require.Equal(t, http.StatusBadRequest, rec.Code) + + _, err := parseCapabilityVersion(req) + herr, ok := errors.AsType[HTTPError](err) + require.True(t, ok) + + entries := buf.entries(t, "user msg: invalid capability version") + require.Len(t, entries, 1) + + logged, _ := entries[0][zerolog.ErrorFieldName].(string) + requireClipped(t, herr.Err.Error(), logged) + }) + + t.Run("unparsable node id", func(t *testing.T) { + buf := captureLog(t, zerolog.ErrorLevel) + + nodeID := strings.Repeat("x", 4000) + req := httptest.NewRequestWithContext( + context.Background(), http.MethodGet, "/machine/ssh/action/x/to/1", nil, + ) + rctx := chi.NewRouteContext() + rctx.URLParams.Add("src_node_id", nodeID) + rctx.URLParams.Add("dst_node_id", "1") + req = req.WithContext(context.WithValue(req.Context(), chi.RouteCtxKey, rctx)) + rec := httptest.NewRecorder() + + // A nil headscale proves the request is refused before any lookup. + (&noiseServer{}).SSHActionHandler(rec, req) + require.Equal(t, http.StatusBadRequest, rec.Code) + + entries := buf.entries(t, "user msg: Invalid src_node_id") + require.Len(t, entries, 1) + assert.Less(t, entries[0]["line.len"], 1024) + }) + + t.Run("ssh local user", func(t *testing.T) { + buf := captureLog(t, zerolog.InfoLevel) + + app := createTestApp(t) + user := app.state.CreateUserForTest("clip-ssh-user") + src := putTestNodeInStore(t, app, user, "clip-src") + dst := putTestNodeInStore(t, app, user, "clip-dst") + + localUser := strings.Repeat("u", 4000) + req := newSSHActionRequest(t, src.ID, dst.ID) + req.URL.RawQuery = url.Values{"local_user": {localUser}}.Encode() + rec := httptest.NewRecorder() + + (&noiseServer{headscale: app, machineKey: dst.MachineKey}). + SSHActionHandler(rec, req) + require.Equal(t, http.StatusOK, rec.Code, "body=%q", rec.Body.String()) + + entries := buf.entries(t, "SSH check denied: no matching check rule") + require.Len(t, entries, 1) + + logged, _ := entries[0]["local_user"].(string) + requireClipped(t, localUser, logged) + }) +} + +func TestRequestLoggerClipsClientText(t *testing.T) { + t.Parallel() + + path := "/" + strings.Repeat("p", 4096) + req := httptest.NewRequestWithContext( + context.Background(), http.MethodGet, path, nil, + ) + req.Method = strings.Repeat("M", 4096) + + entry, ok := (&zerologRequestLogger{}).NewLogEntry(req).(*zerologLogEntry) + require.True(t, ok) + + requireClipped(t, req.Method, entry.method) + requireClipped(t, path, entry.path) +} + +func TestClipForLog(t *testing.T) { + t.Parallel() + + tests := []struct { + name string + in string + want string + }{ + {name: "short", in: "short", want: "short"}, + { + name: "at limit", + in: strings.Repeat("a", logTextLimit), + want: strings.Repeat("a", logTextLimit), + }, + { + name: "over limit", + in: strings.Repeat("a", logTextLimit+1), + want: strings.Repeat("a", logTextLimit) + "...", + }, + { + name: "multi-byte rune across the limit", + in: strings.Repeat("a", logTextLimit-1) + "é" + "z", + want: strings.Repeat("a", logTextLimit-1) + "...", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + assert.Equal(t, tt.want, clipForLog(tt.in)) + }) + } +} + +func TestErrForLog(t *testing.T) { + t.Parallel() + + require.NoError(t, errForLog(nil)) + + short := errTestUnexpected + assert.Equal(t, short, errForLog(short), "a short error is logged as is") + + long := fmt.Errorf("parsing %q: %w", strings.Repeat("x", 4000), errTestUnexpected) + requireClipped(t, long.Error(), errForLog(long).Error()) +} diff --git a/hscontrol/noise.go b/hscontrol/noise.go index 137764f0e..0870961c1 100644 --- a/hscontrol/noise.go +++ b/hscontrol/noise.go @@ -18,6 +18,7 @@ import ( "github.com/juanfont/headscale/hscontrol/capver" "github.com/juanfont/headscale/hscontrol/dns" "github.com/juanfont/headscale/hscontrol/types" + "github.com/juanfont/headscale/hscontrol/util/zlog/zf" "github.com/rs/zerolog" "github.com/rs/zerolog/log" "tailscale.com/control/controlbase" @@ -413,7 +414,7 @@ func (ns *noiseServer) SSHActionHandler( reqLog := log.With(). Uint64("src_node_id", srcNodeID.Uint64()). Uint64("dst_node_id", dstNodeID.Uint64()). - Str("local_user", req.URL.Query().Get("local_user")). + Str(zf.LocalUser, clipForLog(req.URL.Query().Get("local_user"))). Logger() reqLog.Trace().Caller().Msg("SSH action request") diff --git a/hscontrol/util/zlog/zf/fields.go b/hscontrol/util/zlog/zf/fields.go index 1f67fc1e1..c3f1f5ff0 100644 --- a/hscontrol/util/zlog/zf/fields.go +++ b/hscontrol/util/zlog/zf/fields.go @@ -106,6 +106,7 @@ const ( Version = "version" StatusCode = "status_code" RegistrationID = "registration_id" + LocalUser = "local_user" ) // Network fields.