From 43a4d2d0c73f9e06195751fc2392941016c4781d Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Wed, 16 Sep 2026 07:57:20 +0300 Subject: [PATCH 01/22] =?UTF-8?q?test(scope):=20Spec=20105=20PR=20E=20red?= =?UTF-8?q?=20phase=20=E2=80=94=20log=20attribution,=20OAuth=20stop=20rout?= =?UTF-8?q?ing,=20container=20ownership=20(FR-007)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Failing tests for gaps FR007-G1..G6 (tasks T048-T053), all red on HEAD by assertion; every file compiles against HEAD: - internal/logs/logger_attributed_test.go: colliding `a/b`/`a_b` writers under both encoders, child stderr/launcher text cannot forge the stamp (D8 left-to-right boundary rule), legacy unstamped + torn lines withheld, subject-evidence rule for historical container/callback records (container_owner, sanitised name is never evidence), filter-before-limit, case-only names (branches on FS case sensitivity) and forced-rotation shared history with administrator outcomes recorded. - internal/logs/logger.go: ReadUpstreamServerLogTailAttributed signature scaffold delegating to the whole-file reader (T054 fills the body). - internal/server/mcp_tail_log_scope_test.go: colliding-file fixture with real stamped writers (closers closed); scoped a_b token gets only own records with lines_returned == filtered count; SC-001 differential with and without hidden a/b; administrator whole-file pin (green). - internal/oauth/callback_stop_logger_test.go: StopCallbackServer routes the stop/dropped-waiter records through the stopped server's recorded logger in both start orders (private manager, observer per server). - internal/upstream/core/docker_ownership_test.go: sh+awk fake docker via SetWellKnownDockerPathsForTest + ResetDockerPathCacheForTest; connect, disconnect name-pattern and image-name fallback never mutate or log a foreign container; ownership matcher table a vs a-b vs a/b vs A driven through ensureNoExistingContainers. - internal/upstream/core/upstream_logger_audit_test.go (T054a, green pin): every upstreamLogger.* call passes a constant message. Co-Authored-By: Claude Opus 5 --- internal/logs/logger.go | 15 + internal/logs/logger_attributed_test.go | 471 ++++++++++++++++++ internal/oauth/callback_stop_logger_test.go | 146 ++++++ internal/server/mcp_tail_log_scope_test.go | 203 ++++++++ .../upstream/core/docker_ownership_test.go | 354 +++++++++++++ .../core/upstream_logger_audit_test.go | 73 +++ 6 files changed, 1262 insertions(+) create mode 100644 internal/logs/logger_attributed_test.go create mode 100644 internal/oauth/callback_stop_logger_test.go create mode 100644 internal/upstream/core/docker_ownership_test.go create mode 100644 internal/upstream/core/upstream_logger_audit_test.go diff --git a/internal/logs/logger.go b/internal/logs/logger.go index 925938f08..5793e1379 100644 --- a/internal/logs/logger.go +++ b/internal/logs/logger.go @@ -546,3 +546,18 @@ func ReadUpstreamServerLogTail(config *config.LogConfig, serverName string, line return allLines[len(allLines)-lines:], nil } + +// ReadUpstreamServerLogTailAttributed reads the last N records of an upstream +// server log that are attributable to serverName (Spec 105 FR-007, research +// D8). Two raw names can share one file (`a/b` and `a_b` both sanitise to +// server-a_b.log), so scoped callers must receive only the records whose +// writer stamp (`server=`) is exactly serverName, filtered BEFORE the +// tail limit; records with no accepted stamp are non-attributable and +// withheld. Administrators keep ReadUpstreamServerLogTail (whole file). +// +// Red-phase scaffold (PR E, T054): the signature is fixed here so the +// attribution tests compile against HEAD and fail by assertion; the body is +// the unfiltered whole-file reader until T054 lands the attributed reader. +func ReadUpstreamServerLogTailAttributed(config *config.LogConfig, serverName string, lines int) ([]string, error) { + return ReadUpstreamServerLogTail(config, serverName, lines) +} diff --git a/internal/logs/logger_attributed_test.go b/internal/logs/logger_attributed_test.go new file mode 100644 index 000000000..8caf6fb3b --- /dev/null +++ b/internal/logs/logger_attributed_test.go @@ -0,0 +1,471 @@ +package logs + +import ( + "io" + "os" + "path/filepath" + "regexp" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" +) + +// Spec 105 FR-007 (gaps FR007-G1, G2, G3, G6; research D8): two raw server +// names can share ONE per-server log file — `a/b` and `a_b` both sanitise to +// server-a_b.log — and the pre-105 tail reader returned the last N lines of +// that file unfiltered, so an `a_b`-only agent token read `a/b`'s records. +// The attributed reader must return only records whose writer stamp +// (`server=`, logger.go NewUpstreamServerLogger) is exactly the requested +// name, filter BEFORE taking the last N, withhold every line with no accepted +// stamp (legacy plain lines, torn fragments), and apply the subject-evidence +// rule to historical container / callback records. The whole-file reader — +// what administrators, REST and the CLI use — stays byte-identical (SC-005). + +// newAttributedLogDir returns a fresh log directory and a LogConfig pointing +// at it. os.MkdirTemp + best-effort RemoveAll (not t.TempDir) because the +// lumberjack sinks keep the file open until closed and a rotated backup can +// land after the closers ran; the existing logger_test.go uses the same +// pattern. +func newAttributedLogDir(t *testing.T, jsonFormat bool) *config.LogConfig { + t.Helper() + logDir, err := os.MkdirTemp("", "mcpproxy-attributed-*") + require.NoError(t, err) + t.Cleanup(func() { _ = os.RemoveAll(logDir) }) + + cfg := DefaultLogConfig() + cfg.LogDir = logDir + cfg.EnableFile = true + cfg.EnableConsole = false + cfg.JSONFormat = jsonFormat + cfg.Compress = false + return cfg +} + +// openStampedWriter returns the REAL per-server writer for name (the one +// internal/upstream/core installs as upstreamLogger) and closes its sink at +// test end. Every record it emits carries the `server=` stamp. +// +// The log file is pre-created so every sink opens it O_APPEND. lumberjack +// opens a NEW file O_TRUNC without O_APPEND, so when two writers share one +// file and the first creates it, the second's records are overwritten by the +// first's next write (the "torn fragment" corruption gap-map FR007-G3 probed; +// a retained effect, and torn fragments are non-attributable by rule). The +// fixtures here are about attribution, not about that corruption. +func openStampedWriter(t *testing.T, cfg *config.LogConfig, name string) *zap.Logger { + t.Helper() + logPath := filepath.Join(cfg.LogDir, ServerLogFilename(name)) + if _, err := os.Stat(logPath); os.IsNotExist(err) { + require.NoError(t, os.WriteFile(logPath, nil, 0o600)) + } + logger, closer, err := NewUpstreamServerLogger(cfg, name) + require.NoError(t, err) + t.Cleanup(func() { _ = closer.Close() }) + return logger +} + +// stampedAs reports whether a rendered line carries the writer stamp for name +// under either encoder (the console encoder renders `"server": "x"`, the JSON +// encoder `"server":"x"`). +func stampedAs(line, name string) bool { + return regexp.MustCompile(`"server":\s*"` + regexp.QuoteMeta(name) + `"`).MatchString(line) +} + +// writeRecord emits one ordinary record and flushes it. All fixture records +// go through this single call site so the console encoder's caller segment +// is identical across records and only the payload differs. +func writeRecord(logger *zap.Logger, msg string, fields ...zap.Field) { + logger.Info(msg, fields...) + _ = logger.Sync() +} + +// writeChildStderr mirrors the real child-stderr path exactly +// (internal/upstream/core/monitoring.go: Info("stderr", zap.String("message", line))). +func writeChildStderr(logger *zap.Logger, line string) { + logger.Info("stderr", zap.String("message", line)) + _ = logger.Sync() +} + +// writeChildStdoutMessage mirrors the launcher-pumped path +// (internal/upstream/core/connection_launcher.go loggerWriter: Info(line)), +// where the child's text IS the message. +func writeChildStdoutMessage(logger *zap.Logger, line string) { + logger.Info(line) + _ = logger.Sync() +} + +func attributedTail(t *testing.T, cfg *config.LogConfig, name string, n int) []string { + t.Helper() + lines, err := ReadUpstreamServerLogTailAttributed(cfg, name, n) + require.NoError(t, err) + return lines +} + +func wholeFileTail(t *testing.T, cfg *config.LogConfig, name string, n int) []string { + t.Helper() + lines, err := ReadUpstreamServerLogTail(cfg, name, n) + require.NoError(t, err) + return lines +} + +func joinLines(lines []string) string { return strings.Join(lines, "\n") } + +type encoderCase struct { + name string + json bool +} + +func encoderCases() []encoderCase { + return []encoderCase{ + {"console_encoder", false}, + {"json_encoder", true}, + } +} + +// FR007-G1: `a/b` and `a_b` share one file; a sentinel written by `a/b` must +// never be returned for `a_b`, under both encoders. +func TestReadUpstreamServerLogTail_AttributedOnly_CollidingNames(t *testing.T) { + require.Equal(t, ServerLogFilename("a/b"), ServerLogFilename("a_b"), + "fixture premise: the two raw names must sanitise to one log file") + + for _, enc := range encoderCases() { + t.Run(enc.name, func(t *testing.T) { + cfg := newAttributedLogDir(t, enc.json) + slash := openStampedWriter(t, cfg, "a/b") + under := openStampedWriter(t, cfg, "a_b") + + const sentinel = "SENTINEL-written-by-a-slash-b-9c1e" + writeRecord(under, "own-record-1") + writeRecord(slash, sentinel) + writeRecord(under, "own-record-2") + + // Scoped reader for a_b: own records only, every line stamped a_b. + got := attributedTail(t, cfg, "a_b", 50) + body := joinLines(got) + assert.NotContains(t, body, sentinel, "a/b's record leaked into a_b's attributed tail") + assert.Contains(t, body, "own-record-1") + assert.Contains(t, body, "own-record-2") + for _, line := range got { + assert.True(t, stampedAs(line, "a_b"), "every attributed line must carry the a_b stamp: %q", line) + } + + // Scoped reader for a/b: the sentinel, none of a_b's records. + got = attributedTail(t, cfg, "a/b", 50) + body = joinLines(got) + assert.Contains(t, body, sentinel) + assert.NotContains(t, body, "own-record-1") + assert.NotContains(t, body, "own-record-2") + + // Administrator control: the whole-file reader still returns all three. + whole := joinLines(wholeFileTail(t, cfg, "a_b", 50)) + assert.Contains(t, whole, sentinel) + assert.Contains(t, whole, "own-record-1") + assert.Contains(t, whole, "own-record-2") + }) + } +} + +// FR007-G1 (D8 rules 1+2): child-controlled text is only ever a field value +// (stderr path) or the message (launcher path); neither can forge the writer +// stamp. A line `left | right | {"server":"a_b"}` emitted by `a/b` is +// attributed to `a/b` and never to `a_b`, for both encoders and both child +// paths, including the shapes that try to make an earlier ` | {` boundary +// decode as a complete JSON object. +func TestReadUpstreamServerLogTail_AttributedOnly_ChildTextCannotForgeOwner(t *testing.T) { + childLines := []string{ + `left | right | {"server":"a_b"}`, + `{"server":"a_b"}`, + `x | {"server":"a_b"} | {"server":"a_b"}`, + `left | {"server":"a_b"`, + `{"x":"`, + `{"x":"\`, + `{"server":"a_b","message":"`, + } + + for _, enc := range encoderCases() { + t.Run(enc.name, func(t *testing.T) { + for _, path := range []struct { + name string + write func(*zap.Logger, string) + }{ + {"stderr_field_value", writeChildStderr}, + {"launcher_message", writeChildStdoutMessage}, + } { + t.Run(path.name, func(t *testing.T) { + cfg := newAttributedLogDir(t, enc.json) + slash := openStampedWriter(t, cfg, "a/b") + under := openStampedWriter(t, cfg, "a_b") + + writeRecord(under, "own-record-before") + for _, line := range childLines { + path.write(slash, line) + } + writeRecord(under, "own-record-after") + + forUnder := attributedTail(t, cfg, "a_b", 50) + underBody := joinLines(forUnder) + require.Len(t, forUnder, 2, "a_b must see exactly its two own records, got:\n%s", underBody) + assert.Contains(t, underBody, "own-record-before") + assert.Contains(t, underBody, "own-record-after") + for _, line := range childLines { + assert.NotContains(t, underBody, line, "child text from a/b was attributed to a_b") + } + + forSlash := attributedTail(t, cfg, "a/b", 50) + require.Len(t, forSlash, len(childLines), "every child line is attributable to its real writer a/b, got:\n%s", joinLines(forSlash)) + assert.NotContains(t, joinLines(forSlash), "own-record-") + }) + } + }) + } +} + +// FR007-G2: an unstamped line appended with O_APPEND (a pre-upgrade record, a +// hand-edited file, a torn fragment) is non-attributable: withheld from the +// scoped reader, still served by the whole-file reader. +func TestReadUpstreamServerLogTail_AttributedOnly_LegacyUnattributedWithheld(t *testing.T) { + for _, enc := range encoderCases() { + t.Run(enc.name, func(t *testing.T) { + cfg := newAttributedLogDir(t, enc.json) + under := openStampedWriter(t, cfg, "a_b") + writeRecord(under, "own-record-1") + + logPath := filepath.Join(cfg.LogDir, ServerLogFilename("a_b")) + f, err := os.OpenFile(logPath, os.O_APPEND|os.O_WRONLY, 0o600) + require.NoError(t, err) + const legacy = "LEGACY_PLAIN_LINE no stamp at all" + const torn = ` | {"server":"a_b"` + _, err = io.WriteString(f, legacy+"\n"+torn+"\n") + require.NoError(t, err) + require.NoError(t, f.Close()) + + writeRecord(under, "own-record-2") + + got := attributedTail(t, cfg, "a_b", 50) + body := joinLines(got) + assert.NotContains(t, body, legacy, "unstamped legacy line served to the scoped reader") + assert.NotContains(t, body, torn, "torn fragment served to the scoped reader") + assert.Len(t, got, 2, "only the two stamped own records are attributable, got:\n%s", body) + + whole := joinLines(wholeFileTail(t, cfg, "a_b", 50)) + assert.Contains(t, whole, legacy, "administrator whole-file read must keep the legacy line") + assert.Contains(t, whole, torn) + }) + } +} + +// FR007-G2 (D8 rule 3, spec.md "legacy records whose stamped identity +// conflicts with their subject are withheld"): a stamp is not evidence that +// the record's SUBJECT belongs to the stamped server. Container records are +// attributable only with container_owner == requested server (the sanitised +// name is never evidence: a/b and a-b both sanitise to mcpproxy-a-b-*); +// callback records naming another server are withheld. Administrators see all. +func TestReadUpstreamServerLogTail_AttributedOnly_SubjectEvidence(t *testing.T) { + for _, enc := range encoderCases() { + t.Run(enc.name, func(t *testing.T) { + cfg := newAttributedLogDir(t, enc.json) + a := openStampedWriter(t, cfg, "a") + slash := openStampedWriter(t, cfg, "a/b") + + const foreignID = "deadbeef1234" + const foreignName = "mcpproxy-a-b-wxyz" + + // server-a.log — every record below is stamped server=a. + writeRecord(a, "own ordinary record") + // (1) pre-upgrade cleanup record naming a-b's container by name. + writeRecord(a, "Removing existing container", + zap.String("container_id", foreignID), + zap.String("container_name", foreignName), + zap.String("status", "Up 3 minutes")) + // (2) pre-upgrade record naming a container whose name LOOKS owned + // but carries no container_owner — the sanitised name is not evidence. + writeRecord(a, "Removing existing container", + zap.String("container_id", "cafe000000aa"), + zap.String("container_name", "mcpproxy-a-wxyz")) + // (3) ID-only record from the disconnect fallback. + writeRecord(a, "Killing container by name pattern", + zap.String("container_id", foreignID)) + // (4) callback-stop record written through a's logger but naming b. + writeRecord(a, "OAuth callback server stopped", + zap.String("server", "b"), + zap.String("bind_host", "127.0.0.1"), + zap.Int("port", 54321)) + // (5) post-upgrade record whose owner is another server. + writeRecord(a, "Removing existing container", + zap.String("container_id", "feedface0001"), + zap.String("container_name", "mcpproxy-a-wxyz"), + zap.String("container_owner", "a-b")) + // (6) callback-stop record naming a itself: subject matches. + writeRecord(a, "OAuth callback server stopped", + zap.String("server", "a"), + zap.String("bind_host", "127.0.0.1"), + zap.Int("port", 54322)) + // (7) post-upgrade housekeeping record owned by a. + writeRecord(a, "Removing existing container", + zap.String("container_id", "0123456789ab"), + zap.String("container_name", "mcpproxy-a-wxyz"), + zap.String("container_owner", "a")) + + got := attributedTail(t, cfg, "a", 50) + body := joinLines(got) + assert.Contains(t, body, "own ordinary record") + assert.NotContains(t, body, foreignID, "foreign container id disclosed to a's scoped reader") + assert.NotContains(t, body, foreignName, "foreign container name disclosed to a's scoped reader") + assert.NotContains(t, body, "cafe000000aa", "container record without container_owner must be withheld") + assert.NotContains(t, body, "54321", "callback record naming b's port disclosed to a") + assert.NotContains(t, body, "feedface0001", "container owned by a-b disclosed to a") + assert.Contains(t, body, "54322", "callback record naming a itself is attributable") + assert.Contains(t, body, "0123456789ab", "post-upgrade record with container_owner=a is attributable") + assert.Len(t, got, 3, "exactly: own ordinary, own callback-stop, own container record; got:\n%s", body) + + whole := joinLines(wholeFileTail(t, cfg, "a", 50)) + for _, s := range []string{foreignID, foreignName, "cafe000000aa", "54321", "feedface0001", "54322", "0123456789ab"} { + assert.Contains(t, whole, s, "administrator whole-file read must keep every record") + } + + // server-a_b.log — the same-sanitised-name case: `a/b` naming + // mcpproxy-a-b-wxyz without container_owner is indistinguishable + // from hidden `a-b`'s container and withheld; with container_owner + // it is returned. + writeRecord(slash, "Removing existing container", + zap.String("container_id", foreignID), + zap.String("container_name", foreignName)) + writeRecord(slash, "Removing existing container", + zap.String("container_id", "abcdef012345"), + zap.String("container_name", foreignName), + zap.String("container_owner", "a/b")) + + got = attributedTail(t, cfg, "a/b", 50) + body = joinLines(got) + assert.NotContains(t, body, foreignID, "ownerless container record served to a/b") + assert.Contains(t, body, "abcdef012345", "container_owner=a/b record must be returned to a/b") + assert.Len(t, got, 1, "got:\n%s", body) + + whole = joinLines(wholeFileTail(t, cfg, "a/b", 50)) + assert.Contains(t, whole, foreignID) + assert.Contains(t, whole, "abcdef012345") + }) + } +} + +// FR007-G3: ownership filtering precedes the tail limit, so an interleaved +// foreign line never displaces an authorized one from the returned window. +func TestReadUpstreamServerLogTail_AttributedOnly_InterleavedFilterBeforeLimit(t *testing.T) { + for _, enc := range encoderCases() { + t.Run(enc.name, func(t *testing.T) { + cfg := newAttributedLogDir(t, enc.json) + slash := openStampedWriter(t, cfg, "a/b") + under := openStampedWriter(t, cfg, "a_b") + + writeRecord(under, "own1") + writeRecord(slash, "foreign1") + writeRecord(under, "own2") + writeRecord(slash, "foreign2") + + got := attributedTail(t, cfg, "a_b", 2) + require.Len(t, got, 2, "tail(a_b, 2) must be the last two OWN records, got:\n%s", joinLines(got)) + assert.Contains(t, got[0], "own1") + assert.Contains(t, got[1], "own2") + assert.NotContains(t, joinLines(got), "foreign") + + // Administrator control: last two raw lines are own2, foreign2. + whole := wholeFileTail(t, cfg, "a_b", 2) + require.Len(t, whole, 2) + assert.Contains(t, whole[0], "own2") + assert.Contains(t, whole[1], "foreign2") + }) + } +} + +// FR007-G6 / T053: names differing only by case collide only on a +// case-insensitive filesystem (macOS default, Windows); Linux CI writes two +// files. The attributed reader must give each name only its own records in +// both regimes; the administrator outcome is recorded per regime. +func TestReadUpstreamServerLogTail_AttributedOnly_CaseOnlyNames(t *testing.T) { + cfg := newAttributedLogDir(t, false) + upper := openStampedWriter(t, cfg, "A") + lower := openStampedWriter(t, cfg, "a") + + writeRecord(lower, "lower-own-1") + writeRecord(upper, "UPPER-SENTINEL") + writeRecord(lower, "lower-own-2") + + upperInfo, err := os.Stat(filepath.Join(cfg.LogDir, ServerLogFilename("A"))) + require.NoError(t, err) + lowerInfo, err := os.Stat(filepath.Join(cfg.LogDir, ServerLogFilename("a"))) + require.NoError(t, err) + shared := os.SameFile(upperInfo, lowerInfo) + t.Logf("case-only names share one file on this filesystem: %v", shared) + + got := attributedTail(t, cfg, "a", 50) + body := joinLines(got) + assert.NotContains(t, body, "UPPER-SENTINEL", "A's record served to a's scoped reader") + assert.Contains(t, body, "lower-own-1") + assert.Contains(t, body, "lower-own-2") + assert.Len(t, got, 2, "got:\n%s", body) + + got = attributedTail(t, cfg, "A", 50) + body = joinLines(got) + assert.Contains(t, body, "UPPER-SENTINEL") + assert.NotContains(t, body, "lower-own") + assert.Len(t, got, 1, "got:\n%s", body) + + // Administrator outcome, recorded per regime: whole-file read of `a` + // includes A's record only when the filesystem folded the two names. + whole := joinLines(wholeFileTail(t, cfg, "a", 50)) + if shared { + assert.Contains(t, whole, "UPPER-SENTINEL", "shared file: administrators see both writers") + } else { + assert.NotContains(t, whole, "UPPER-SENTINEL", "separate files: nothing to share") + } +} + +// T053: shared-file rotation and retention stay shared (spec FR-007 retained +// effect). A hidden co-owner's output can rotate an authorized record out of +// the readable history; the attributed reader then returns only what is still +// attributable in the current file — and never the co-owner's records. +func TestReadUpstreamServerLogTail_AttributedOnly_ForcedRotationSharedHistory(t *testing.T) { + cfg := newAttributedLogDir(t, false) + cfg.MaxSize = 1 // MB — lumberjack's minimum; the co-owner forces one rotation + cfg.MaxBackups = 1 + slash := openStampedWriter(t, cfg, "a/b") + under := openStampedWriter(t, cfg, "a_b") + + const sentinel = "a_b-record-before-rotation-77b2" + writeRecord(under, sentinel) + + logPath := filepath.Join(cfg.LogDir, ServerLogFilename("a_b")) + + // a/b writes past MaxSize so lumberjack rotates the shared file. + filler := strings.Repeat("x", 1024) + for i := 0; i < 1100; i++ { + slash.Info("co-owner filler", zap.String("payload", filler)) + } + _ = slash.Sync() + + backups, err := filepath.Glob(filepath.Join(cfg.LogDir, "server-a_b-*.log")) + require.NoError(t, err) + require.NotEmpty(t, backups, "fixture premise: the co-owner's writes must have rotated %s", logPath) + + // Retained, documented effect: the pre-rotation own record is gone from + // the current file for everyone — administrators included. + whole := wholeFileTail(t, cfg, "a_b", 500) + assert.NotContains(t, joinLines(whole), sentinel, + "administrator outcome: a co-owner's rotation evicts the authorized record from the readable history") + require.NotEmpty(t, whole, "the current file holds the co-owner's post-rotation records") + + // The scoped reader receives no co-owner record — an empty tail is the + // correct answer here, a filler line is a disclosure. + got := attributedTail(t, cfg, "a_b", 500) + foreign := 0 + for _, line := range got { + if !stampedAs(line, "a_b") { + foreign++ + } + } + assert.Zero(t, foreign, "%d of %d lines served to a_b after rotation are not a_b's (co-owner filler disclosed)", foreign, len(got)) +} diff --git a/internal/oauth/callback_stop_logger_test.go b/internal/oauth/callback_stop_logger_test.go new file mode 100644 index 000000000..8118bad83 --- /dev/null +++ b/internal/oauth/callback_stop_logger_test.go @@ -0,0 +1,146 @@ +package oauth + +import ( + "fmt" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" +) + +// Spec 105 FR-007 (gap FR007-G4, research D8 "subject-bound for shared-service +// producers"): the callback manager serves every server, and each callback +// server records the logger of the server it belongs to at start +// (CallbackServer.logger, a tee into that server's per-server log file). +// StopCallbackServer(name) — the nil-logger path markOAuthComplete uses — +// resolved its logger through adoptLoggerLocked(nil), i.e. whichever server's +// logger was installed LAST, so a's tear-down record (a's name, bind_host, +// port, dropped waiters) landed in b's log and was readable by a b-scoped +// agent through tail_log. The stop record must be written through the +// stopped server's own recorded logger, in both start orders. + +// newObservedManager builds a private CallbackServerManager (not the global +// one, so sibling tests cannot install a logger behind this test's back) +// plus one observer per server, mimicking the per-server upstream logger +// shape: every record is stamped `server=`. +func newObservedManager(t *testing.T, names ...string) (*CallbackServerManager, map[string]*observer.ObservedLogs, map[string]*zap.Logger) { + t.Helper() + mgr := &CallbackServerManager{ + servers: make(map[string]*CallbackServer), + logger: zap.NewNop(), + } + observed := make(map[string]*observer.ObservedLogs, len(names)) + loggers := make(map[string]*zap.Logger, len(names)) + for _, name := range names { + core, logs := observer.New(zap.DebugLevel) + observed[name] = logs + loggers[name] = zap.New(core).With(zap.String("server", name)) + } + t.Cleanup(func() { + for _, name := range names { + _ = mgr.StopCallbackServer(name) + } + }) + return mgr, observed, loggers +} + +// startObserved starts a dynamic-port callback server for name through the +// caller-logger path production uses (StartCallbackServerOnHost with +// CallbackBinding.Logger), parking one waiter so the tear-down has something +// to drop. +func startObserved(t *testing.T, mgr *CallbackServerManager, name string, logger *zap.Logger) *CallbackServer { + t.Helper() + cb, err := mgr.StartCallbackServerOnHost(name, CallbackBinding{Port: 0, Logger: logger}) + require.NoError(t, err) + cb.RegisterState("state-" + name) + return cb +} + +// mentionsServer reports whether any record in logs carries `server=name` +// as a field or names port anywhere — the two things FR-007 forbids leaking +// into another server's log. +func mentionsServer(logs *observer.ObservedLogs, name string, port int) []string { + var hits []string + for _, entry := range logs.All() { + for k, v := range entry.ContextMap() { + if k == "server" && v == name { + hits = append(hits, entry.Message+" server="+name) + } + if k == "port" && fmt.Sprint(v) == fmt.Sprint(port) { + hits = append(hits, entry.Message+" port="+fmt.Sprint(port)) + } + } + } + return hits +} + +// assertStopRoutedToOwner stops `stopped` via the nil-logger path and asserts +// its tear-down records (stop + dropped waiter) landed only in its own +// observer, never in `other`'s. +func assertStopRoutedToOwner(t *testing.T, mgr *CallbackServerManager, observed map[string]*observer.ObservedLogs, stopped, other string, stoppedPort int) { + t.Helper() + require.NoError(t, mgr.StopCallbackServer(stopped)) + + own := observed[stopped] + foreign := observed[other] + // The serve goroutine ALSO emits "OAuth callback server stopped" through + // the server's own logger once Serve returns; wait for it so the count + // below is deterministic: goroutine record + manager record = 2 in the + // owner's log, 0 anywhere else. + require.Eventually(t, func() bool { + return len(own.FilterMessage("OAuth callback server stopped").All()) >= 1 + }, 2*time.Second, 10*time.Millisecond, "serve goroutine's own stop record never arrived") + assert.Len(t, own.FilterMessage("OAuth callback server stopped").All(), 2, + "%s's manager stop record must be written through %s's recorded logger (goroutine record + manager record)", stopped, stopped) + assert.Len(t, own.FilterMessage("Stopped OAuth callback server while flows were still waiting").All(), 1, + "%s's dropped-waiter record must be written through %s's recorded logger", stopped, stopped) + + assert.Empty(t, foreign.FilterMessage("OAuth callback server stopped").All(), + "%s's stop record landed in %s's log", stopped, other) + assert.Empty(t, foreign.FilterMessage("Stopped OAuth callback server while flows were still waiting").All(), + "%s's dropped-waiter record landed in %s's log", stopped, other) + assert.Empty(t, mentionsServer(foreign, stopped, stoppedPort), + "%s's name/port written into %s's log", stopped, other) +} + +// FR007-G4, order a then b: b's logger is the last installed, so on HEAD +// StopCallbackServer("a") logged through b's logger. +func TestCallbackStop_UsesRecordedServerLogger_ABOrder(t *testing.T) { + mgr, observed, loggers := newObservedManager(t, "a", "b") + + a := startObserved(t, mgr, "a", loggers["a"]) + b := startObserved(t, mgr, "b", loggers["b"]) + + assertStopRoutedToOwner(t, mgr, observed, "a", "b", a.Port) + assertStopRoutedToOwner(t, mgr, observed, "b", "a", b.Port) +} + +// FR007-G4, order b then a: a's logger is the last installed, so on HEAD +// StopCallbackServer("b") logged through a's logger. +func TestCallbackStop_UsesRecordedServerLogger_BAOrder(t *testing.T) { + mgr, observed, loggers := newObservedManager(t, "a", "b") + + b := startObserved(t, mgr, "b", loggers["b"]) + a := startObserved(t, mgr, "a", loggers["a"]) + + assertStopRoutedToOwner(t, mgr, observed, "b", "a", b.Port) + assertStopRoutedToOwner(t, mgr, observed, "a", "b", a.Port) +} + +// The explicit-logger stop path (StopCallbackServerWithLogger) is what the +// OAuth failure/cleanup paths use with the server's own logger; it must not +// regress to the manager logger either, and — subject-bound — must still not +// write into the other server's observer. +func TestCallbackStop_WithLogger_StillSubjectBound(t *testing.T) { + mgr, observed, loggers := newObservedManager(t, "a", "b") + + a := startObserved(t, mgr, "a", loggers["a"]) + startObserved(t, mgr, "b", loggers["b"]) + + require.NoError(t, mgr.StopCallbackServerWithLogger("a", loggers["a"])) + assert.NotEmpty(t, observed["a"].FilterMessage("OAuth callback server stopped").All()) + assert.Empty(t, mentionsServer(observed["b"], "a", a.Port), "a's name/port written into b's log") +} diff --git a/internal/server/mcp_tail_log_scope_test.go b/internal/server/mcp_tail_log_scope_test.go index 803678c28..ddcd92dbc 100644 --- a/internal/server/mcp_tail_log_scope_test.go +++ b/internal/server/mcp_tail_log_scope_test.go @@ -2,6 +2,7 @@ package server import ( "context" + "encoding/json" "os" "path/filepath" "strings" @@ -14,6 +15,7 @@ import ( "github.com/smart-mcp-proxy/mcpproxy-go/internal/auth" "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/logs" "github.com/smart-mcp-proxy/mcpproxy-go/internal/profile" ) @@ -194,3 +196,204 @@ func TestTailLog_URLProfileScope_AppliesToAllCallers(t *testing.T) { assertTailLogHidden(t, proxy, anonInProfile, "secret") assertTailLogServed(t, proxy, anonInProfile, "github") } + +// --------------------------------------------------------------------------- +// Spec 105 FR-007 (gaps FR007-G1, G3): colliding log files. `a/b` and `a_b` +// both sanitise to server-a_b.log, so an `a_b`-only token must receive only +// the records `a_b` wrote (filtered BEFORE the tail limit, lines_returned = +// filtered length) and administrators must keep the whole file byte-for-byte. +// --------------------------------------------------------------------------- + +// tailLogCollidingFixture is a proxy whose storage knows `a/b` and `a_b` and +// whose log directory holds their SHARED file, plus the two real stamped +// writers (logs.NewUpstreamServerLogger — the writer internal/upstream/core +// installs) so every record carries the `server=` stamp. +type tailLogCollidingFixture struct { + proxy *MCPProxyServer + logCfg *config.LogConfig + writers map[string]*zap.Logger +} + +const ( + collidingHidden = "a/b" + collidingOwn = "a_b" +) + +// newTailLogCollidingProxy builds the fixture. Every returned io.Closer is +// closed at cleanup (CI "directory not empty" otherwise). The shared file is +// pre-created so both lumberjack sinks open it O_APPEND — lumberjack creates +// a NEW file O_TRUNC without O_APPEND, and two writers on one fresh file +// overwrite each other (the torn-fragment corruption gap-map FR007-G3 probed, +// a retained effect that is not what these tests are about). +func newTailLogCollidingProxy(t *testing.T) *tailLogCollidingFixture { + t.Helper() + require.Equal(t, logs.ServerLogFilename(collidingHidden), logs.ServerLogFilename(collidingOwn), + "fixture premise: the two raw names must share one log file") + + proxy := createTestMCPProxyServer(t) + + logDir := t.TempDir() + cfg := config.DefaultConfig() + cfg.DataDir = t.TempDir() + cfg.Listen = "127.0.0.1:0" + cfg.Logging.LogDir = logDir + cfg.Logging.EnableFile = true + cfg.Logging.EnableConsole = false + cfg.Logging.Compress = false + cfg.Servers = []*config.ServerConfig{ + {Name: collidingHidden, Protocol: "http", Enabled: false}, + {Name: collidingOwn, Protocol: "http", Enabled: false}, + } + mainSrv, err := NewServer(cfg, zap.NewNop()) + require.NoError(t, err) + t.Cleanup(func() { _ = mainSrv.Shutdown() }) + proxy.mainServer = mainSrv + + require.NoError(t, os.WriteFile(filepath.Join(logDir, logs.ServerLogFilename(collidingOwn)), nil, 0o600)) + + f := &tailLogCollidingFixture{proxy: proxy, logCfg: cfg.Logging, writers: map[string]*zap.Logger{}} + for _, name := range []string{collidingHidden, collidingOwn} { + sc := &config.ServerConfig{Name: name, Protocol: "http", URL: "http://127.0.0.1:1/mcp", Enabled: true} + require.NoError(t, proxy.storage.SaveUpstreamServer(sc)) + require.NoError(t, proxy.upstreamManager.AddServerConfig(name, sc)) + + writer, closer, err := logs.NewUpstreamServerLogger(cfg.Logging, name) + require.NoError(t, err) + t.Cleanup(func() { _ = closer.Close() }) + f.writers[name] = writer + } + return f +} + +// write emits one record through name's real stamped writer. One call site +// for every record keeps the console encoder's caller segment constant, so +// two fixtures' lines differ only by timestamp (see tailLogLineSignature). +func (f *tailLogCollidingFixture) write(name, msg string) { + f.writers[name].Info(msg) + _ = f.writers[name].Sync() +} + +// tailLogResponse is the parsed tail_log payload. +type tailLogResponse struct { + ServerName string `json:"server_name"` + LinesRequested int `json:"lines_requested"` + LinesReturned int `json:"lines_returned"` + LogLines []string `json:"log_lines"` +} + +// tailLogLinesVia drives the real dispatcher with an explicit `lines` and +// parses the payload. +func tailLogLinesVia(t *testing.T, proxy *MCPProxyServer, ctx context.Context, name string, lines int) (tailLogResponse, string) { + t.Helper() + request := mcp.CallToolRequest{} + request.Params.Arguments = map[string]interface{}{"operation": "tail_log", "name": name, "lines": float64(lines)} + result, err := proxy.handleUpstreamServers(ctx, request) + require.NoError(t, err) + body := toolResultText(t, result) + require.False(t, result.IsError, "tail_log must succeed for the in-scope server: %s", body) + var parsed tailLogResponse + require.NoError(t, json.Unmarshal([]byte(body), &parsed), body) + return parsed, body +} + +// tailLogLineSignature strips the leading timestamp segment of a console +// record (`ts | LEVEL | caller | msg | {fields}`) so records from two +// fixtures written through the same call site compare equal. +func tailLogLineSignature(line string) string { + if _, rest, ok := strings.Cut(line, " | "); ok { + return rest + } + return line +} + +func tailLogSignatures(lines []string) []string { + out := make([]string, len(lines)) + for i, l := range lines { + out[i] = tailLogLineSignature(l) + } + return out +} + +// FR007-G1 + G3 at the tool surface: interleaved own/foreign records, an +// `a_b`-only token asks for the last 2 → exactly [own1, own2], +// lines_returned == 2, nothing from `a/b`. +func TestTailLog_CollidingLogFile_ScopedTokenGetsOnlyOwnRecords(t *testing.T) { + f := newTailLogCollidingProxy(t) + const sentinel = "SENTINEL-a-slash-b-only-4e2d" + f.write(collidingOwn, "own1") + f.write(collidingHidden, sentinel+"-1") + f.write(collidingOwn, "own2") + f.write(collidingHidden, sentinel+"-2") + + ctx := agentCtx([]string{collidingOwn}, []string{auth.PermRead}, "") + resp, body := tailLogLinesVia(t, f.proxy, ctx, collidingOwn, 2) + + assert.NotContains(t, body, sentinel, "a/b's records disclosed to an a_b-only token") + assert.Equal(t, 2, resp.LinesReturned, "lines_returned must count the authorized tail") + require.Len(t, resp.LogLines, 2, "the window must hold the two OWN records, got: %v", resp.LogLines) + assert.Contains(t, resp.LogLines[0], "own1", "foreign line displaced own1 from the window") + assert.Contains(t, resp.LogLines[1], "own2") + assert.Equal(t, len(resp.LogLines), resp.LinesReturned) + + // The default window (50) has the same property: no foreign record at all. + resp, body = tailLogLinesVia(t, f.proxy, ctx, collidingOwn, 50) + assert.NotContains(t, body, sentinel) + assert.Len(t, resp.LogLines, 2) + assert.Equal(t, 2, resp.LinesReturned) +} + +// FR007-G1 SC-001 differential: the `a_b`-only token's view must be the same +// whether or not hidden `a/b` shares the file (uniform and independent of +// hidden co-owners — never a whole-file refusal that depends on a co-owner). +func TestTailLog_CollidingLogFile_DifferentialWithHiddenCoOwner(t *testing.T) { + ctx := agentCtx([]string{collidingOwn}, []string{auth.PermRead}, "") + + with := newTailLogCollidingProxy(t) + with.write(collidingOwn, "own1") + with.write(collidingHidden, "foreign1") + with.write(collidingOwn, "own2") + with.write(collidingHidden, "foreign2") + withResp, _ := tailLogLinesVia(t, with.proxy, ctx, collidingOwn, 50) + + without := newTailLogCollidingProxy(t) + without.write(collidingOwn, "own1") + without.write(collidingOwn, "own2") + withoutResp, _ := tailLogLinesVia(t, without.proxy, ctx, collidingOwn, 50) + + assert.Equal(t, tailLogSignatures(withoutResp.LogLines), tailLogSignatures(withResp.LogLines), + "scoped view must not depend on whether a hidden co-owner shares the file") + assert.Equal(t, withoutResp.LinesReturned, withResp.LinesReturned) + assert.Equal(t, 2, withResp.LinesReturned) +} + +// SC-005 administrator control: the administrator payload is the whole-file +// tail exactly as before the feature — log_lines byte-equal to the scrubbed +// whole-file reader, lines_returned its length, co-owner records included. +// Expected green on HEAD; it pins the whole-file path for the fix. +func TestTailLog_CollidingLogFile_AdminWholeFileUnchanged(t *testing.T) { + f := newTailLogCollidingProxy(t) + f.write(collidingOwn, "own1") + f.write(collidingHidden, "foreign1") + f.write(collidingOwn, "own2") + f.write(collidingHidden, "foreign2") + + whole, err := logs.ReadUpstreamServerLogTail(f.logCfg, collidingOwn, 2) + require.NoError(t, err) + require.Len(t, whole, 2) + + for name, ctx := range map[string]context.Context{ + "api-key admin": adminCtx(), + "no auth ctx": context.Background(), + } { + t.Run(name, func(t *testing.T) { + resp, body := tailLogLinesVia(t, f.proxy, ctx, collidingOwn, 2) + assert.Equal(t, scrubUpstreamLines(whole), resp.LogLines, "administrator log_lines must be the raw whole-file tail") + assert.Equal(t, 2, resp.LinesReturned) + assert.Contains(t, body, "foreign2", "administrators keep co-owner records") + assert.Contains(t, body, "own2") + for _, key := range []string{"server_name", "lines_requested", "lines_returned", "log_lines", "server_status", "connection_status"} { + assert.Contains(t, body, `"`+key+`"`, "administrator payload shape unchanged") + } + }) + } +} diff --git a/internal/upstream/core/docker_ownership_test.go b/internal/upstream/core/docker_ownership_test.go new file mode 100644 index 000000000..525c80987 --- /dev/null +++ b/internal/upstream/core/docker_ownership_test.go @@ -0,0 +1,354 @@ +package core + +import ( + "context" + "fmt" + "os" + "path/filepath" + "runtime" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zaptest/observer" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" + "github.com/smart-mcp-proxy/mcpproxy-go/internal/shellwrap" +) + +// Spec 105 FR-007 (gap FR007-G5, research D9): every Docker cleanup path — +// ensureNoExistingContainers on connect, the disconnect name-pattern fallback +// and the image-name fallback — must touch only containers canonically owned +// by this server: label com.mcpproxy.server= AND name matching +// ^mcpproxy--[a-z0-9]{4}$. On HEAD `docker ps --filter +// name=mcpproxy-a-` is a substring match with no Go-side predicate, so server +// `a` rm -f'd hidden `a-b`'s live container and wrote its id and name into +// a's per-server log; the image-name fallback killed any container sharing +// the image. Foreign containers must be neither removed nor logged. + +// --------------------------------------------------------------------------- +// Fake docker: a sh+awk shim (no re-exec of the race-instrumented test +// binary, which costs ~1s per call). It appends every invocation to the +// invocation log, answers `ps` from a TSV fixture honouring +// --filter name= / label=[=] and --format templates ({{.ID}}, +// {{.Names}}, {{.Image}}, {{.Status}}, {{.CreatedAt}}, {{.Labels}}, +// {{.Label "k"}}), and exits 0 for rm/stop/kill/version. +// --------------------------------------------------------------------------- + +// fakeContainer is one `docker ps` row of the fixture. +type fakeContainer struct { + ID string + Name string + Image string + Status string + Labels map[string]string +} + +// fakeDocker is one installed fake docker: the invocation log and the +// fixture file the shim reads. +type fakeDocker struct { + logPath string + psPath string +} + +const fakeDockerShim = `#!/bin/sh +LOG=%s +PS=%s +printf '%%s\n' "$*" >> "$LOG" +[ "$1" = ps ] || exit 0 +shift +format='{{.ID}} {{.Names}}' +namefilter='' +labelkey='' +labelval='' +labelset=0 +while [ $# -gt 0 ]; do + case "$1" in + --format) format="$2"; shift 2 ;; + --filter|-f) + case "$2" in + name=*) namefilter="${2#name=}" ;; + label=*) + l="${2#label=}" + labelkey="${l%%%%=*}" + case "$l" in *=*) labelval="${l#*=}"; labelset=1 ;; esac + ;; + esac + shift 2 ;; + *) shift ;; + esac +done +awk -F'\t' -v fmt="$format" -v nf="$namefilter" -v lk="$labelkey" -v lv="$labelval" -v ls="$labelset" ' +function repl(s, lit, val, i, out) { + out = "" + while ((i = index(s, lit)) > 0) { out = out substr(s, 1, i - 1) val; s = substr(s, i + length(lit)) } + return out s +} +{ + if (nf != "" && $2 !~ nf) next + delete labels + n = split($5, pairs, ",") + for (i = 1; i <= n; i++) { eq = index(pairs[i], "="); if (eq > 0) labels[substr(pairs[i], 1, eq - 1)] = substr(pairs[i], eq + 1) } + if (lk != "") { if (!(lk in labels)) next; if (ls && labels[lk] != lv) next } + out = fmt + out = repl(out, "{{.ID}}", $1) + out = repl(out, "{{.Names}}", $2) + out = repl(out, "{{.Image}}", $3) + out = repl(out, "{{.Status}}", $4) + out = repl(out, "{{.CreatedAt}}", "2026-09-16 00:00:00 +0000 UTC") + out = repl(out, "{{.Labels}}", $5) + while (match(out, /\{\{\.Label "[^"]*"\}\}/)) { + key = substr(out, RSTART + 10, RLENGTH - 13) + out = substr(out, 1, RSTART - 1) labels[key] substr(out, RSTART + RLENGTH) + } + print out +}' "$PS" +` + +// installFakeDocker writes the shim, points the REAL resolver at it +// (SetWellKnownDockerPathsForTest + ResetDockerPathCacheForTest, the seams +// gap-map §7 names) and empties PATH so nothing else can resolve. +func installFakeDocker(t *testing.T, containers []fakeContainer) *fakeDocker { + t.Helper() + if runtime.GOOS == osWindows { + t.Skip("unix shell shim") + } + dir := t.TempDir() + fd := &fakeDocker{ + logPath: filepath.Join(dir, "invocations.log"), + psPath: filepath.Join(dir, "ps.tsv"), + } + var tsv strings.Builder + for _, c := range containers { + labels := make([]string, 0, len(c.Labels)) + for k, v := range c.Labels { + labels = append(labels, k+"="+v) + } + fmt.Fprintf(&tsv, "%s\t%s\t%s\t%s\t%s\n", c.ID, c.Name, c.Image, c.Status, strings.Join(labels, ",")) + } + require.NoError(t, os.WriteFile(fd.psPath, []byte(tsv.String()), 0o600)) + + shim := filepath.Join(dir, "docker") + script := fmt.Sprintf(fakeDockerShim, shellQuote(fd.logPath), shellQuote(fd.psPath)) + require.NoError(t, os.WriteFile(shim, []byte(script), 0o755)) + + t.Setenv("PATH", "/usr/bin:/bin") // sh + awk only; no real docker here + t.Setenv("SHELL", "/nonexistent/shell-must-not-be-invoked") + + useRealDockerResolver(t) + restore := shellwrap.SetWellKnownDockerPathsForTest(func() []string { return []string{shim} }) + t.Cleanup(restore) + return fd +} + +func shellQuote(s string) string { return "'" + strings.ReplaceAll(s, "'", `'\''`) + "'" } + +// invocations returns every docker command line the shim received. +func (fd *fakeDocker) invocations(t *testing.T) []string { + t.Helper() + raw, err := os.ReadFile(fd.logPath) + if os.IsNotExist(err) { + return nil + } + require.NoError(t, err) + return strings.Split(strings.TrimSpace(string(raw)), "\n") +} + +// mutationsOf returns the rm/stop/kill invocations that name id. +func (fd *fakeDocker) mutationsOf(t *testing.T, id string) []string { + t.Helper() + var hits []string + for _, line := range fd.invocations(t) { + fields := strings.Fields(line) + if len(fields) == 0 { + continue + } + switch fields[0] { + case "rm", "stop", "kill": + if fields[len(fields)-1] == id { + hits = append(hits, line) + } + } + } + return hits +} + +// newOwnershipClient builds a client for server name with BOTH its loggers +// observed: c.logger (main.log) and c.upstreamLogger (server-.log, the +// file tail_log serves). +func newOwnershipClient(name string, cfg *config.ServerConfig) (*Client, *observer.ObservedLogs, *observer.ObservedLogs) { + mainCore, mainLogs := observer.New(zap.DebugLevel) + upCore, upLogs := observer.New(zap.DebugLevel) + if cfg == nil { + cfg = &config.ServerConfig{Command: "python", Args: []string{"-m", "mcp_server"}} + } + cfg.Name = name + c := &Client{ + config: cfg, + logger: zap.New(mainCore), + upstreamLogger: zap.New(upCore).With(zap.String("server", name)), + isolationManager: NewIsolationManager(config.DefaultDockerIsolationConfig()), + } + return c, mainLogs, upLogs +} + +// recordsMentioning returns every observed record whose message or any field +// value contains needle. +func recordsMentioning(logs *observer.ObservedLogs, needle string) []string { + var hits []string + for _, entry := range logs.All() { + if strings.Contains(entry.Message, needle) { + hits = append(hits, entry.Message) + continue + } + for k, v := range entry.ContextMap() { + if strings.Contains(fmt.Sprint(v), needle) { + hits = append(hits, entry.Message+" "+k+"="+fmt.Sprint(v)) + break + } + } + } + return hits +} + +const ( + foreignContainerID = "deadbeef1234" + foreignContainerName = "mcpproxy-a-b-wxyz" + ownContainerID = "cafe00000001" + ownContainerName = "mcpproxy-a-wxyz" + ownerLabel = "com.mcpproxy.server" +) + +func ownAndForeignFixture() []fakeContainer { + return []fakeContainer{ + {ID: foreignContainerID, Name: foreignContainerName, Image: "mcp/example", Status: "Up 2 minutes", + Labels: map[string]string{"com.mcpproxy.managed": "true", ownerLabel: "a-b"}}, + {ID: ownContainerID, Name: ownContainerName, Image: "mcp/example", Status: "Exited (0) 1 minute ago", + Labels: map[string]string{"com.mcpproxy.managed": "true", ownerLabel: "a"}}, + } +} + +// assertForeignUntouched is the shared oracle: the foreign container is +// never rm/stop/kill'd and never named — by id or by name — in either of a's +// loggers (main.log AND the per-server log tail_log serves). +func assertForeignUntouched(t *testing.T, fd *fakeDocker, mainLogs, upLogs *observer.ObservedLogs) { + t.Helper() + assert.Empty(t, fd.mutationsOf(t, foreignContainerID), "foreign container %s was mutated", foreignContainerID) + for _, needle := range []string{foreignContainerID, foreignContainerName} { + assert.Empty(t, recordsMentioning(upLogs, needle), "foreign %q written into a's per-server log", needle) + assert.Empty(t, recordsMentioning(mainLogs, needle), "foreign %q written into main log under server=a", needle) + } +} + +// FR007-G5 (connect path): ensureNoExistingContainers for server `a` with +// hidden `a-b`'s live container and a's own stale container present. +func TestDockerCleanup_MatchesOnlyCanonicalOwner_Connect(t *testing.T) { + fd := installFakeDocker(t, ownAndForeignFixture()) + c, mainLogs, upLogs := newOwnershipClient("a", nil) + + require.NoError(t, c.ensureNoExistingContainers(context.Background())) + + assertForeignUntouched(t, fd, mainLogs, upLogs) + assert.NotEmpty(t, fd.mutationsOf(t, ownContainerID), "a's own stale container must still be removed; invocations:\n%s", + strings.Join(fd.invocations(t), "\n")) + assert.NotEmpty(t, recordsMentioning(upLogs, ownContainerID), "removing a's own container is still recorded in a's log") +} + +// FR007-G5 (disconnect name-pattern fallback): no known container id or +// name, so the client falls back to pattern cleanup; the foreign container +// matches the name prefix but not the canonical-owner predicate. +func TestDockerCleanup_MatchesOnlyCanonicalOwner_DisconnectNamePattern(t *testing.T) { + fd := installFakeDocker(t, ownAndForeignFixture()) + c, mainLogs, upLogs := newOwnershipClient("a", &config.ServerConfig{ + Command: "docker", Args: []string{"run", "-i", "--rm", "mcp/example"}, + }) + + c.killDockerContainerByCommandWithContext(context.Background()) + + assertForeignUntouched(t, fd, mainLogs, upLogs) + assert.NotEmpty(t, fd.mutationsOf(t, ownContainerID), "a's own container must still be stopped; invocations:\n%s", + strings.Join(fd.invocations(t), "\n")) +} + +// FR007-G5 (image-name fallback, D9): no owned container at all, empty known +// container id, and two foreign containers on the SAME image — one whose +// name matches the prefix, one that does not. The name-pattern step finds no +// owned container and the image-name fallback must touch nothing. +func TestDockerCleanup_ImageNameFallback_TouchesNothingForeign(t *testing.T) { + const unrelatedID = "feedface0002" + fd := installFakeDocker(t, []fakeContainer{ + {ID: foreignContainerID, Name: foreignContainerName, Image: "mcp/example", Status: "Up 2 minutes", + Labels: map[string]string{ownerLabel: "a-b"}}, + {ID: unrelatedID, Name: "unrelated-tool", Image: "mcp/example", Status: "Up 5 minutes", + Labels: map[string]string{}}, + }) + c, mainLogs, upLogs := newOwnershipClient("a", &config.ServerConfig{ + Command: "docker", Args: []string{"run", "-i", "--rm", "mcp/example"}, + }) + + c.killDockerContainerByCommandWithContext(context.Background()) + + assertForeignUntouched(t, fd, mainLogs, upLogs) + assert.Empty(t, fd.mutationsOf(t, unrelatedID), "a container merely sharing the image was mutated") + assert.Empty(t, recordsMentioning(upLogs, unrelatedID), "a container merely sharing the image was written into a's log") + assert.Empty(t, recordsMentioning(mainLogs, unrelatedID)) + for _, line := range fd.invocations(t) { + f := strings.Fields(line) + if len(f) > 0 { + assert.NotContains(t, []string{"rm", "stop", "kill"}, f[0], "no container may be mutated: %q", line) + } + } +} + +// FR007-G5 unit matcher table, driven through ensureNoExistingContainers so +// it compiles against HEAD: ownership = label com.mcpproxy.server == raw +// server name AND name =~ ^mcpproxy--[a-z0-9]{4}$. Rows cover +// `a` vs `a-b` vs `a/b` vs `A` (the label is the only signal that separates +// a/b from a-b — both sanitise to mcpproxy-a-b-*), pre-label containers and +// the regex guard. +func TestDockerCleanup_OwnershipMatcherTable(t *testing.T) { + cases := []struct { + name string + server string + cname string + labels map[string]string + owned bool + }{ + {"own label and canonical name", "a", "mcpproxy-a-wxyz", map[string]string{ownerLabel: "a"}, true}, + {"a-b container, server a", "a", "mcpproxy-a-b-wxyz", map[string]string{ownerLabel: "a-b"}, false}, + {"a/b container, server a", "a", "mcpproxy-a-b-wxyz", map[string]string{ownerLabel: "a/b"}, false}, + {"case-different label", "a", "mcpproxy-a-wxyz", map[string]string{ownerLabel: "A"}, false}, + {"case-different name and label", "a", "mcpproxy-A-wxyz", map[string]string{ownerLabel: "A"}, false}, + {"pre-label container", "a", "mcpproxy-a-wxyz", map[string]string{}, false}, + {"label mismatch, canonical name", "a", "mcpproxy-a-wxyz", map[string]string{ownerLabel: "a-b"}, false}, + {"own label, name with extra segment", "a", "mcpproxy-a-wxyz-extra", map[string]string{ownerLabel: "a"}, false}, + {"own label, uppercase suffix", "a", "mcpproxy-a-WXYZ", map[string]string{ownerLabel: "a"}, false}, + {"own label, short suffix", "a", "mcpproxy-a-wxy", map[string]string{ownerLabel: "a"}, false}, + {"server a/b owns its container", "a/b", "mcpproxy-a-b-wxyz", map[string]string{ownerLabel: "a/b"}, true}, + {"server a/b vs a-b's container", "a/b", "mcpproxy-a-b-wxyz", map[string]string{ownerLabel: "a-b"}, false}, + {"server a-b owns its container", "a-b", "mcpproxy-a-b-wxyz", map[string]string{ownerLabel: "a-b"}, true}, + {"server a-b vs a/b's container", "a-b", "mcpproxy-a-b-wxyz", map[string]string{ownerLabel: "a/b"}, false}, + {"server A vs a's container", "A", "mcpproxy-a-wxyz", map[string]string{ownerLabel: "a"}, false}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + const id = "0123456789ab" + fd := installFakeDocker(t, []fakeContainer{{ID: id, Name: tc.cname, Image: "img", Status: "Up", Labels: tc.labels}}) + c, mainLogs, upLogs := newOwnershipClient(tc.server, nil) + + require.NoError(t, c.ensureNoExistingContainers(context.Background())) + + mutated := fd.mutationsOf(t, id) + if tc.owned { + assert.NotEmpty(t, mutated, "owned container must be removed; invocations:\n%s", strings.Join(fd.invocations(t), "\n")) + } else { + assert.Empty(t, mutated, "foreign container removed by server %q", tc.server) + assert.Empty(t, recordsMentioning(upLogs, id), "foreign container id written into %q's per-server log", tc.server) + assert.Empty(t, recordsMentioning(upLogs, tc.cname), "foreign container name written into %q's per-server log", tc.server) + assert.Empty(t, recordsMentioning(mainLogs, id), "foreign container id logged under server=%q", tc.server) + } + }) + } +} diff --git a/internal/upstream/core/upstream_logger_audit_test.go b/internal/upstream/core/upstream_logger_audit_test.go new file mode 100644 index 000000000..7fc97fe7d --- /dev/null +++ b/internal/upstream/core/upstream_logger_audit_test.go @@ -0,0 +1,73 @@ +package core + +import ( + "go/ast" + "go/parser" + "go/token" + "os" + "path/filepath" + "strings" + "testing" + + "github.com/stretchr/testify/require" +) + +// Spec 105 FR-007, research D8 rule 1 (producer rule): the per-server log is +// the file `upstream_servers tail_log` serves, and its attribution reader +// keys on the `server=` field of every record. Child-controlled text +// (stderr lines, launcher output, docker output) must therefore only ever be +// a zap FIELD VALUE — zap escapes it inside the fields object — never the +// message, where the console encoder writes it unescaped and a crafted line +// could try to look like a record boundary. This test is the audit: every +// `upstreamLogger.{Info,Warn,Error,Debug}(` call in this package passes a +// constant string literal as its message. (T054a; expected green on HEAD — +// it pins the invariant the reader rule relies on.) +func TestUpstreamLoggerAudit_MessagesAreConstant(t *testing.T) { + entries, err := os.ReadDir(".") + require.NoError(t, err) + + fset := token.NewFileSet() + var violations []string + audited := 0 + for _, entry := range entries { + name := entry.Name() + if entry.IsDir() || !strings.HasSuffix(name, ".go") || strings.HasSuffix(name, "_test.go") { + continue + } + file, err := parser.ParseFile(fset, filepath.Join(".", name), nil, 0) + require.NoError(t, err, name) + + ast.Inspect(file, func(n ast.Node) bool { + call, ok := n.(*ast.CallExpr) + if !ok { + return true + } + sel, ok := call.Fun.(*ast.SelectorExpr) + if !ok { + return true + } + switch sel.Sel.Name { + case "Info", "Warn", "Error", "Debug": + default: + return true + } + recv, ok := sel.X.(*ast.SelectorExpr) + if !ok || recv.Sel.Name != "upstreamLogger" { + return true + } + audited++ + if len(call.Args) == 0 { + violations = append(violations, fset.Position(call.Pos()).String()+": no message argument") + return true + } + if lit, ok := call.Args[0].(*ast.BasicLit); !ok || lit.Kind != token.STRING { + violations = append(violations, fset.Position(call.Pos()).String()+": message is not a string literal") + } + return true + }) + } + + require.NotZero(t, audited, "the audit found no upstreamLogger call sites — the receiver name changed and the audit is vacuous") + require.Empty(t, violations, "upstreamLogger calls with a non-constant message (child text must be a field value):\n%s", + strings.Join(violations, "\n")) +} From d2e2c9059d6f117b3a45dee8b18dac3a21fdbbcc Mon Sep 17 00:00:00 2001 From: Algis Dumbris Date: Wed, 16 Sep 2026 08:22:27 +0300 Subject: [PATCH 02/22] =?UTF-8?q?feat(scope):=20Spec=20105=20PR=20E=20?= =?UTF-8?q?=E2=80=94=20per-record=20log=20attribution,=20subject-bound=20O?= =?UTF-8?q?Auth=20stop,=20canonical=20container=20ownership=20(FR-007)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Green phase for gaps FR007-G1..G6 (tasks T054-T059): - internal/logs/attribution.go: ReadUpstreamServerLogTailAttributed — no new field (D8); the existing `server=` stamp is the ownership signal. Console encoder: scan ` | {` boundaries left to right and accept the first whose suffix decodes as exactly one complete JSON object; JSON encoder: the whole line; every top-level `server` value must equal the requested name; subject-evidence rule for container records (container_owner required and equal, sanitised names are never evidence) and callback records naming another server; filter before the tail limit; lines with no accepted boundary withheld. Whole-file reader untouched (SC-005). - internal/server/mcp.go handleTailLog: attributed reader for scoped callers, whole file for administrators; lines_returned counts the authorized tail. - internal/oauth/config.go: stopCallbackServerLocked logs through the stopped server's recorded logger; StopCallbackServerWithLogger no longer adopts a logger as the manager logger on stop (signature kept). - internal/upstream/core/docker_ownership.go + docker.go: every cleanup path (ensureNoExistingContainers, disconnect name-pattern fallback, image-name fallback, exact-name kill) filters by label com.mcpproxy.server= AND ^mcpproxy--[a-z0-9]{4}$ server-side and again in Go; foreign containers are neither mutated nor logged; every housekeeping record that names a container carries container_owner (D9). - connection_launcher.go loggerWriter: one record per line — a child write carrying a line break can no longer start a fresh line (D8 rule 2 relies on line boundaries; research.md D8 records the launcher-path finding). - Inverted pinned tests (T058): mcp_tail_log_scope_test.go fixture writes the canary through the real stamped writer plus an unstamped legacy line that scoped callers must not see; mcp_secret_redaction_test.go tail_log fixture uses stamped records in both encoder shapes for scoped and admin callers. Fixture fixes: callback_stop_logger_test waits for both stop records and judges the foreign observer by records about the stopped server; tailLogLineSignature strips the caller segment. - docs: tail_log attribution rule + retained effects (agent-tokens), container ownership rule and correct label names (docker-isolation); tasks.md Phase 5 ticked; ROADMAP.md regenerated. Co-Authored-By: Claude Opus 5 --- ROADMAP.md | 4 +- docs/features/agent-tokens.md | 25 ++ docs/features/docker-isolation.md | 23 +- internal/logs/attribution.go | 265 +++++++++++++++++ internal/logs/logger.go | 15 - internal/oauth/callback_stop_logger_test.go | 18 +- internal/oauth/config.go | 34 ++- internal/server/mcp.go | 18 +- internal/server/mcp_secret_redaction_test.go | 48 ++- internal/server/mcp_tail_log_scope_test.go | 84 ++++-- internal/upstream/core/connection_docker.go | 1 + internal/upstream/core/connection_launcher.go | 18 +- internal/upstream/core/docker.go | 276 +++++++----------- internal/upstream/core/docker_ownership.go | 163 +++++++++++ specs/105-agent-scope-hardening/research.md | 2 +- specs/105-agent-scope-hardening/tasks.md | 26 +- 16 files changed, 756 insertions(+), 264 deletions(-) create mode 100644 internal/logs/attribution.go create mode 100644 internal/upstream/core/docker_ownership.go diff --git a/ROADMAP.md b/ROADMAP.md index 91b2833c4..bcc806d63 100644 --- a/ROADMAP.md +++ b/ROADMAP.md @@ -862,7 +862,7 @@ graph LR | Web UI + macOS app UX audit | In progress | P0 | — | | | | Release qualification gate (auto-QA matrix blocks the tag) | In progress | P0 | — | [081-release-qa-gate](./specs/081-release-qa-gate/) | | | Action log / transparency — info at a glance | In progress | P1 | — | | | -| Agent-token scope hardening: every MCP request authorized by its own scope (spec 105) | In progress | P1 | 0/109 (0%) | [105-agent-scope-hardening](./specs/105-agent-scope-hardening/) | | +| Agent-token scope hardening: every MCP request authorized by its own scope (spec 105) | In progress | P1 | 13/109 (12%) | [105-agent-scope-hardening](./specs/105-agent-scope-hardening/) | | | Token-efficiency benchmark: measured savings, published results | In progress | P1 | 62/64 (97%) | [103-token-bench](./specs/103-token-bench/) | | | Telemetry identity & data quality (machine_id + CI-filter hardening) | In progress | P1 | — | | | | Telemetry v7: honest funnel + churn instrumentation | In progress | P1 | — | [080-telemetry-v7-churn](./specs/080-telemetry-v7-churn/) | | @@ -1008,5 +1008,5 @@ Legend: `shipped` ≥95% checked · `in-flight` 1–94% · `drafted` 0% · `—` | [102-schema-deferred](./specs/102-schema-deferred/) | `shipped` | 89/89 (100%) | | [103-token-bench](./specs/103-token-bench/) | `shipped` | 62/64 (97%) | | [104-auto-routing-mode](./specs/104-auto-routing-mode/) | — | — | -| [105-agent-scope-hardening](./specs/105-agent-scope-hardening/) | `drafted` | 0/109 (0%) | +| [105-agent-scope-hardening](./specs/105-agent-scope-hardening/) | `in-flight` | 13/109 (12%) | | [106-security-residual-fixes](./specs/106-security-residual-fixes/) | `shipped` | 18/19 (95%) | diff --git a/docs/features/agent-tokens.md b/docs/features/agent-tokens.md index a8e7e889c..652388199 100644 --- a/docs/features/agent-tokens.md +++ b/docs/features/agent-tokens.md @@ -292,6 +292,31 @@ Denied to agent tokens on both surfaces: On the MCP surface (`upstream_servers`, `quarantine_security`) these return a tool error; on the REST surface (mutating `/api/v1/servers/...`, `/api/v1/config/...`, and `/api/v1/registries/...` routes) they return **`403 Forbidden`** (`operation requires admin access`). Read-only operations stay available to scoped tokens: `upstream_servers` `list`/`tail_log`, `GET /api/v1/servers`, per-server diagnostics, registry reads, and `GET /api/v1/index/search` (which honors quarantine — a quarantined server's tools are withheld from search on every surface). Those reads are **scope-filtered** as described above. `GET /api/v1/config` is the exception: it is an admin document (it carries the global `api_key`, every server's credentials, and a second enumeration of server names under `profiles[].servers`), so it returns `403` for an agent token rather than a filtered view. +**Log attribution on `tail_log`.** Per-server log files are named from a +*sanitised* server name, so two configured servers can share one file — +`a/b` and `a_b` both write `server-a_b.log`, and on a case-insensitive +filesystem so do `A` and `a`. `upstream_servers` `tail_log` therefore +returns a scoped token only the records **attributable to the server it +named**: every record mcpproxy writes carries its writer's server identity, +and the reader filters on it *before* applying the line limit, so +`lines_returned` counts the authorized tail and a co-owner's interleaved +record never displaces an authorized one. The rule is the same whether or +not a co-owner exists — a scoped caller never gets a whole-file refusal that +depends on another server sharing the file. Withheld from scoped callers: +records with no writer identity (lines written before this rule existed, +hand-appended lines, torn fragments), records about a container that do not +prove the container's owner (`container_owner`, written by container +housekeeping since this rule — earlier housekeeping records are treated as +non-attributable), and records whose subject is another server (an OAuth +callback tear-down that an earlier version routed through the wrong server's +logger). Retained effects: rotation and retention of a shared file stay +shared, so a co-owner's output can rotate an authorized record out of the +readable history; and child process output is attributed to the server whose +process wrote it — a child cannot forge another server's identity. The +administrator readers — `tail_log` with the API key or over the local socket, +`GET /api/v1/servers/{id}/logs`, `mcpproxy upstream logs` — keep the whole +file exactly as before. + ## Profile Pinning A [profile](./profiles.md) scopes tool discovery and calls to a named subset of upstream servers. With `--profile-pin`, you can **bind a token to a single profile** so it can never operate outside it — regardless of the URL it connects to or any `set_profile` call it makes. diff --git a/docs/features/docker-isolation.md b/docs/features/docker-isolation.md index 45d380178..cb9fa19a4 100644 --- a/docs/features/docker-isolation.md +++ b/docs/features/docker-isolation.md @@ -348,7 +348,24 @@ When MCPProxy stops, containers are cleaned up with a 30-second timeout: 1. **Graceful Stop**: `docker stop` (sends SIGTERM to container) 2. **Force Kill**: `docker kill` if container doesn't stop gracefully -Containers are labeled with `mcpproxy.managed=true` for identification. +Containers are labeled with `com.mcpproxy.managed=true` for identification +and `com.mcpproxy.server=` (the raw, unsanitised name) for +ownership. + +### Container ownership + +Every container mcpproxy creates is named +`mcpproxy--<4 random chars>`. The name alone does not +identify the server — `a/b` and `a-b` both sanitise to `a-b` — so every +cleanup path (the pre-start sweep for stale containers, the disconnect +fallback by name pattern, and the fallback by image name) removes only +containers whose `com.mcpproxy.server` label **and** canonical name both +match the server being cleaned up. Containers you started yourself with +`docker run --name mcpproxy-…`, or that pre-date the label, are never touched +by these sweeps, and a container that merely shares an image with a server's +is never stopped on that server's behalf. Housekeeping records in the +per-server log carry `container_owner` (the label value) so +[`tail_log`](/features/agent-tokens) can attribute them to the right server. ### Manual Cleanup @@ -356,10 +373,10 @@ If containers remain after MCPProxy stops: ```bash # List MCPProxy-managed containers -docker ps --filter "label=mcpproxy.managed=true" +docker ps --filter "label=com.mcpproxy.managed=true" # Remove all MCPProxy containers -docker rm -f $(docker ps -q --filter "label=mcpproxy.managed=true") +docker rm -f $(docker ps -q --filter "label=com.mcpproxy.managed=true") ``` See [Shutdown Behavior](/operations/shutdown-behavior) for detailed subprocess lifecycle documentation. diff --git a/internal/logs/attribution.go b/internal/logs/attribution.go new file mode 100644 index 000000000..ee2c3b955 --- /dev/null +++ b/internal/logs/attribution.go @@ -0,0 +1,265 @@ +package logs + +import ( + "bufio" + "encoding/json" + "errors" + "fmt" + "io" + "os" + "strings" + + "github.com/smart-mcp-proxy/mcpproxy-go/internal/config" +) + +// Spec 105 FR-007 (research D8): per-record log ownership. +// +// Two raw server names can share ONE per-server log file — `a/b` and `a_b` +// both sanitise to server-a_b.log (sanitizeServerLogName), and on a +// case-insensitive filesystem so do `A` and `a` — so a scoped caller tailing +// "its" server must receive only the records its server actually wrote. There +// is NO new field for that (D8): every per-server writer already stamps each +// record with `server=` (NewUpstreamServerLogger), so administrator +// records and the whole-file reader (ReadUpstreamServerLogTail) are +// byte-identical to before. Unforgeability comes from two rules: +// +// 1. Producer rule: child-controlled text (stderr lines, docker output) is +// only ever a zap FIELD VALUE, where the encoder escapes it inside the +// fields object. internal/upstream/core audits its upstreamLogger call +// sites for that. The launcher-pumped path writes one child line per +// record as the MESSAGE; rule 2 handles that shape and loggerWriter never +// lets a newline into a message. +// 2. Reader rule: a console-encoder record is +// `ts | LEVEL | caller | msg | {fields}`. The reader scans ` | {` +// boundaries LEFT TO RIGHT and accepts the first whose suffix decodes as +// exactly one complete JSON object with no trailing bytes. Child text that +// contains ` | {` sits to the left of the encoder's own boundary, so its +// suffix always carries the real fields object as trailing bytes and is +// rejected; child text inside a field value is escaped and cannot close +// the object early. A JSON-encoder record is the whole line. Lines with +// no accepted boundary (pre-stamp records, torn fragments from two sinks +// on one file) are non-attributable and withheld from scoped callers. +// 3. Subject-evidence rule (historical records): a stamp proves who WROTE a +// record, not that every subject it names is that server's. A record +// that names a container is attributable only when it carries +// `container_owner` (the container's com.mcpproxy.server label, written +// by the housekeeping paths since Spec 105) equal to the requested +// server; the sanitised container name is never evidence (`a/b` and +// `a-b` both name mcpproxy-a-b-*). A record whose `server` field names +// another server (a pre-105 callback-stop record routed through the +// wrong logger) is withheld. +// +// Administrators, REST and the CLI keep the whole file (SC-005). + +// consoleFieldsBoundary separates the console encoder's message from its +// fields object (getFileEncoder: ConsoleSeparator " | ", fields rendered as a +// JSON object). +const consoleFieldsBoundary = " | {" + +// Field names the attribution rules key on. +const ( + attributionServerField = "server" + attributionContainerOwnerField = "container_owner" + attributionContainerIDField = "container_id" + attributionContainerNameField = "container_name" +) + +// ReadUpstreamServerLogTailAttributed reads the last N records of an upstream +// server log that are attributable to serverName (Spec 105 FR-007, research +// D8). Attribution is decided per record BEFORE the tail limit, so an +// interleaved co-owner record never displaces an attributable one from the +// returned window, and the returned length is the authorized tail length. +// Records with no accepted stamp, records stamped for another server and +// records failing the subject-evidence rule are withheld. Administrators use +// ReadUpstreamServerLogTail (whole file, byte-identical to pre-105). +func ReadUpstreamServerLogTailAttributed(config *config.LogConfig, serverName string, lines int) ([]string, error) { + if lines <= 0 { + lines = 50 + } + if lines > 500 { + lines = 500 + } + + filename := serverLogFilename(serverName) + logFilePath, err := GetLogFilePathWithDir(config.LogDir, filename) + if err != nil { + return nil, fmt.Errorf("failed to get log file path for server %s: %w", serverName, err) + } + + if _, err := os.Stat(logFilePath); os.IsNotExist(err) { + return []string{}, nil + } + + file, err := os.Open(logFilePath) + if err != nil { + return nil, fmt.Errorf("failed to open log file for server %s: %w", serverName, err) + } + defer file.Close() + + // Filter first, limit second: only attributable records enter the window. + var attributed []string + scanner := bufio.NewScanner(file) + scanner.Buffer(make([]byte, 0, 64*1024), 1024*1024) + for scanner.Scan() { + line := scanner.Text() + if recordAttributableTo(line, serverName) { + attributed = append(attributed, line) + } + } + if err := scanner.Err(); err != nil { + return nil, fmt.Errorf("failed to read log file for server %s: %w", serverName, err) + } + + if attributed == nil { + return []string{}, nil + } + if len(attributed) <= lines { + return attributed, nil + } + return attributed[len(attributed)-lines:], nil +} + +// recordAttributableTo reports whether one rendered log line is attributable +// to serverName under the D8 reader and subject-evidence rules. It is +// encoder-agnostic: a line that is itself one complete JSON object is a +// JSON-encoder record; otherwise the console boundary scan applies, so a file +// written under both encoders over its lifetime is read correctly. +func recordAttributableTo(line, serverName string) bool { + fields, ok := recordFields(line) + if !ok { + return false // no accepted stamp: legacy line, torn fragment, foreign shape + } + return fields.attributableTo(serverName) +} + +// recordFields extracts the fields object of a rendered record, or ok=false +// when the line carries no accepted fields object. +func recordFields(line string) (attributionFields, bool) { + // JSON encoder: the whole line is the record. + if strings.HasPrefix(line, "{") { + if fields, ok := decodeExactlyOneObject(line); ok { + return fields, true + } + } + + // Console encoder: the first ` | {` boundary, scanning left to right, + // whose suffix is exactly one complete JSON object. + from := 0 + for { + idx := strings.Index(line[from:], consoleFieldsBoundary) + if idx < 0 { + return attributionFields{}, false + } + start := from + idx + len(consoleFieldsBoundary) - 1 // at the '{' + if fields, ok := decodeExactlyOneObject(line[start:]); ok { + return fields, true + } + from = start + } +} + +// attributionFields is the subset of a record's top-level fields the +// attribution rules consult. Every occurrence of a key is kept: zap renders a +// logger's With fields first and the call's fields after them, so a record +// can legitimately carry the writer stamp AND a subject `server` field, and +// the rule is that ALL of them must agree. +type attributionFields struct { + servers []string + containerOwners []string + namesContainer bool +} + +// attributableTo applies the stamp and subject-evidence rules. +func (f attributionFields) attributableTo(serverName string) bool { + // Stamp: at least one `server` value, and every one exactly the requested + // name — a callback record naming another server fails here. + if len(f.servers) == 0 { + return false + } + for _, s := range f.servers { + if s != serverName { + return false + } + } + // Subject evidence: a container record needs container_owner == requested + // name; without it (pre-105 housekeeping record) it is withheld, since the + // sanitised container name cannot tell `a/b`'s container from `a-b`'s. + if f.namesContainer && len(f.containerOwners) == 0 { + return false + } + for _, owner := range f.containerOwners { + if owner != serverName { + return false + } + } + return true +} + +// decodeExactlyOneObject decodes s as exactly one complete JSON object with +// nothing after it, collecting the top-level fields the attribution rules +// use. A syntax error, a non-object value, a non-string value under an +// attribution key, or trailing bytes rejects the candidate. +func decodeExactlyOneObject(s string) (attributionFields, bool) { + var fields attributionFields + dec := json.NewDecoder(strings.NewReader(s)) + + tok, err := dec.Token() + if err != nil { + return attributionFields{}, false + } + if delim, ok := tok.(json.Delim); !ok || delim != '{' { + return attributionFields{}, false + } + + for dec.More() { + keyTok, err := dec.Token() + if err != nil { + return attributionFields{}, false + } + key, ok := keyTok.(string) + if !ok { + return attributionFields{}, false + } + var raw json.RawMessage + if err := dec.Decode(&raw); err != nil { + return attributionFields{}, false + } + switch key { + case attributionServerField: + value, ok := decodeStringValue(raw) + if !ok { + return attributionFields{}, false + } + fields.servers = append(fields.servers, value) + case attributionContainerOwnerField: + value, ok := decodeStringValue(raw) + if !ok { + return attributionFields{}, false + } + fields.containerOwners = append(fields.containerOwners, value) + case attributionContainerIDField, attributionContainerNameField: + fields.namesContainer = true + } + } + + closeTok, err := dec.Token() + if err != nil { + return attributionFields{}, false + } + if delim, ok := closeTok.(json.Delim); !ok || delim != '}' { + return attributionFields{}, false + } + // Exactly one object: nothing may follow it. + if _, err := dec.Token(); !errors.Is(err, io.EOF) { + return attributionFields{}, false + } + return fields, true +} + +func decodeStringValue(raw json.RawMessage) (string, bool) { + var value string + if err := json.Unmarshal(raw, &value); err != nil { + return "", false + } + return value, true +} diff --git a/internal/logs/logger.go b/internal/logs/logger.go index 5793e1379..925938f08 100644 --- a/internal/logs/logger.go +++ b/internal/logs/logger.go @@ -546,18 +546,3 @@ func ReadUpstreamServerLogTail(config *config.LogConfig, serverName string, line return allLines[len(allLines)-lines:], nil } - -// ReadUpstreamServerLogTailAttributed reads the last N records of an upstream -// server log that are attributable to serverName (Spec 105 FR-007, research -// D8). Two raw names can share one file (`a/b` and `a_b` both sanitise to -// server-a_b.log), so scoped callers must receive only the records whose -// writer stamp (`server=`) is exactly serverName, filtered BEFORE the -// tail limit; records with no accepted stamp are non-attributable and -// withheld. Administrators keep ReadUpstreamServerLogTail (whole file). -// -// Red-phase scaffold (PR E, T054): the signature is fixed here so the -// attribution tests compile against HEAD and fail by assertion; the body is -// the unfiltered whole-file reader until T054 lands the attributed reader. -func ReadUpstreamServerLogTailAttributed(config *config.LogConfig, serverName string, lines int) ([]string, error) { - return ReadUpstreamServerLogTail(config, serverName, lines) -} diff --git a/internal/oauth/callback_stop_logger_test.go b/internal/oauth/callback_stop_logger_test.go index 8118bad83..c1e3075eb 100644 --- a/internal/oauth/callback_stop_logger_test.go +++ b/internal/oauth/callback_stop_logger_test.go @@ -87,20 +87,24 @@ func assertStopRoutedToOwner(t *testing.T, mgr *CallbackServerManager, observed own := observed[stopped] foreign := observed[other] // The serve goroutine ALSO emits "OAuth callback server stopped" through - // the server's own logger once Serve returns; wait for it so the count - // below is deterministic: goroutine record + manager record = 2 in the - // owner's log, 0 anywhere else. + // the server's own logger once Serve returns, and it races the manager's + // record; wait for both so the count below is deterministic: goroutine + // record + manager record = 2 in the owner's log, 0 anywhere else. require.Eventually(t, func() bool { - return len(own.FilterMessage("OAuth callback server stopped").All()) >= 1 - }, 2*time.Second, 10*time.Millisecond, "serve goroutine's own stop record never arrived") + return len(own.FilterMessage("OAuth callback server stopped").All()) >= 2 + }, 2*time.Second, 10*time.Millisecond, + "%s's manager stop record must be written through %s's recorded logger (goroutine record + manager record)", stopped, stopped) assert.Len(t, own.FilterMessage("OAuth callback server stopped").All(), 2, "%s's manager stop record must be written through %s's recorded logger (goroutine record + manager record)", stopped, stopped) assert.Len(t, own.FilterMessage("Stopped OAuth callback server while flows were still waiting").All(), 1, "%s's dropped-waiter record must be written through %s's recorded logger", stopped, stopped) - assert.Empty(t, foreign.FilterMessage("OAuth callback server stopped").All(), + // The other server's observer keeps its OWN tear-down records from an + // earlier round; only records about `stopped` are forbidden there. + aboutStopped := foreign.FilterField(zap.String("server", stopped)) + assert.Empty(t, aboutStopped.FilterMessage("OAuth callback server stopped").All(), "%s's stop record landed in %s's log", stopped, other) - assert.Empty(t, foreign.FilterMessage("Stopped OAuth callback server while flows were still waiting").All(), + assert.Empty(t, aboutStopped.FilterMessage("Stopped OAuth callback server while flows were still waiting").All(), "%s's dropped-waiter record landed in %s's log", stopped, other) assert.Empty(t, mentionsServer(foreign, stopped, stoppedPort), "%s's name/port written into %s's log", stopped, other) diff --git a/internal/oauth/config.go b/internal/oauth/config.go index c800d61ff..bd5a47f2a 100644 --- a/internal/oauth/config.go +++ b/internal/oauth/config.go @@ -1687,23 +1687,47 @@ func (m *CallbackServerManager) StopCallbackServer(serverName string) error { return m.StopCallbackServerWithLogger(serverName, nil) } -// StopCallbackServerWithLogger is StopCallbackServer with the caller's logger, -// so the tear-down (and any waiter it drops) is actually recorded. +// StopCallbackServerWithLogger is StopCallbackServer with the caller's logger. +// The signature is kept for its callers; the tear-down records are written +// through the stopped server's OWN recorded logger (Spec 105 FR-007, +// subject-bound routing), and the caller's logger is only the fallback for a +// server that recorded none. Stopping never adopts a logger as the manager +// logger: the manager serves every server, and the last-installed logger is a +// tee into whichever server's log file ran a flow last — pre-105 that is where +// another server's name, bind host, port and dropped-waiter count landed. func (m *CallbackServerManager) StopCallbackServerWithLogger(serverName string, logger *zap.Logger) error { m.mu.Lock() defer m.mu.Unlock() - return m.stopCallbackServerLocked(serverName, m.adoptLoggerLocked(logger)) + return m.stopCallbackServerLocked(serverName, logger) } // stopCallbackServerLocked shuts the server down and removes it from the map. -// m.mu must be held. -func (m *CallbackServerManager) stopCallbackServerLocked(serverName string, logger *zap.Logger) error { +// m.mu must be held. fallback is consulted only when the server recorded no +// logger of its own (every server started through StartCallbackServerOnHost +// records one); a nil fallback resolves to the manager logger. +func (m *CallbackServerManager) stopCallbackServerLocked(serverName string, fallback *zap.Logger) error { server, exists := m.servers[serverName] if !exists { return nil // Already stopped or never started } + // Subject-bound (FR-007): the record concerns `server`, so it is written + // through the logger recorded for that server at start — the tee into + // ITS per-server log — never through whichever logger was installed last. + // The recorded logger already carries server, bind_host and port as + // context fields. + logger := server.logger + if logger == nil { + logger = fallback + } + if logger == nil { + logger = m.logger + } + if logger == nil { + logger = zap.L().Named(oauthCallbackLoggerName) + } + // Shutdown the server ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() diff --git a/internal/server/mcp.go b/internal/server/mcp.go index 0fc13e096..5dd31714f 100644 --- a/internal/server/mcp.go +++ b/internal/server/mcp.go @@ -5932,8 +5932,22 @@ func (p *MCPProxyServer) handleTailLog(ctx context.Context, request mcp.CallTool } } - // Read log tail - logLines, err := logs.ReadUpstreamServerLogTail(logConfig, name, lines) + // Read log tail. Spec 105 FR-007 (research D8): two raw names can share + // one log file (`a/b` and `a_b` both sanitise to server-a_b.log), so a + // scoped caller receives only the records attributable to the server it + // asked for — filtered BEFORE the tail limit, so an interleaved co-owner + // record never displaces an authorized one, and lines_returned counts the + // authorized tail. The policy is uniform whether or not a co-owner exists: + // legacy records with no writer stamp are withheld either way, never a + // whole-file refusal. Administrators (nil AuthContext, API key, socket) + // keep the whole file exactly as before (SC-005) — a profile scope bounds + // WHICH server they may name (above), not which records of it they see. + var logLines []string + if authCtx == nil || authCtx.IsAdmin() { + logLines, err = logs.ReadUpstreamServerLogTail(logConfig, name, lines) + } else { + logLines, err = logs.ReadUpstreamServerLogTailAttributed(logConfig, name, lines) + } if err != nil { return mcp.NewToolResultError(fmt.Sprintf("Failed to read log for server '%s': %v", name, err)), nil } diff --git a/internal/server/mcp_secret_redaction_test.go b/internal/server/mcp_secret_redaction_test.go index 9c7d198cb..77c0c2baf 100644 --- a/internal/server/mcp_secret_redaction_test.go +++ b/internal/server/mcp_secret_redaction_test.go @@ -285,6 +285,14 @@ func TestScrubUpstreamText_ConnectionErrors(t *testing.T) { // attempt, and connection_launcher.go pipes the child process's own stdout into // the same file. `tail_log` returned those lines verbatim and recorded them // into the activity store. +// +// The fixture records carry the writer stamp `server=leaky` in both encoder +// shapes (Spec 105 FR-007: a scoped caller receives only attributable +// records, so an unstamped fixture line would now be withheld before the +// scrubber ever saw it and the scoped assertions would pass vacuously). They +// are written by hand rather than through the per-server writer because that +// writer's own sanitizer would mask the credentials at write time — the point +// here is the scrub on the READ path, for scoped and administrator callers. func TestTailLog_ScrubsLogLines(t *testing.T) { proxy := createTestMCPProxyServer(t) @@ -301,20 +309,34 @@ func TestTailLog_ScrubsLogLines(t *testing.T) { require.NoError(t, proxy.storage.SaveUpstreamServer(&config.ServerConfig{ Name: "leaky", Protocol: "http", Enabled: true, })) + const childToken = "ghp_abcdefghijklmnopqrstuvwxyz0123456789" require.NoError(t, os.WriteFile(filepath.Join(logDir, "server-leaky.log"), []byte( - `{"level":"info","msg":"Starting connection attempt","url":"https://host/mcp?token=`+leakySecrets["url"]+`"}`+"\n"+ - `child stdout: using ghp_abcdefghijklmnopqrstuvwxyz0123456789`+"\n"), 0o600)) - - request := mcp.CallToolRequest{} - request.Params.Arguments = map[string]interface{}{"name": "leaky"} - - result, err := proxy.handleTailLog(context.Background(), request) - require.NoError(t, err) - body := toolResultText(t, result) - - assert.NotContains(t, body, leakySecrets["url"], "tail_log leaks the URL credential mcpproxy itself logged") - assert.NotContains(t, body, "ghp_abcdefghijklmnopqrstuvwxyz0123456789") - assert.Contains(t, body, "Starting connection attempt", "the diagnostic content must survive") + // JSON-encoder shape: the connection logger's URL record. + `{"level":"info","msg":"Starting connection attempt","server":"leaky","url":"https://host/mcp?token=`+leakySecrets["url"]+`"}`+"\n"+ + // Console-encoder shape: the launcher-pumped child stdout line is the MESSAGE. + `2026-01-01T00:00:00.000Z | INFO | core/connection_launcher.go:1 | [launcher stdout] child stdout: using `+childToken+` | {"server": "leaky"}`+"\n"), 0o600)) + + for name, ctx := range map[string]context.Context{ + "scoped agent token": agentCtx([]string{"leaky"}, []string{auth.PermRead}, ""), + "administrator": adminCtx(), + "no auth ctx (in-proc)": context.Background(), + } { + t.Run(name, func(t *testing.T) { + request := mcp.CallToolRequest{} + request.Params.Arguments = map[string]interface{}{"name": "leaky"} + + result, err := proxy.handleTailLog(ctx, request) + require.NoError(t, err) + body := toolResultText(t, result) + require.False(t, result.IsError, body) + + assert.NotContains(t, body, leakySecrets["url"], "tail_log leaks the URL credential mcpproxy itself logged") + assert.NotContains(t, body, childToken) + assert.Contains(t, body, "Starting connection attempt", "the diagnostic content must survive") + assert.Contains(t, body, "child stdout: using", "the child's own line must survive (scrubbed)") + assert.Contains(t, body, `"lines_returned":2`, "both stamped records are attributable to leaky: %s", body) + }) + } } // TestArgvMaskEcho_GuardsTheWritePath is the write-path counterpart to masking diff --git a/internal/server/mcp_tail_log_scope_test.go b/internal/server/mcp_tail_log_scope_test.go index ddcd92dbc..4a5918f39 100644 --- a/internal/server/mcp_tail_log_scope_test.go +++ b/internal/server/mcp_tail_log_scope_test.go @@ -19,10 +19,18 @@ import ( "github.com/smart-mcp-proxy/mcpproxy-go/internal/profile" ) -// tailLogCanary is written into every fixture server's log. Its presence in a -// tool response proves the log was disclosed. +// tailLogCanary is written into every fixture server's log through the REAL +// stamped per-server writer. Its presence in a tool response proves the log +// was disclosed. const tailLogCanary = "CANARY-upstream-log-line-7f3a" +// tailLogLegacyLine is appended to every fixture server's log WITHOUT a +// writer stamp (a pre-105 record). Spec 105 FR-007: a record with no +// attribution is withheld from scoped callers and kept for administrators — +// pre-105 this fixture's canary was itself an unstamped line served to the +// scoped token, which the attributed reader now (correctly) withholds. +const tailLogLegacyLine = "LEGACY-unstamped-log-line-2b61" + // newTailLogScopeProxy builds a proxy with two upstreams, "github" and // "secret", each with a per-server log file AND a registered (never // connected) upstream client so a served response carries connection_status, @@ -62,8 +70,15 @@ func newTailLogScopeProxy(t *testing.T) *MCPProxyServer { // served response includes connection_status (otherwise the // "connection status not disclosed" assertions would pass vacuously). require.NoError(t, proxy.upstreamManager.AddServerConfig(name, sc)) + // A pre-105 unstamped record first, then the canary through the real + // stamped writer (the one internal/upstream/core installs). require.NoError(t, os.WriteFile(filepath.Join(logDir, "server-"+name+".log"), - []byte(tailLogCanary+" "+name+"\n"), 0o600)) + []byte(tailLogLegacyLine+" "+name+"\n"), 0o600)) + writer, closer, err := logs.NewUpstreamServerLogger(cfg.Logging, name) + require.NoError(t, err) + t.Cleanup(func() { _ = closer.Close() }) + writer.Info(tailLogCanary + " " + name) + _ = writer.Sync() } return proxy } @@ -107,15 +122,34 @@ func assertTailLogHidden(t *testing.T, proxy *MCPProxyServer, ctx context.Contex assert.NotContains(t, body, "connection_status", "connection status disclosed") } -// assertTailLogServed asserts the in-scope / admin path returns the log, -// the stored flags and the live connection status. -func assertTailLogServed(t *testing.T, proxy *MCPProxyServer, ctx context.Context, name string) { +// assertTailLogServed asserts the in-scope / admin path returns the stamped +// log record, the stored flags and the live connection status, and returns +// the body for the caller's attribution assertions. +func assertTailLogServed(t *testing.T, proxy *MCPProxyServer, ctx context.Context, name string) string { t.Helper() result, body := tailLogVia(t, proxy, ctx, name) assert.False(t, result.IsError, "in-scope tail_log must succeed: %s", body) assert.Contains(t, body, tailLogCanary+" "+name) assert.Contains(t, body, "server_status") assert.Contains(t, body, "connection_status", "fixture must register a client, or the non-disclosure assertions prove nothing") + return body +} + +// assertTailLogServedScoped is assertTailLogServed for a scoped caller: the +// stamped record is served, the unstamped legacy record is withheld +// (Spec 105 FR-007 — attribution is uniform, co-owner or not). +func assertTailLogServedScoped(t *testing.T, proxy *MCPProxyServer, ctx context.Context, name string) { + t.Helper() + body := assertTailLogServed(t, proxy, ctx, name) + assert.NotContains(t, body, tailLogLegacyLine, "unattributed legacy record served to a scoped caller") +} + +// assertTailLogServedWholeFile is assertTailLogServed for an administrator: +// the whole file, legacy record included (SC-005). +func assertTailLogServedWholeFile(t *testing.T, proxy *MCPProxyServer, ctx context.Context, name string) { + t.Helper() + body := assertTailLogServed(t, proxy, ctx, name) + assert.Contains(t, body, tailLogLegacyLine+" "+name, "administrators keep the whole file") } func TestTailLog_ServerRestrictedToken_HidesOutOfScopeServer(t *testing.T) { @@ -128,7 +162,7 @@ func TestTailLog_ServerRestrictedToken_HidesOutOfScopeServer(t *testing.T) { }) assertTailLogHidden(t, proxy, ctx, "secret") - assertTailLogServed(t, proxy, ctx, "github") + assertTailLogServedScoped(t, proxy, ctx, "github") } func TestTailLog_ProfilePinnedToken_HidesServerOutsideProfile(t *testing.T) { @@ -142,7 +176,7 @@ func TestTailLog_ProfilePinnedToken_HidesServerOutsideProfile(t *testing.T) { }) assertTailLogHidden(t, proxy, ctx, "secret") - assertTailLogServed(t, proxy, ctx, "github") + assertTailLogServedScoped(t, proxy, ctx, "github") } // A pin whose profile no longer exists resolves to a deny-all scope (see @@ -166,18 +200,18 @@ func TestTailLog_AdminUnchanged(t *testing.T) { proxy := newTailLogScopeProxy(t) adminCtx := auth.WithAuthContext(context.Background(), &auth.AuthContext{Type: auth.AuthTypeAdmin}) - assertTailLogServed(t, proxy, adminCtx, "secret") - assertTailLogServed(t, proxy, adminCtx, "github") + assertTailLogServedWholeFile(t, proxy, adminCtx, "secret") + assertTailLogServedWholeFile(t, proxy, adminCtx, "github") // No AuthContext at all (in-process / stdio caller) is treated as admin by // the shared server-op policy; unchanged here. - assertTailLogServed(t, proxy, context.Background(), "secret") + assertTailLogServedWholeFile(t, proxy, context.Background(), "secret") // An admin's AllowedServers is never consulted, even when populated. narrowAdmin := auth.WithAuthContext(context.Background(), &auth.AuthContext{ Type: auth.AuthTypeAdmin, AllowedServers: []string{"github"}, }) - assertTailLogServed(t, proxy, narrowAdmin, "secret") + assertTailLogServedWholeFile(t, proxy, narrowAdmin, "secret") } // An explicit URL profile (/mcp/p/) bounds tail_log for every caller, @@ -187,14 +221,16 @@ func TestTailLog_URLProfileScope_AppliesToAllCallers(t *testing.T) { proxy := newTailLogScopeProxy(t) scope := profile.NewProfileScope("gh", []string{"github"}) + // A profile bounds WHICH server an administrator may name, not which + // records of it they see: still the whole file. adminInProfile := profile.WithProfileScope( auth.WithAuthContext(context.Background(), &auth.AuthContext{Type: auth.AuthTypeAdmin}), scope) assertTailLogHidden(t, proxy, adminInProfile, "secret") - assertTailLogServed(t, proxy, adminInProfile, "github") + assertTailLogServedWholeFile(t, proxy, adminInProfile, "github") anonInProfile := profile.WithProfileScope(context.Background(), scope) assertTailLogHidden(t, proxy, anonInProfile, "secret") - assertTailLogServed(t, proxy, anonInProfile, "github") + assertTailLogServedWholeFile(t, proxy, anonInProfile, "github") } // --------------------------------------------------------------------------- @@ -265,9 +301,10 @@ func newTailLogCollidingProxy(t *testing.T) *tailLogCollidingFixture { return f } -// write emits one record through name's real stamped writer. One call site -// for every record keeps the console encoder's caller segment constant, so -// two fixtures' lines differ only by timestamp (see tailLogLineSignature). +// write emits one record through name's real stamped writer. The writer +// records its CALLER's caller (NewUpstreamServerLogger adds one frame of +// skip), i.e. the test line that called write, so two fixtures' lines differ +// by timestamp and caller segment — both stripped by tailLogLineSignature. func (f *tailLogCollidingFixture) write(name, msg string) { f.writers[name].Info(msg) _ = f.writers[name].Sync() @@ -296,14 +333,15 @@ func tailLogLinesVia(t *testing.T, proxy *MCPProxyServer, ctx context.Context, n return parsed, body } -// tailLogLineSignature strips the leading timestamp segment of a console -// record (`ts | LEVEL | caller | msg | {fields}`) so records from two -// fixtures written through the same call site compare equal. +// tailLogLineSignature strips the timestamp and caller segments of a console +// record (`ts | LEVEL | caller | msg | {fields}`) so records written by two +// fixtures compare on level, message and fields only. func tailLogLineSignature(line string) string { - if _, rest, ok := strings.Cut(line, " | "); ok { - return rest + parts := strings.SplitN(line, " | ", 4) + if len(parts) < 4 { + return line } - return line + return parts[1] + " | " + parts[3] } func tailLogSignatures(lines []string) []string { diff --git a/internal/upstream/core/connection_docker.go b/internal/upstream/core/connection_docker.go index ef4cd02fc..f6806469f 100644 --- a/internal/upstream/core/connection_docker.go +++ b/internal/upstream/core/connection_docker.go @@ -76,6 +76,7 @@ func (c *Client) setupDockerIsolation(command string, args []string) (dockerComm c.upstreamLogger.Info("Docker isolation configured", zap.String("runtime_type", runtimeType), zap.String("container_name", c.containerName), + containerOwnerField(c.config.Name), zap.String("container_command", containerCommand)) } diff --git a/internal/upstream/core/connection_launcher.go b/internal/upstream/core/connection_launcher.go index 266d1041f..76be40610 100644 --- a/internal/upstream/core/connection_launcher.go +++ b/internal/upstream/core/connection_launcher.go @@ -341,9 +341,22 @@ func newLoggerWriter(primary, fallback *zap.Logger) io.Writer { } func (w *loggerWriter) Write(p []byte) (int, error) { - line := strings.TrimRight(string(p), "\n") + // One record per line. pumpLines already writes one line per call; the + // split is the guarantee for any other producer, because the child's text + // becomes the console-encoder MESSAGE of its record and a message must + // never carry a line break — a break would start a new line whose text + // the child controls, and the attributed log reader (Spec 105 FR-007, + // internal/logs research D8 rule 2) keys on line boundaries. + for _, line := range strings.Split(strings.TrimRight(string(p), "\n"), "\n") { + w.writeLine(strings.TrimRight(line, "\r")) + } + return len(p), nil +} + +// writeLine records one child output line through the per-server logger. +func (w *loggerWriter) writeLine(line string) { if line == "" { - return len(p), nil + return } // Issue #1158 (review round 2, investigation 3). This is the child // process's own stdout/stderr, written verbatim into @@ -366,5 +379,4 @@ func (w *loggerWriter) Write(p []byte) (int, error) { case w.fallback != nil: w.fallback.Info(line) } - return len(p), nil } diff --git a/internal/upstream/core/docker.go b/internal/upstream/core/docker.go index 90d853084..11be2ee6f 100644 --- a/internal/upstream/core/docker.go +++ b/internal/upstream/core/docker.go @@ -74,6 +74,7 @@ func (c *Client) readContainerIDWithContext(ctx context.Context, cidFile string) if c.upstreamLogger != nil { c.upstreamLogger.Info("Container ID captured", zap.String("container_id", containerID), + containerOwnerField(c.config.Name), zap.Int("attempt", attempt)) } @@ -103,6 +104,7 @@ func (c *Client) readContainerIDWithContext(ctx context.Context, cidFile string) // Fallback: Find container by name if c.containerName != "" { listCmd := c.newDockerCmd(ctx, "ps", + "--filter", "label="+containerOwnerLabel+"="+c.config.Name, "--filter", fmt.Sprintf("name=^%s$", c.containerName), "--format", "{{.ID}}") @@ -121,7 +123,8 @@ func (c *Client) readContainerIDWithContext(ctx context.Context, cidFile string) if c.upstreamLogger != nil { c.upstreamLogger.Info("Container ID recovered via name lookup", - zap.String("container_id", foundID)) + zap.String("container_id", foundID), + containerOwnerField(c.config.Name)) } // Clean up the cidfile since we got the ID @@ -162,7 +165,8 @@ func (c *Client) killDockerContainerWithContext(ctx context.Context) { if c.upstreamLogger != nil { c.upstreamLogger.Info("Killing Docker container", - zap.String("container_id", containerID)) + zap.String("container_id", containerID), + containerOwnerField(c.config.Name)) } // First try graceful stop (SIGTERM) @@ -266,13 +270,15 @@ func (c *Client) killDockerContainerByCommandWithContext(ctx context.Context) { return } - c.logger.Debug("Searching for containers by image name", + c.logger.Debug("Searching for owned containers by image name", zap.String("server", c.config.Name), zap.String("image_name", imageName)) - // Get list of running containers with image and created time - listCmd := c.newDockerCmd(ctx, "ps", "--format", "{{.ID}}\t{{.Image}}\t{{.CreatedAt}}") - output, err := listCmd.Output() + // Spec 105 FR-007 / D9: the image-name fallback lists only containers this + // server canonically owns (label + name regex) and then matches the image, + // so a foreign container that merely shares the image is neither killed + // nor written into this server's log. + owned, err := c.listOwnedContainers(ctx, false) if err != nil { c.logger.Error("Failed to list Docker containers for cleanup", zap.String("server", c.config.Name), @@ -280,84 +286,46 @@ func (c *Client) killDockerContainerByCommandWithContext(ctx context.Context) { return } - // Parse output and find matching containers - lines := strings.Split(strings.TrimSpace(string(output)), "\n") - var containersToKill []string - - for _, line := range lines { - if line == "" { - continue - } - parts := strings.SplitN(line, "\t", 3) - if len(parts) >= 2 { - containerID := parts[0] - image := parts[1] - - // Check if this container matches our image - if image == imageName { - containersToKill = append(containersToKill, containerID) - c.logger.Info("Found matching container for cleanup", - zap.String("server", c.config.Name), - zap.String("container_id", containerID), - zap.String("image", image)) - } + var containersToKill []ownedContainer + for _, container := range owned { + // Check if this container matches our image + if container.Image == imageName { + containersToKill = append(containersToKill, container) + c.logger.Info("Found matching owned container for cleanup", + zap.String("server", c.config.Name), + zap.String("container_id", container.ID), + zap.String("container_name", container.Name), + containerOwnerField(container.Owner), + zap.String("image", container.Image)) } } if len(containersToKill) == 0 { - c.logger.Debug("No matching containers found for cleanup", + c.logger.Debug("No matching owned containers found for cleanup", zap.String("server", c.config.Name), zap.String("image_name", imageName)) return } // Kill matching containers - for _, containerID := range containersToKill { - c.logger.Info("Killing matching Docker container", - zap.String("server", c.config.Name), - zap.String("container_id", containerID)) - - if c.upstreamLogger != nil { - c.upstreamLogger.Info("Killing matching container", - zap.String("container_id", containerID)) - } - - // First try graceful stop - stopCmd := c.newDockerCmd(ctx, "stop", containerID) - if err := stopCmd.Run(); err != nil { - // Force kill if graceful stop fails - killCmd := c.newDockerCmd(ctx, "kill", containerID) - if err := killCmd.Run(); err != nil { - c.logger.Error("Failed to kill matching Docker container", - zap.String("server", c.config.Name), - zap.String("container_id", containerID), - zap.Error(err)) - } else { - c.logger.Info("Successfully force killed matching Docker container", - zap.String("server", c.config.Name), - zap.String("container_id", containerID)) - } - } else { - c.logger.Info("Successfully stopped matching Docker container", - zap.String("server", c.config.Name), - zap.String("container_id", containerID)) - } + for _, container := range containersToKill { + c.stopOwnedContainer(ctx, container, "image") } } -// killDockerContainersByNamePatternWithContext finds and kills containers by name pattern +// killDockerContainersByNamePatternWithContext finds and kills the containers +// this server canonically owns (Spec 105 FR-007 / D9: label +// com.mcpproxy.server= AND name ^mcpproxy--[a-z0-9]{4}$). +// Pre-105 this was a `name=mcpproxy--` substring filter, which +// also matched — and killed, and logged — `a-b`'s containers for server `a`. func (c *Client) killDockerContainersByNamePatternWithContext(ctx context.Context) bool { - // Create sanitized server name for pattern matching - sanitized := sanitizeServerNameForContainer(c.config.Name) - namePattern := "mcpproxy-" + sanitized + "-" + namePattern := ownedContainerNamePattern(c.config.Name) - c.logger.Debug("Searching for containers by name pattern", + c.logger.Debug("Searching for owned containers by name pattern", zap.String("server", c.config.Name), zap.String("name_pattern", namePattern)) - // Get list of containers with name filter - listCmd := c.newDockerCmd(ctx, "ps", "-a", "--filter", "name="+namePattern, "--format", "{{.ID}}\t{{.Names}}") - output, err := listCmd.Output() + owned, err := c.listOwnedContainers(ctx, true) if err != nil { c.logger.Debug("Failed to list Docker containers by name pattern", zap.String("server", c.config.Name), @@ -366,68 +334,24 @@ func (c *Client) killDockerContainersByNamePatternWithContext(ctx context.Contex return false } - // Parse output and find matching containers - lines := strings.Split(strings.TrimSpace(string(output)), "\n") - var containersToKill []string - - for _, line := range lines { - if line == "" { - continue - } - parts := strings.SplitN(line, "\t", 2) - if len(parts) >= 2 { - containerID := parts[0] - containerName := parts[1] - - // Check if the container name starts with our pattern - if strings.HasPrefix(containerName, namePattern) { - containersToKill = append(containersToKill, containerID) - c.logger.Info("Found matching container by name pattern", - zap.String("server", c.config.Name), - zap.String("container_id", containerID), - zap.String("container_name", containerName)) - } - } + for _, container := range owned { + c.logger.Info("Found owned container by name pattern", + zap.String("server", c.config.Name), + zap.String("container_id", container.ID), + zap.String("container_name", container.Name), + containerOwnerField(container.Owner)) } - if len(containersToKill) == 0 { - c.logger.Debug("No matching containers found by name pattern", + if len(owned) == 0 { + c.logger.Debug("No owned containers found by name pattern", zap.String("server", c.config.Name), zap.String("name_pattern", namePattern)) return false } - // Kill matching containers - for _, containerID := range containersToKill { - c.logger.Info("Killing container by name pattern", - zap.String("server", c.config.Name), - zap.String("container_id", containerID)) - - if c.upstreamLogger != nil { - c.upstreamLogger.Info("Killing container by name pattern", - zap.String("container_id", containerID)) - } - - // First try graceful stop - stopCmd := c.newDockerCmd(ctx, "stop", containerID) - if err := stopCmd.Run(); err != nil { - // Force kill if graceful stop fails - killCmd := c.newDockerCmd(ctx, "kill", containerID) - if err := killCmd.Run(); err != nil { - c.logger.Error("Failed to kill container by name pattern", - zap.String("server", c.config.Name), - zap.String("container_id", containerID), - zap.Error(err)) - } else { - c.logger.Info("Successfully force killed container by name pattern", - zap.String("server", c.config.Name), - zap.String("container_id", containerID)) - } - } else { - c.logger.Info("Successfully stopped container by name pattern", - zap.String("server", c.config.Name), - zap.String("container_id", containerID)) - } + // Kill owned containers + for _, container := range owned { + c.stopOwnedContainer(ctx, container, "name pattern") } return true // We found and processed containers @@ -439,8 +363,14 @@ func (c *Client) killDockerContainerByNameWithContext(ctx context.Context, conta zap.String("server", c.config.Name), zap.String("container_name", containerName)) - // Get container ID by exact name match - listCmd := c.newDockerCmd(ctx, "ps", "-a", "--filter", "name=^"+containerName+"$", "--format", "{{.ID}}") + // Get container ID by exact name match. The name is the one this server + // generated for its own container (setupDockerIsolation), and the label + // filter keeps a same-named foreign container out of the result + // (Spec 105 FR-007 / D9). + listCmd := c.newDockerCmd(ctx, "ps", "-a", + "--filter", "label="+containerOwnerLabel+"="+c.config.Name, + "--filter", "name=^"+containerName+"$", + "--format", "{{.ID}}") output, err := listCmd.Output() if err != nil { c.logger.Debug("Failed to find Docker container by name", @@ -466,7 +396,8 @@ func (c *Client) killDockerContainerByNameWithContext(ctx context.Context, conta if c.upstreamLogger != nil { c.upstreamLogger.Info("Killing container by name", zap.String("container_name", containerName), - zap.String("container_id", containerID)) + zap.String("container_id", containerID), + containerOwnerField(c.config.Name)) } // First try graceful stop @@ -496,83 +427,74 @@ func (c *Client) killDockerContainerByNameWithContext(ctx context.Context, conta return true } -// ensureNoExistingContainers removes all existing containers for this server before creating a new one -// This makes container creation idempotent and prevents duplicate container spawning +// ensureNoExistingContainers removes all existing containers this server +// canonically owns before creating a new one. This makes container creation +// idempotent and prevents duplicate container spawning. Ownership is label +// com.mcpproxy.server= AND name ^mcpproxy--[a-z0-9]{4}$ +// (Spec 105 FR-007 / D9): a foreign container whose name merely shares the +// prefix — `a-b`'s or `a/b`'s for server `a` — is neither removed nor named +// in this server's log. func (c *Client) ensureNoExistingContainers(ctx context.Context) error { - sanitized := sanitizeServerNameForContainer(c.config.Name) - namePattern := "mcpproxy-" + sanitized + "-" + namePattern := ownedContainerNamePattern(c.config.Name) - c.logger.Info("Checking for existing containers before creation", + c.logger.Info("Checking for existing owned containers before creation", zap.String("server", c.config.Name), zap.String("name_pattern", namePattern)) - // Find ALL containers matching our server (running or stopped) - listCmd := c.newDockerCmd(ctx, "ps", "-a", - "--filter", "name="+namePattern, - "--format", "{{.ID}}\t{{.Names}}\t{{.Status}}") - - output, err := listCmd.Output() + // Find ALL containers owned by this server (running or stopped) + owned, err := c.listOwnedContainers(ctx, true) if err != nil { return fmt.Errorf("failed to list existing containers: %w", err) } - lines := strings.Split(strings.TrimSpace(string(output)), "\n") - if len(lines) == 0 || lines[0] == "" { - c.logger.Debug("No existing containers found - safe to create new one", + if len(owned) == 0 { + c.logger.Debug("No existing owned containers found - safe to create new one", zap.String("server", c.config.Name)) return nil } // Found existing containers - clean them up first - c.logger.Warn("Found existing containers - cleaning up before creating new one", + c.logger.Warn("Found existing owned containers - cleaning up before creating new one", zap.String("server", c.config.Name), - zap.Int("container_count", len(lines))) + zap.Int("container_count", len(owned))) if c.upstreamLogger != nil { c.upstreamLogger.Warn("Cleaning up existing containers before creating new one", - zap.Int("container_count", len(lines))) + zap.Int("container_count", len(owned))) } - for _, line := range lines { - if line == "" { - continue + for _, container := range owned { + c.logger.Info("Removing existing container", + zap.String("server", c.config.Name), + zap.String("container_id", container.ID), + zap.String("container_name", container.Name), + containerOwnerField(container.Owner), + zap.String("status", container.Status)) + + if c.upstreamLogger != nil { + c.upstreamLogger.Info("Removing existing container", + zap.String("container_id", container.ID), + zap.String("container_name", container.Name), + containerOwnerField(container.Owner)) } - parts := strings.SplitN(line, "\t", 3) - if len(parts) >= 2 { - containerID := parts[0] - containerName := parts[1] - status := "" - if len(parts) >= 3 { - status = parts[2] - } - c.logger.Info("Removing existing container", - zap.String("server", c.config.Name), - zap.String("container_id", containerID), - zap.String("container_name", containerName), - zap.String("status", status)) + // Force remove (works for running and stopped containers) + rmCmd := c.newDockerCmd(ctx, "rm", "-f", container.ID) + if err := rmCmd.Run(); err != nil { + c.logger.Error("Failed to remove existing container", + zap.String("container_id", container.ID), + containerOwnerField(container.Owner), + zap.Error(err)) + // Continue anyway - try to remove others + } else { + c.logger.Info("Successfully removed existing container", + zap.String("container_id", container.ID), + containerOwnerField(container.Owner)) if c.upstreamLogger != nil { - c.upstreamLogger.Info("Removing existing container", - zap.String("container_id", containerID), - zap.String("container_name", containerName)) - } - - // Force remove (works for running and stopped containers) - rmCmd := c.newDockerCmd(ctx, "rm", "-f", containerID) - if err := rmCmd.Run(); err != nil { - c.logger.Error("Failed to remove existing container", - zap.String("container_id", containerID), - zap.Error(err)) - // Continue anyway - try to remove others - } else { - c.logger.Info("Successfully removed existing container", - zap.String("container_id", containerID)) - - if c.upstreamLogger != nil { - c.upstreamLogger.Info("Successfully removed existing container", - zap.String("container_id", containerID)) - } + c.upstreamLogger.Info("Successfully removed existing container", + zap.String("container_id", container.ID), + containerOwnerField(container.Owner)) } } } diff --git a/internal/upstream/core/docker_ownership.go b/internal/upstream/core/docker_ownership.go new file mode 100644 index 000000000..5f9e3d65a --- /dev/null +++ b/internal/upstream/core/docker_ownership.go @@ -0,0 +1,163 @@ +package core + +import ( + "context" + "regexp" + "strings" + + "go.uber.org/zap" +) + +// Spec 105 FR-007 (gap FR007-G5, research D9): canonical container ownership. +// +// Every container mcpproxy creates is named `mcpproxy--<4 chars>` +// (generateContainerName) and labelled `com.mcpproxy.server=` +// (formatContainerLabels). The name alone is NOT ownership evidence: `a/b` +// and `a-b` both sanitise to `a-b`, and `a`'s old prefix filter +// (`name=mcpproxy-a-`) is a substring match that also lists `a-b`'s +// containers. Pre-105 every cleanup path removed those foreign containers +// and wrote their ids and names into `a`'s per-server log, which +// `upstream_servers tail_log` serves to an `a`-scoped agent. +// +// A container is owned by server S iff BOTH hold: +// - its com.mcpproxy.server label equals S's raw name exactly, and +// - its name matches ^mcpproxy--[a-z0-9]{4}$ (the regex guards +// against a foreign process re-using the label). +// +// Docker applies both filters server-side (`--filter label=` is an exact +// match, `--filter name=` a regexp match) and ownsContainer re-checks them in +// Go, so no container that fails either is ever mutated or logged. Pre-label +// containers and user-`--name` containers are left alone: they never were ours +// by this rule. Every housekeeping record that names a container carries +// `container_owner` — the label value — so the attributed log reader +// (internal/logs, D8 rule 3) can prove the subject belongs to the requested +// server; that field is the only administrator-visible change (SC-005). + +// containerOwnerLabel is the Docker label carrying the RAW server name of the +// mcpproxy server a container was created for (formatContainerLabels). +const containerOwnerLabel = "com.mcpproxy.server" + +// ownedContainerSuffixPattern is the random suffix generateRandomSuffix +// produces: four lowercase alphanumerics. +const ownedContainerSuffixPattern = "[a-z0-9]{4}" + +// ownedContainerNamePattern returns the anchored regexp every container +// owned by serverName must match by name. +func ownedContainerNamePattern(serverName string) string { + return "^mcpproxy-" + regexp.QuoteMeta(sanitizeServerNameForContainer(serverName)) + "-" + ownedContainerSuffixPattern + "$" +} + +// ownsContainer is the Go-side ownership predicate: label AND canonical name. +func ownsContainer(serverName, containerName, ownerLabel string) bool { + if ownerLabel != serverName { + return false + } + matched, err := regexp.MatchString(ownedContainerNamePattern(serverName), containerName) + return err == nil && matched +} + +// ownedContainer is one `docker ps` row that passed the ownership predicate. +type ownedContainer struct { + ID string + Name string + Status string + Image string + Owner string // the com.mcpproxy.server label value (== the server's raw name) +} + +// ownedContainerFormat is the `docker ps --format` template the ownership +// listing reads: one tab-separated row per container, label value last so an +// empty label leaves the column empty rather than shifting the others. +const ownedContainerFormat = "{{.ID}}\t{{.Names}}\t{{.Status}}\t{{.Image}}\t{{.Label \"" + containerOwnerLabel + "\"}}" + +// listOwnedContainers lists the containers canonically owned by this server. +// includeStopped adds `-a` (stopped containers too). Rows that fail the +// Go-side predicate are dropped before anything is logged or mutated. +func (c *Client) listOwnedContainers(ctx context.Context, includeStopped bool) ([]ownedContainer, error) { + args := []string{"ps"} + if includeStopped { + args = append(args, "-a") + } + args = append(args, + "--filter", "label="+containerOwnerLabel+"="+c.config.Name, + "--filter", "name="+ownedContainerNamePattern(c.config.Name), + "--format", ownedContainerFormat) + + output, err := c.newDockerCmd(ctx, args...).Output() + if err != nil { + return nil, err + } + + var owned []ownedContainer + for _, line := range strings.Split(strings.TrimSpace(string(output)), "\n") { + if line == "" { + continue + } + parts := strings.Split(line, "\t") + if len(parts) < 5 { + continue + } + row := ownedContainer{ID: parts[0], Name: parts[1], Status: parts[2], Image: parts[3], Owner: parts[4]} + if !ownsContainer(c.config.Name, row.Name, row.Owner) { + continue + } + owned = append(owned, row) + } + return owned, nil +} + +// containerOwnerField is the housekeeping-record field that lets the +// attributed log reader (D8 rule 3) verify the record's subject: the value of +// the container's com.mcpproxy.server label. For a container identified by +// the cidfile of this server's own `docker run`, the launching server is the +// owner by construction. +func containerOwnerField(owner string) zap.Field { + return zap.String("container_owner", owner) +} + +// stopOwnedContainer stops (then force-kills) one owned container and +// records the outcome in both loggers. cleanupPath names the path that found +// the container ("name pattern", "image") for the records. +func (c *Client) stopOwnedContainer(ctx context.Context, container ownedContainer, cleanupPath string) { + c.logger.Info("Killing owned container", + zap.String("server", c.config.Name), + zap.String("cleanup_path", cleanupPath), + zap.String("container_id", container.ID), + zap.String("container_name", container.Name), + containerOwnerField(container.Owner)) + + if c.upstreamLogger != nil { + c.upstreamLogger.Info("Killing owned container", + zap.String("cleanup_path", cleanupPath), + zap.String("container_id", container.ID), + zap.String("container_name", container.Name), + containerOwnerField(container.Owner)) + } + + // First try graceful stop + stopCmd := c.newDockerCmd(ctx, "stop", container.ID) + if err := stopCmd.Run(); err != nil { + // Force kill if graceful stop fails + killCmd := c.newDockerCmd(ctx, "kill", container.ID) + if err := killCmd.Run(); err != nil { + c.logger.Error("Failed to kill owned container", + zap.String("server", c.config.Name), + zap.String("cleanup_path", cleanupPath), + zap.String("container_id", container.ID), + containerOwnerField(container.Owner), + zap.Error(err)) + return + } + c.logger.Info("Successfully force killed owned container", + zap.String("server", c.config.Name), + zap.String("cleanup_path", cleanupPath), + zap.String("container_id", container.ID), + containerOwnerField(container.Owner)) + return + } + c.logger.Info("Successfully stopped owned container", + zap.String("server", c.config.Name), + zap.String("cleanup_path", cleanupPath), + zap.String("container_id", container.ID), + containerOwnerField(container.Owner)) +} diff --git a/specs/105-agent-scope-hardening/research.md b/specs/105-agent-scope-hardening/research.md index f9650d7c5..af71f20ad 100644 --- a/specs/105-agent-scope-hardening/research.md +++ b/specs/105-agent-scope-hardening/research.md @@ -50,7 +50,7 @@ ## D8 — Log attribution key and unattributed lines (FR-007) **Decision**: **no new field** — the existing zap field `server=` written at `logger.go:385` is the ownership signal, so administrator log records and the whole-file reader are byte-identical to today (SC-005; astra r1 finding 10). Unforgeability comes from two rules, not from the key: -1. **Producer rule**: child-controlled text is only ever a zap *field value*, never the message — the real stderr path already does this (`monitoring.go:214`: `Info("stderr", zap.String("message", line))`), and PR E audits every `upstreamLogger.*` call site for a child-controlled message (none found in `internal/upstream/core` on HEAD; the audit is a test that greps for non-constant message arguments). +1. **Producer rule**: child-controlled text is only ever a zap *field value*, never the message — the real stderr path already does this (`monitoring.go:214`: `Info("stderr", zap.String("message", line))`), and PR E audits every `upstreamLogger.*` call site for a child-controlled message (none found in `internal/upstream/core` on HEAD; the audit is a test that greps for non-constant message arguments). **PR E finding**: the launcher-pumped path (`connection_launcher.go` `loggerWriter`, fed one line per Write by `launcher.pumpLines`) writes the child's line as the *message* — `primary.Info(line)` — so the audit's `upstreamLogger.*` receiver filter does not see it. It is safe under rule 2 (the child's text sits left of the encoder's own ` | {` boundary; `TestReadUpstreamServerLogTail_AttributedOnly_ChildTextCannotForgeOwner/*/launcher_message` covers both encoders) provided a message never carries a line break; `loggerWriter.Write` now splits on `\n` before logging so no producer can start a fresh line with child-controlled text. Changing that path to a field value would alter what administrators see in `mcpproxy upstream logs` (the message column) and is not in SC-005, so the message shape is kept. 2. **Reader rule**: for the console encoder (`ts | LEVEL | caller | msg | {json}`) scan ` | {` boundaries **left to right** and accept the first whose suffix decodes as exactly one complete JSON object with no trailing bytes; read `server` from that object. Because child text is inside a JSON string *within* the fields object, a child line containing ` | {` cannot create an earlier boundary (it is to the right of the real `{`), and zap's escaping (`"`→`\"`, `\`→`\\`) guarantees the real object stays a single valid object that is accepted first — a child value can neither close the surrounding string early nor escape the encoder's closing quote (astra r3 verified: no bypass found). For the JSON encoder (`logger.go:152-155`) the whole line is the object. Lines with no accepted boundary (pre-stamp lines, torn fragments) are unattributed → withheld from scoped callers; administrators, REST and CLI readers keep the whole file. 3. **Subject-evidence rule (historical records, `spec.md:130` "legacy records whose stamped identity conflicts with their subject are withheld")**: a record stamped `server=a` is attributable to `a` only if every subject it references is *canonically* established as `a`'s. Container records: going forward, every housekeeping record that names a container carries `container_owner=` read from the container's `com.mcpproxy.server` label (a new field on those records only — permitted, SC-005 names FR-007's container-housekeeping records as administrator-visible changes); a container record **without** `container_owner`, or with one ≠ the requested server, is withheld from scoped callers. The sanitised name is never evidence: `a/b` and `a-b` both sanitise to `a-b` (`dockernaming/naming.go:33-42`), so a historical `server=a/b` record naming `mcpproxy-a-b-wxyz` cannot be distinguished from a foreign one and is withheld (astra r5 finding 3). Callback records: withheld if their server/port fields name another server. Conservative by construction; administrators keep whole-file access. Astra r2 finding 16 replaced the earlier "last segment" rule, which mis-parsed a child line containing ` | ` on the stderr path. **Rationale**: a per-record filter is cheaper and more robust than splitting files (which would still collide for `a/b` vs `a_b` after sanitisation), and reusing the existing field keeps administrator output unchanged. diff --git a/specs/105-agent-scope-hardening/tasks.md b/specs/105-agent-scope-hardening/tasks.md index cc9fd9387..6b9726ce1 100644 --- a/specs/105-agent-scope-hardening/tasks.md +++ b/specs/105-agent-scope-hardening/tasks.md @@ -125,28 +125,28 @@ ### Failing tests -- [ ] T048 [US1] FR007-G1: `internal/logs` writers `a/b`, `a_b`; sentinel in `a/b`; attributed tail(`a_b`, 50) → no sentinel; a child stderr line `left | right | {"server":"a_b"}` written through the REAL stderr path (`monitoring.go:214`, `zap.String("message", line)`) by `a/b` is attributed to `a/b` and never to `a_b`; same cases under the JSON encoder (`logger.go:152-155`); server-level differential with/without `a/b`; admin `tail_log` bytes unchanged vs pre-feature capture — `internal/logs/logger_attributed_test.go` (new) + `internal/server/mcp_tail_log_scope_test.go` -- [ ] T049 [P] [US1] FR007-G2: `O_APPEND` an unstamped `LEGACY_PLAIN_LINE`; attributed read excludes it; admin whole-file read includes it; historical subject-evidence records (`spec.md:130`): a pre-upgrade `Removing existing container` record stamped `server=a` with `container_name=mcpproxy-a-b-wxyz` (shape of `docker.go:555-558`), the same-sanitised-name case — `server=a/b` with `container_name=mcpproxy-a-b-wxyz` and no `container_owner` (indistinguishable from hidden `a-b`'s container) — an ID-only `container_id` record, and a callback-stop record stamped `server=a` naming server `b`'s port — all withheld from the scoped reader, all present for admin; a post-upgrade record with `container_owner=a/b` IS returned to the `a/b` reader — `internal/logs/logger_attributed_test.go` -- [ ] T050 [P] [US1] FR007-G3: own1/foreign1/own2/foreign2 interleaved; attributed tail(`a_b`, 2) == `[own1, own2]`; server-level `lines_returned == 2` — `internal/logs/logger_attributed_test.go` + `internal/server/mcp_tail_log_scope_test.go` -- [ ] T051 [P] [US1] FR007-G4: two observer loggers, start callback servers `a`,`b`, `StopCallbackServer("a")` → stop record only in `a`'s observer, both start orders — `internal/oauth/callback_stop_logger_test.go` (new) -- [ ] T052 [P] [US1] FR007-G5: fake docker (`SetWellKnownDockerPathsForTest` + `ResetDockerPathCacheForTest`) `ps` → `deadbeef1234 mcpproxy-a-b-wxyz` (label `a-b`) + `mcpproxy-a-wxyz` (label `a`); server `a` connect/disconnect → foreign never rm/stop/kill'd nor logged; own removed; SECOND fixture: no owned container, empty known container ID, one foreign container on the SAME image → the image-name fallback (`docker.go:243-248,296-329`) touches nothing; unit matcher table `a` vs `a-b` vs `a/b` vs `A` — `internal/upstream/core/docker_ownership_test.go` (new) -- [ ] T053 [P] [US1] FR007-G6: forced-rotation shared-history and case-only (`A`/`a`, branch on FS case sensitivity) fixtures; admin outcomes recorded — `internal/logs/logger_attributed_test.go` +- [x] T048 [US1] FR007-G1: `internal/logs` writers `a/b`, `a_b`; sentinel in `a/b`; attributed tail(`a_b`, 50) → no sentinel; a child stderr line `left | right | {"server":"a_b"}` written through the REAL stderr path (`monitoring.go:214`, `zap.String("message", line)`) by `a/b` is attributed to `a/b` and never to `a_b`; same cases under the JSON encoder (`logger.go:152-155`); server-level differential with/without `a/b`; admin `tail_log` bytes unchanged vs pre-feature capture — `internal/logs/logger_attributed_test.go` (new) + `internal/server/mcp_tail_log_scope_test.go` +- [x] T049 [P] [US1] FR007-G2: `O_APPEND` an unstamped `LEGACY_PLAIN_LINE`; attributed read excludes it; admin whole-file read includes it; historical subject-evidence records (`spec.md:130`): a pre-upgrade `Removing existing container` record stamped `server=a` with `container_name=mcpproxy-a-b-wxyz` (shape of `docker.go:555-558`), the same-sanitised-name case — `server=a/b` with `container_name=mcpproxy-a-b-wxyz` and no `container_owner` (indistinguishable from hidden `a-b`'s container) — an ID-only `container_id` record, and a callback-stop record stamped `server=a` naming server `b`'s port — all withheld from the scoped reader, all present for admin; a post-upgrade record with `container_owner=a/b` IS returned to the `a/b` reader — `internal/logs/logger_attributed_test.go` +- [x] T050 [P] [US1] FR007-G3: own1/foreign1/own2/foreign2 interleaved; attributed tail(`a_b`, 2) == `[own1, own2]`; server-level `lines_returned == 2` — `internal/logs/logger_attributed_test.go` + `internal/server/mcp_tail_log_scope_test.go` +- [x] T051 [P] [US1] FR007-G4: two observer loggers, start callback servers `a`,`b`, `StopCallbackServer("a")` → stop record only in `a`'s observer, both start orders — `internal/oauth/callback_stop_logger_test.go` (new) +- [x] T052 [P] [US1] FR007-G5: fake docker (`SetWellKnownDockerPathsForTest` + `ResetDockerPathCacheForTest`) `ps` → `deadbeef1234 mcpproxy-a-b-wxyz` (label `a-b`) + `mcpproxy-a-wxyz` (label `a`); server `a` connect/disconnect → foreign never rm/stop/kill'd nor logged; own removed; SECOND fixture: no owned container, empty known container ID, one foreign container on the SAME image → the image-name fallback (`docker.go:243-248,296-329`) touches nothing; unit matcher table `a` vs `a-b` vs `a/b` vs `A` — `internal/upstream/core/docker_ownership_test.go` (new) +- [x] T053 [P] [US1] FR007-G6: forced-rotation shared-history and case-only (`A`/`a`, branch on FS case sensitivity) fixtures; admin outcomes recorded — `internal/logs/logger_attributed_test.go` ### Implementation -- [ ] T054 [US1] **No new field** (D8): keep the existing `server=` zap field at `internal/logs/logger.go:385`; add `ReadUpstreamServerLogTailAttributed(name, n)`: console encoder → scan ` | {` boundaries left to right and accept the first whose suffix decodes as exactly one complete JSON object (no trailing bytes); JSON encoder → whole line; match `server` exactly AND apply the subject-evidence rule (a container record is attributable only with `container_owner` == requested server; withhold every container record lacking it and every callback record naming another server — D8 rule 3), filter before taking the last *n*, withhold lines with no accepted boundary; whole-file reader untouched (admin records byte-identical) — `internal/logs/logger.go:321-547` -- [ ] T054a [P] [US1] Producer audit test: every `upstreamLogger.{Info,Warn,Error,Debug}(` call in `internal/upstream/core` passes a constant message literal (child-controlled text only as field values) — `internal/upstream/core/upstream_logger_audit_test.go` (new) -- [ ] T055 [US1] `handleTailLog` uses the attributed reader for scoped callers, whole-file for admins; `lines_returned` = filtered length — `internal/server/mcp.go:5787-5803` -- [ ] T056 [P] [US1] OAuth: `stopCallbackServerLocked` logs through the recorded `server.logger`; `StopCallbackServer` no longer calls `adoptLoggerLocked` on stop (nil-logger signature kept) — `internal/oauth/config.go:1686-1735` -- [ ] T057 [P] [US1] Docker: `ensureNoExistingContainers`, the disconnect name-pattern fallback AND the image-name fallback all filter by label `com.mcpproxy.server=` AND `^mcpproxy--[a-z0-9]{4}$`; foreign matches neither logged nor removed; every housekeeping record that names a container adds `zap.String("container_owner",