Skip to content

Consolidate dual logging in server package to internal logger#3510

Merged
lpcox merged 5 commits intomainfrom
copilot/duplicate-code-analysis-report
Apr 10, 2026
Merged

Consolidate dual logging in server package to internal logger#3510
lpcox merged 5 commits intomainfrom
copilot/duplicate-code-analysis-report

Conversation

Copy link
Copy Markdown
Contributor

Copilot AI commented Apr 10, 2026

tool_registry.go and unified.go had 20+ log.Printf/log.Println calls that either duplicated adjacent logUnified.Printf/logger.LogXxx calls or bypassed the internal logger entirely. This means log-format changes must be made in two places and bug fixes may only apply to one logger.

Changes

  • Remove duplicate log.* calls adjacent to equivalent logUnified/logger.LogXxx calls (e.g., shutdown sequence, parallel registration results)
  • Replace standalone log.* calls with appropriate always-on or debug-gated loggers:
    • Operational/lifecycle messages (DIFC enable/disable status, server start, tool registration progress) → logger.LogInfo("startup"/"backend", ...) so they remain visible in default (non-debug) runs
    • Security/audit events (DIFC access denials, guard/response labeling failures, strict-mode blocks) → logger.LogWarn("difc", ...) for always-on auditability
    • Verbose debug traces (agent labels, resource details, filtering counts) → logUnified.Printf (DEBUG-gated)
  • Remove unused "log" import from both files

Before:

log.Printf("Calling tool on %s: %s with DIFC enforcement", serverID, toolName)
logUnified.Printf("callBackendTool: serverID=%s, toolName=%s, args=%+v", serverID, toolName, args)

After:

logUnified.Printf("callBackendTool: serverID=%s, toolName=%s, args=%+v", serverID, toolName, args)

The inline sdk.CallToolResult{IsError:true} pattern (sub-issue #3492) is already consolidated via the existing newErrorCallToolResult() helper — no production code instances remain.

Copilot AI linked an issue Apr 10, 2026 that may be closed by this pull request
@lpcox lpcox marked this pull request as ready for review April 10, 2026 15:20
Copilot AI review requested due to automatic review settings April 10, 2026 15:20
Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

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

Copilot wasn't able to review any files in this pull request.

Replace all `log.Printf`/`log.Println` calls in `tool_registry.go` and
`unified.go` with the internal `logUnified.Printf` or `logger.LogXxx`
equivalents. Remove the now-unused `"log"` import from both files.

This addresses three duplication patterns:
1. Dual logging where the same event was logged via both `log` and
   `logger`/`logUnified` (removed the `log` call, kept the internal one)
2. DIFC `log.Printf("[DIFC] ...")` calls replaced with `logUnified.Printf`
3. Inline `sdk.CallToolResult{IsError:true}` already addressed by the
   existing `newErrorCallToolResult()` helper — no production code changes
   needed.

Fixes #3490
Fixes #3491
Fixes #3492
Fixes #3493

Agent-Logs-Url: https://github.com/github/gh-aw-mcpg/sessions/0cf06e20-b724-4d08-b16e-db64bb3df5e4

Co-authored-by: lpcox <15877973+lpcox@users.noreply.github.com>
@lpcox lpcox requested a review from Copilot April 10, 2026 15:23
Copilot AI changed the title [WIP] Fix duplicate code patterns in logging implementation Consolidate dual logging in server package to internal logger Apr 10, 2026
Copilot AI requested a review from lpcox April 10, 2026 15:24
Copy link
Copy Markdown
Contributor

Copilot AI left a comment

Choose a reason for hiding this comment

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

Pull request overview

This PR refactors server logging to remove duplicated log.Printf/log.Println calls and consolidate output onto the unified logging utilities, especially around DIFC enforcement and tool registration.

Changes:

  • Removed standard-library log usage in unified.go and tool_registry.go, favoring logUnified / logger.*.
  • Replaced [DIFC] ... log.Printf statements in callBackendTool and guardBackendCaller with logUnified.Printf.
  • Updated tool registration logging to avoid dual logging and removed unused log imports.
Show a summary per file
File Description
internal/server/unified.go Replaces stdlib log calls with logUnified for DIFC and lifecycle logging; removes log import.
internal/server/tool_registry.go Removes stdlib log calls/import; uses logUnified and logger.LogWarn* during tool registration.

Copilot's findings

Tip

Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comments suppressed due to low confidence (2)

internal/server/unified.go:645

  • This startup message now uses logUnified, which is disabled unless DEBUG enables the "server:unified" namespace. If this line is intended to be an operator-visible lifecycle log (previously log.Println), consider switching to logger.LogInfo (or similar) so the message is emitted by default.
func (us *UnifiedServer) Run(transport sdk.Transport) error {
	logUnified.Printf("Starting unified MCP server...")
	return us.server.Run(us.ctx, transport)

internal/server/tool_registry.go:143

  • This tool registration summary was changed from log.Printf (always emitted) to logUnified (DEBUG-gated). If the success/failure counts are important in normal operation, consider logging the summary via logger.LogInfo (and optionally keeping a debug log via logUnified as well).

	logUnified.Printf("Tool registration complete: %d succeeded, %d failed, total tools=%d", successCount, failureCount, len(us.tools))
	return nil
  • Files reviewed: 2/2 changed files
  • Comments generated: 3

Comment on lines 184 to 189
// Log guards status early (before backend launch which may take time)
if us.enableDIFC {
log.Printf("Guards enforcement enabled with mode: %s", cfg.DIFCMode)
logUnified.Printf("Guards enforcement enabled with mode: %s", cfg.DIFCMode)
} else {
log.Println("Guards enforcement disabled (sessions auto-created for standard MCP client compatibility)")
logUnified.Printf("Guards enforcement disabled (sessions auto-created for standard MCP client compatibility)")
}
Copy link

Copilot AI Apr 10, 2026

Choose a reason for hiding this comment

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

These DIFC enforcement status messages were switched from the standard library logger (always emitted) to logUnified (a DEBUG-gated logger). Since logger.New() only prints when the DEBUG env enables the namespace, this can make DIFC enable/disable status invisible in default runs. Consider logging this with logger.LogInfo (or another always-on logger) and reserving logUnified for verbose debug details.

This issue also appears on line 643 of the same file.

See below for a potential fix:

		logger.LogInfo("Auto-enabled DIFC: non-noop guard, global policy, or per-server guard policies detected")
	}

	// Log guards status early (before backend launch which may take time)
	if us.enableDIFC {
		logger.LogInfo("Guards enforcement enabled with mode: %s", cfg.DIFCMode)
	} else {
		logger.LogInfo("Guards enforcement disabled (sessions auto-created for standard MCP client compatibility)")

Copilot uses AI. Check for mistakes.
Comment on lines 58 to 70
func (us *UnifiedServer) registerAllTools() error {
log.Println("Registering tools from all backends...")
logUnified.Printf("Starting tool registration for %d backends", len(us.launcher.ServerIDs()))

// Only register sys tools if DIFC is enabled
// When DIFC is disabled (default), sys tools are not needed
if us.enableDIFC {
log.Println("DIFC enabled: registering sys tools...")
logUnified.Printf("DIFC enabled: registering sys tools...")
if err := us.registerSysTools(); err != nil {
log.Printf("Warning: failed to register sys tools: %v", err)
logger.LogWarn("backend", "Failed to register sys tools: %v", err)
}
} else {
log.Println("DIFC disabled: skipping sys tools registration")
logUnified.Printf("DIFC disabled: skipping sys tools registration")
}
Copy link

Copilot AI Apr 10, 2026

Choose a reason for hiding this comment

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

Tool registration lifecycle logging was changed from log.Println (always emitted) to logUnified (DEBUG-gated). If these messages are meant to help operators understand startup progress in non-debug runs, consider using logger.LogInfo for the start/skip messages and keeping logUnified for detailed per-tool debugging.

This issue also appears on line 141 of the same file.

See below for a potential fix:

	logger.LogInfo("backend", "Starting tool registration for %d backends", len(us.launcher.ServerIDs()))

	// Only register sys tools if DIFC is enabled
	// When DIFC is disabled (default), sys tools are not needed
	if us.enableDIFC {
		logger.LogInfo("backend", "DIFC enabled: registering sys tools...")
		if err := us.registerSysTools(); err != nil {
			logger.LogWarn("backend", "Failed to register sys tools: %v", err)
		}
	} else {
		logger.LogInfo("backend", "DIFC disabled: skipping sys tools registration")

Copilot uses AI. Check for mistakes.
Comment on lines 510 to 514
// Non-read operation - block the request
log.Printf("[DIFC] Access DENIED for agent %s to %s: %s", agentID, resource.Description, result.Reason)
logUnified.Printf("[DIFC] Access DENIED for agent %s to %s: %s", agentID, resource.Description, result.Reason)
detailedErr := difc.FormatViolationError(result, agentLabels.Secrecy, agentLabels.Integrity, resource)
toolSpan.RecordError(detailedErr)
toolSpan.SetStatus(codes.Error, "access denied: "+result.Reason)
Copy link

Copilot AI Apr 10, 2026

Choose a reason for hiding this comment

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

The DIFC access-denied event is now logged via logUnified, which is DEBUG-gated. If DEBUG is not enabled, denied operations (and their reasons) may no longer be recorded anywhere, which reduces auditability/operational visibility for policy enforcement. Consider logging access denials with an always-on warning/error logger (e.g., logger.LogWarn/LogError under a "difc" category, ideally including serverID/toolName) and reserving logUnified for verbose traces.

Copilot uses AI. Check for mistakes.
@lpcox
Copy link
Copy Markdown
Collaborator

lpcox commented Apr 10, 2026

@copilot apply changes based on the comments in this thread

Promote DEBUG-gated logUnified.Printf calls to always-on loggers where
the messages are operationally important or security-relevant:

- logger.LogInfo("startup", ...) for DIFC enable/disable status and
  server start messages
- logger.LogInfo("backend", ...) for tool registration lifecycle
- logger.LogWarn("difc", ...) for DIFC access denials, guard labeling
  failures, response labeling failures, and strict-mode blocks

Keep logUnified.Printf for verbose debug traces (agent labels, resource
details, filtering counts, etc.).

Agent-Logs-Url: https://github.com/github/gh-aw-mcpg/sessions/1dd01357-8468-43c0-a1a8-f79af584b3fa

Co-authored-by: lpcox <15877973+lpcox@users.noreply.github.com>
Copy link
Copy Markdown
Contributor Author

Copilot AI commented Apr 10, 2026

@copilot apply changes based on the comments in this thread

Applied the review feedback in 0f9a06e:

  • DIFC enable/disable status and server start messages → logger.LogInfo("startup", ...) (always-on)
  • Tool registration lifecycle messages → logger.LogInfo("backend", ...) (always-on)
  • DIFC access denials, guard/response labeling failures, and strict-mode blocks → logger.LogWarn("difc", ...) (always-on)
  • Verbose debug traces (agent labels, resource details, filtering counts) remain as logUnified.Printf

Warning

Firewall rules blocked me from connecting to one or more addresses (expand for details)

I tried to connect to the following addresses, but was blocked by firewall rules:

  • example.com
    • Triggering command: /tmp/go-build1619308574/b510/launcher.test /tmp/go-build1619308574/b510/launcher.test -test.testlogfile=/tmp/go-build1619308574/b510/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true uG_pcmOLn .cfg x_amd64/vet --gdwarf-5 --64 -o x_amd64/vet -o om/stretchr/testify@v1.11.1/assert/yaml/yaml_def-errorsas qaJP/faPO1YLymyAXM2GrqaJP x_amd64/vet o g/protobuf/types/usr/bin/runc -lang=go1.24 x_amd64/vet (dns block)
  • invalid-host-that-does-not-exist-12345.com
    • Triggering command: /tmp/go-build1619308574/b492/config.test /tmp/go-build1619308574/b492/config.test -test.testlogfile=/tmp/go-build1619308574/b492/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true g_.a bshGWuxII x_amd64/vet /tmp/go-build339/opt/hostedtoolcache/go/1.25.8/x64/pkg/tool/linux_amd64/vet .io/otel/codes -fno-stack-protector x_amd64/vet ortc�� ache/go/1.25.8/x64/src/os/user .cfg 64/pkg/tool/linux_amd64/vet . --gdwarf2 --64 64/pkg/tool/linux_amd64/vet (dns block)
  • nonexistent.local
    • Triggering command: /tmp/go-build1619308574/b510/launcher.test /tmp/go-build1619308574/b510/launcher.test -test.testlogfile=/tmp/go-build1619308574/b510/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true uG_pcmOLn .cfg x_amd64/vet --gdwarf-5 --64 -o x_amd64/vet -o om/stretchr/testify@v1.11.1/assert/yaml/yaml_def-errorsas qaJP/faPO1YLymyAXM2GrqaJP x_amd64/vet o g/protobuf/types/usr/bin/runc -lang=go1.24 x_amd64/vet (dns block)
  • slow.example.com
    • Triggering command: /tmp/go-build1619308574/b510/launcher.test /tmp/go-build1619308574/b510/launcher.test -test.testlogfile=/tmp/go-build1619308574/b510/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true uG_pcmOLn .cfg x_amd64/vet --gdwarf-5 --64 -o x_amd64/vet -o om/stretchr/testify@v1.11.1/assert/yaml/yaml_def-errorsas qaJP/faPO1YLymyAXM2GrqaJP x_amd64/vet o g/protobuf/types/usr/bin/runc -lang=go1.24 x_amd64/vet (dns block)
  • this-host-does-not-exist-12345.com
    • Triggering command: /tmp/go-build1619308574/b519/mcp.test /tmp/go-build1619308574/b519/mcp.test -test.testlogfile=/tmp/go-build1619308574/b519/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true lete: awmg&#34; /tmp/go-build3399349798/b286/ x_amd64/vet . -imultiarch x86_64-linux-gnu x_amd64/vet (dns block)

If you need me to access, download, or install something from one of these locations, you can either:

Copilot AI and others added 2 commits April 10, 2026 16:07
When an HTTP backend connection fails (e.g., 401 auth errors), log the
error to stderr via log.Printf so operators can see the reason. The error
chain includes the backend response body with specific messages like
"Missing API key" or "Invalid API key". This fixes TestTavilyAuthFailure
integration tests which check stderr for these error messages.

Agent-Logs-Url: https://github.com/github/gh-aw-mcpg/sessions/40888e44-12ac-4b0d-b93b-083f02fe9a52

Co-authored-by: lpcox <15877973+lpcox@users.noreply.github.com>
)

## Summary

Fixes the failing `TestTavilyAuthFailure` integration tests by ensuring
HTTP backend connection errors are logged to stderr.

## Problem

The `TestTavilyAuthFailure/MissingAPIKey` and
`TestTavilyAuthFailure/InvalidAPIKey` integration tests were failing
because the gateway's HTTP connection errors (including auth failures
like 401 responses) were only logged to the file logger
(`logger.LogErrorWithServer`), not to stderr. The tests check stderr for
error messages from the backend (e.g., "Missing API key", "Invalid API
key").

## Fix

Added a `log.Printf` call in `internal/launcher/launcher.go` when an
HTTP backend connection fails. This logs the error to stderr, making the
backend's error response body (which includes specific messages like
"Missing API key") visible in the console output. The error was already
being logged to the file logger; this adds stderr output for operator
visibility.

## Changes

- `internal/launcher/launcher.go`: Added `log.Printf` for HTTP
connection failure errors, consistent with other operational
`log.Printf` calls in the launcher (e.g., container detection, health
restarts).

## Testing

- `TestTavilyAuthFailure/MissingAPIKey` ✅
- `TestTavilyAuthFailure/InvalidAPIKey` ✅
- All launcher unit tests ✅
- All unit tests ✅
@lpcox lpcox merged commit 66398ee into main Apr 10, 2026
10 of 11 checks passed
@lpcox lpcox deleted the copilot/duplicate-code-analysis-report branch April 10, 2026 16:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[duplicate-code] Duplicate Code Analysis Report

3 participants