Consolidate dual logging in server package to internal logger#3510
Consolidate dual logging in server package to internal logger#3510
Conversation
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>
There was a problem hiding this comment.
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
logusage inunified.goandtool_registry.go, favoringlogUnified/logger.*. - Replaced
[DIFC] ...log.Printfstatements incallBackendToolandguardBackendCallerwithlogUnified.Printf. - Updated tool registration logging to avoid dual logging and removed unused
logimports.
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
| // 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)") | ||
| } |
There was a problem hiding this comment.
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)")
| 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") | ||
| } |
There was a problem hiding this comment.
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")
| // 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) |
There was a problem hiding this comment.
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 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>
Applied the review feedback in 0f9a06e:
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:
If you need me to access, download, or install something from one of these locations, you can either:
|
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 ✅
tool_registry.goandunified.gohad 20+log.Printf/log.Printlncalls that either duplicated adjacentlogUnified.Printf/logger.LogXxxcalls 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
log.*calls adjacent to equivalentlogUnified/logger.LogXxxcalls (e.g., shutdown sequence, parallel registration results)log.*calls with appropriate always-on or debug-gated loggers:logger.LogInfo("startup"/"backend", ...)so they remain visible in default (non-debug) runslogger.LogWarn("difc", ...)for always-on auditabilitylogUnified.Printf(DEBUG-gated)"log"import from both filesBefore:
After:
The inline
sdk.CallToolResult{IsError:true}pattern (sub-issue #3492) is already consolidated via the existingnewErrorCallToolResult()helper — no production code instances remain.