Skip to content

Commit c670a2c

Browse files
lpcoxlpcox
authored
Deduplicate startup logging in cmd/root.go via logger helpers (#3515)
~10 consecutive `log.Printf` + `logger.LogInfoMd`/`LogWarn` pairs in `internal/cmd/root.go` log identical startup messages to both stderr and structured loggers. Every message change must be applied in two places. ### Changes - **`internal/logger/startup.go`** — Add `StartupInfo` and `StartupWarn` that combine both calls: ```go logger.StartupInfo("Starting MCPG in ROUTED mode on %s", listenAddr) // replaces: // log.Printf("Starting MCPG in ROUTED mode on %s", listenAddr) // logger.LogInfoMd("startup", "Starting in ROUTED mode on %s", listenAddr) ``` - **`internal/cmd/root.go`** — Replace 11 duplicate pairs with single-line helper calls - **`internal/logger/startup_test.go`** — Tests verifying both helpers write to file and markdown loggers > [!WARNING] > > <details> > <summary>Firewall rules blocked me from connecting to one or more addresses (expand for details)</summary> > > #### I tried to connect to the following addresses, but was blocked by firewall rules: > > - `example.com` > - Triggering command: `/tmp/go-build175238182/b510/launcher.test /tmp/go-build175238182/b510/launcher.test -test.testlogfile=/tmp/go-build175238182/b510/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true ache/go/1.25.8/x-errorsas cgo_.o 64/bin/as -p vendor/golang.or-atomic -lang=go1.25 238182/b171/_x00-buildtags -p ity/connectivity-errorsas -trimpath x_amd64/compile -I /tmp/go-build175docker-cli-plugin-metadata -I x_amd64/compile` (dns block) > - Triggering command: `/tmp/go-build3857722332/b514/launcher.test /tmp/go-build3857722332/b514/launcher.test -test.testlogfile=/tmp/go-build3857722332/b514/testlog.txt -test.paniconexit0 -test.timeout=10m0s rtcf�� pkg/mod/google.golang.org/grpc@v1.80.0/binarylog-s tmain.go x_amd64/vet /x64=/_/GOROOT --local u/13/cc1 x_amd64/vet -o /tmp/go-build175-errorsas ettings.Ports}} x_amd64/vet -p go.opentelemetry--version -lang=go1.25 x_amd64/vet` (dns block) > - Triggering command: `/tmp/go-build516878933/b510/launcher.test /tmp/go-build516878933/b510/launcher.test -test.testlogfile=/tmp/go-build516878933/b510/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true 7722332/b559/tty.test -tests 7722332/b559/importcfg.link 8NDC/SRjZ7_MrzxIbash pkg/mod/go.opent/usr/bin/runc ache/go/1.25.8/x--root 97a/log.json U02 io.containerd.ru/run/containerd/io.containerd.runtime.v2.task/moby/83fdf3a250dfab704055af7b451aa/usr/bin/runc.original {{json .NetworkS--log-format che/go-build/ba/json by/197def118f828/opt/hostedtoolcache/go/1.25.8/x64/pkg/tool/linux_amd64/vet -importcfg x_amd64/vet runc` (dns block) > - `invalid-host-that-does-not-exist-12345.com` > - Triggering command: `/tmp/go-build175238182/b492/config.test /tmp/go-build175238182/b492/config.test -test.testlogfile=/tmp/go-build175238182/b492/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true ternal/fsapi/fil-p ternal/fsapi/polgoogle.golang.org/grpc/internal/stats x_amd64/asm cgo=false false -g&#34; &#34;-lpthread&#34; x_amd64/asm 2381�� 238182/b172/_pkg-p ache/go/1.25.8/xgoogle.golang.org/grpc/health/grpc_health_v1` (dns block) > - Triggering command: `/tmp/go-build3857722332/b496/config.test /tmp/go-build3857722332/b496/config.test -test.testlogfile=/tmp/go-build3857722332/b496/testlog.txt -test.paniconexit0 -test.timeout=10m0s -qui�� 4W2NdfqUv /tmp/go-build175238182/b318/ ache/go/1.25.8/x64/pkg/tool/linu-importcfg . -imultiarch x86_64-linux-gnu rtcfg -I o aw-mcpg/internal/config/rules/rules_test.go x_amd64/compile --gdwarf-5 --64 -o x_amd64/compile` (dns block) > - Triggering command: `/tmp/go-build516878933/b492/config.test /tmp/go-build516878933/b492/config.test -test.testlogfile=/tmp/go-build516878933/b492/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true /tmp/go-build3857722332/b001/_pk/run/containerd/io.containerd.runtime.v2.task/moby/1aae6b0541c71bash 576e049387694a82674f762305209147fde512f1ff55f4537e6 e-handler 576e049387694a82/usr/bin/chronyc` (dns block) > - `nonexistent.local` > - Triggering command: `/tmp/go-build175238182/b510/launcher.test /tmp/go-build175238182/b510/launcher.test -test.testlogfile=/tmp/go-build175238182/b510/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true ache/go/1.25.8/x-errorsas cgo_.o 64/bin/as -p vendor/golang.or-atomic -lang=go1.25 238182/b171/_x00-buildtags -p ity/connectivity-errorsas -trimpath x_amd64/compile -I /tmp/go-build175docker-cli-plugin-metadata -I x_amd64/compile` (dns block) > - Triggering command: `/tmp/go-build3857722332/b514/launcher.test /tmp/go-build3857722332/b514/launcher.test -test.testlogfile=/tmp/go-build3857722332/b514/testlog.txt -test.paniconexit0 -test.timeout=10m0s rtcf�� pkg/mod/google.golang.org/grpc@v1.80.0/binarylog-s tmain.go x_amd64/vet /x64=/_/GOROOT --local u/13/cc1 x_amd64/vet -o /tmp/go-build175-errorsas ettings.Ports}} x_amd64/vet -p go.opentelemetry--version -lang=go1.25 x_amd64/vet` (dns block) > - Triggering command: `/tmp/go-build516878933/b510/launcher.test /tmp/go-build516878933/b510/launcher.test -test.testlogfile=/tmp/go-build516878933/b510/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true 7722332/b559/tty.test -tests 7722332/b559/importcfg.link 8NDC/SRjZ7_MrzxIbash pkg/mod/go.opent/usr/bin/runc ache/go/1.25.8/x--root 97a/log.json U02 io.containerd.ru/run/containerd/io.containerd.runtime.v2.task/moby/83fdf3a250dfab704055af7b451aa/usr/bin/runc.original {{json .NetworkS--log-format che/go-build/ba/json by/197def118f828/opt/hostedtoolcache/go/1.25.8/x64/pkg/tool/linux_amd64/vet -importcfg x_amd64/vet runc` (dns block) > - `slow.example.com` > - Triggering command: `/tmp/go-build175238182/b510/launcher.test /tmp/go-build175238182/b510/launcher.test -test.testlogfile=/tmp/go-build175238182/b510/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true ache/go/1.25.8/x-errorsas cgo_.o 64/bin/as -p vendor/golang.or-atomic -lang=go1.25 238182/b171/_x00-buildtags -p ity/connectivity-errorsas -trimpath x_amd64/compile -I /tmp/go-build175docker-cli-plugin-metadata -I x_amd64/compile` (dns block) > - Triggering command: `/tmp/go-build3857722332/b514/launcher.test /tmp/go-build3857722332/b514/launcher.test -test.testlogfile=/tmp/go-build3857722332/b514/testlog.txt -test.paniconexit0 -test.timeout=10m0s rtcf�� pkg/mod/google.golang.org/grpc@v1.80.0/binarylog-s tmain.go x_amd64/vet /x64=/_/GOROOT --local u/13/cc1 x_amd64/vet -o /tmp/go-build175-errorsas ettings.Ports}} x_amd64/vet -p go.opentelemetry--version -lang=go1.25 x_amd64/vet` (dns block) > - Triggering command: `/tmp/go-build516878933/b510/launcher.test /tmp/go-build516878933/b510/launcher.test -test.testlogfile=/tmp/go-build516878933/b510/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true 7722332/b559/tty.test -tests 7722332/b559/importcfg.link 8NDC/SRjZ7_MrzxIbash pkg/mod/go.opent/usr/bin/runc ache/go/1.25.8/x--root 97a/log.json U02 io.containerd.ru/run/containerd/io.containerd.runtime.v2.task/moby/83fdf3a250dfab704055af7b451aa/usr/bin/runc.original {{json .NetworkS--log-format che/go-build/ba/json by/197def118f828/opt/hostedtoolcache/go/1.25.8/x64/pkg/tool/linux_amd64/vet -importcfg x_amd64/vet runc` (dns block) > - `this-host-does-not-exist-12345.com` > - Triggering command: `/tmp/go-build175238182/b519/mcp.test /tmp/go-build175238182/b519/mcp.test -test.testlogfile=/tmp/go-build175238182/b519/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true s/known/fieldmaskpb/field_mask.pb.go @v1.43.0/semconv/v1.37.0/doc.go x_amd64/compile --gdwarf-5 --64 -o x_amd64/compile 2381�� _.a 238182/b165/ x_amd64/vet --gdwarf-5 /v1.40.0 -o x_amd64/vet` (dns block) > - Triggering command: `/tmp/go-build3857722332/b523/mcp.test /tmp/go-build3857722332/b523/mcp.test -test.testlogfile=/tmp/go-build3857722332/b523/testlog.txt -test.paniconexit0 -test.timeout=10m0s -o /tmp/go-build175238182/b459/_pkg_.a -trimpath x_amd64/vet -p github.com/githu-qE -lang=go1.25 x_amd64/vet -ato�� g_.a -buildtags x_amd64/vet -errorsas ernal/logger -nilfunc x_amd64/vet` (dns block) > - Triggering command: `/tmp/go-build516878933/b519/mcp.test /tmp/go-build516878933/b519/mcp.test -test.testlogfile=/tmp/go-build516878933/b519/testlog.txt -test.paniconexit0 -test.timeout=10m0s -test.v=true (create|run) runtime-runc/mobjson` (dns block) > > If you need me to access, download, or install something from one of these locations, you can either: > > - Configure [Actions setup steps](https://gh.io/copilot/actions-setup-steps) to set up my environment, which run before the firewall is enabled > - Add the appropriate URLs or hosts to the custom allowlist in this repository's [Copilot coding agent settings](https://github.com/github/gh-aw-mcpg/settings/copilot/coding_agent) (admins only) > > </details>
2 parents aea3db6 + 477e7a8 commit c670a2c

File tree

3 files changed

+127
-28
lines changed

3 files changed

+127
-28
lines changed

‎internal/cmd/root.go‎

Lines changed: 14 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -153,8 +153,7 @@ func run(cmd *cobra.Command, args []string) error {
153153
logger.LogErrorMd("startup", "Environment validation failed: %s", result.Error())
154154
return fmt.Errorf("environment validation failed: %s", result.Error())
155155
}
156-
logger.LogInfoMd("startup", "Environment validation passed")
157-
log.Println("Environment validation passed")
156+
logger.StartupInfo("Environment validation passed")
158157
}
159158

160159
// Load configuration
@@ -210,13 +209,11 @@ func run(cmd *cobra.Command, args []string) error {
210209
if policyOverride != nil {
211210
cfg.GuardPolicy = policyOverride
212211
cfg.GuardPolicySource = policySource
213-
log.Printf("Guard policy override configured (source=%s)", policySource)
214-
logger.LogInfoMd("startup", "Guard policy override configured (source=%s)", policySource)
212+
logger.StartupInfo("Guard policy override configured (source=%s)", policySource)
215213
}
216214

217215
if envSinkServerIDs, exists := os.LookupEnv("MCP_GATEWAY_GUARDS_SINK_SERVER_IDS"); exists {
218-
log.Printf("MCP_GATEWAY_GUARDS_SINK_SERVER_IDS=%q", envSinkServerIDs)
219-
logger.LogInfoMd("startup", "MCP_GATEWAY_GUARDS_SINK_SERVER_IDS=%q", envSinkServerIDs)
216+
logger.StartupInfo("MCP_GATEWAY_GUARDS_SINK_SERVER_IDS=%q", envSinkServerIDs)
220217
}
221218

222219
resolvedSinkServerIDs, err := parseDIFCSinkServerIDs(difcSinkServerIDs)
@@ -225,15 +222,12 @@ func run(cmd *cobra.Command, args []string) error {
225222
}
226223
difc.SetSinkServerIDs(resolvedSinkServerIDs)
227224
if len(resolvedSinkServerIDs) == 0 {
228-
log.Println("Guards sink server ID logging enrichment disabled (no sink server IDs configured)")
229-
logger.LogInfoMd("startup", "Guards sink server ID logging enrichment disabled")
225+
logger.StartupInfo("Guards sink server ID logging enrichment disabled (no sink server IDs configured)")
230226
} else {
231-
log.Printf("Guards sink server IDs configured for JSONL tag enrichment: %v", resolvedSinkServerIDs)
232-
logger.LogInfoMd("startup", "Guards sink server IDs configured for JSONL tag enrichment: %v", resolvedSinkServerIDs)
227+
logger.StartupInfo("Guards sink server IDs configured for JSONL tag enrichment: %v", resolvedSinkServerIDs)
233228
for _, sinkServerID := range resolvedSinkServerIDs {
234229
if _, exists := cfg.Servers[sinkServerID]; !exists {
235-
log.Printf("Warning: guards sink server ID '%s' is not configured in mcpServers", sinkServerID)
236-
logger.LogWarn("startup", "Guards sink server ID '%s' is not configured in mcpServers", sinkServerID)
230+
logger.StartupWarn("Guards sink server ID '%s' is not configured in mcpServers", sinkServerID)
237231
}
238232
}
239233
}
@@ -285,8 +279,7 @@ func run(cmd *cobra.Command, args []string) error {
285279
return fmt.Errorf("failed to generate random API key: %w", err)
286280
}
287281
cfg.Gateway.APIKey = randomKey
288-
log.Printf("No API key configured — generated a temporary random API key for this session")
289-
logger.LogInfoMd("startup", "Generated temporary random API key (spec §7.3)")
282+
logger.StartupInfo("No API key configured — generated temporary random API key (spec §7.3)")
290283
}
291284

292285
// Apply tracing flags: CLI flags override config values.
@@ -318,8 +311,7 @@ func run(cmd *cobra.Command, args []string) error {
318311
}
319312
tracingProvider, err := tracing.InitProvider(ctx, tracingCfg)
320313
if err != nil {
321-
log.Printf("Warning: failed to initialize tracing provider: %v", err)
322-
logger.LogWarn("startup", "Failed to initialize tracing provider: %v", err)
314+
logger.StartupWarn("Failed to initialize tracing provider: %v", err)
323315
// Non-fatal: continue without tracing
324316
tracingProvider, _ = tracing.InitProvider(ctx, nil)
325317
}
@@ -346,12 +338,10 @@ func run(cmd *cobra.Command, args []string) error {
346338
serviceName = tracingCfg.ServiceName
347339
}
348340
if endpoint != "" {
349-
log.Printf("OpenTelemetry tracing enabled: endpoint=%s, service=%s, sampleRate=%.2f",
341+
logger.StartupInfo("OpenTelemetry tracing enabled: endpoint=%s, service=%s, sampleRate=%.2f",
350342
endpoint, serviceName, sampleRate)
351-
logger.LogInfoMd("startup", "OpenTelemetry tracing enabled: endpoint=%s, service=%s",
352-
endpoint, serviceName)
353343
} else {
354-
log.Printf("OpenTelemetry tracing disabled (no OTLP endpoint configured)")
344+
logger.StartupInfo("OpenTelemetry tracing disabled (no OTLP endpoint configured)")
355345
}
356346
}
357347

@@ -373,20 +363,16 @@ func run(cmd *cobra.Command, args []string) error {
373363
// Create HTTP server based on mode
374364
var httpServer *http.Server
375365
if mode == "routed" {
376-
log.Printf("Starting MCPG in ROUTED mode on %s", listenAddr)
377-
log.Printf("Routes: /mcp/<server> where <server> is one of: %v", unifiedServer.GetServerIDs())
378-
logger.LogInfoMd("startup", "Starting in ROUTED mode on %s", listenAddr)
379-
logger.LogInfoMd("startup", "Routes: /mcp/<server> for servers: %v", unifiedServer.GetServerIDs())
366+
logger.StartupInfo("Starting MCPG in ROUTED mode on %s", listenAddr)
367+
logger.StartupInfo("Routes: /mcp/<server> where <server> is one of: %v", unifiedServer.GetServerIDs())
380368

381369
// Extract API key from gateway config (spec 7.1)
382370
apiKey := cfg.GetAPIKey()
383371

384372
httpServer = server.CreateHTTPServerForRoutedMode(listenAddr, unifiedServer, apiKey)
385373
} else {
386-
log.Printf("Starting MCPG in UNIFIED mode on %s", listenAddr)
387-
log.Printf("Endpoint: /mcp")
388-
logger.LogInfoMd("startup", "Starting in UNIFIED mode on %s", listenAddr)
389-
logger.LogInfoMd("startup", "Endpoint: /mcp")
374+
logger.StartupInfo("Starting MCPG in UNIFIED mode on %s", listenAddr)
375+
logger.StartupInfo("Endpoint: /mcp")
390376

391377
// Extract API key from gateway config (spec 7.1)
392378
apiKey := cfg.GetAPIKey()

‎internal/logger/startup.go‎

Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,20 @@
1+
package logger
2+
3+
import "log"
4+
5+
// StartupInfo logs a startup informational message to stderr (via log.Printf)
6+
// and to the startup markdown/file log sink (via LogInfoMd with "startup" category).
7+
// This eliminates the need to call log.Printf and LogInfoMd separately for the same message.
8+
func StartupInfo(format string, args ...interface{}) {
9+
log.Printf(format, args...)
10+
LogInfoMd("startup", format, args...)
11+
}
12+
13+
// StartupWarn logs a startup warning message to stderr (via log.Printf with
14+
// "Warning: " prefix) and to the startup warning log sink (via LogWarn with
15+
// "startup" category).
16+
// This eliminates the need to call log.Printf and LogWarn separately for the same message.
17+
func StartupWarn(format string, args ...interface{}) {
18+
log.Printf("Warning: "+format, args...)
19+
LogWarn("startup", format, args...)
20+
}

‎internal/logger/startup_test.go‎

Lines changed: 93 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,93 @@
1+
package logger
2+
3+
import (
4+
"os"
5+
"path/filepath"
6+
"testing"
7+
8+
"github.com/stretchr/testify/assert"
9+
"github.com/stretchr/testify/require"
10+
)
11+
12+
// TestStartupInfo verifies that StartupInfo writes to both the file logger and markdown logger.
13+
func TestStartupInfo(t *testing.T) {
14+
tmpDir := t.TempDir()
15+
logDir := filepath.Join(tmpDir, "logs")
16+
17+
err := InitFileLogger(logDir, "test.log")
18+
require.NoError(t, err)
19+
defer CloseGlobalLogger()
20+
21+
err = InitMarkdownLogger(logDir, "test.md")
22+
require.NoError(t, err)
23+
defer CloseMarkdownLogger()
24+
25+
StartupInfo("Server started on %s", "localhost:3000")
26+
27+
CloseMarkdownLogger()
28+
CloseGlobalLogger()
29+
30+
// Verify file logger received the message
31+
logPath := filepath.Join(logDir, "test.log")
32+
content, err := os.ReadFile(logPath)
33+
require.NoError(t, err)
34+
35+
logContent := string(content)
36+
assert.Contains(t, logContent, "[INFO]")
37+
assert.Contains(t, logContent, "[startup]")
38+
assert.Contains(t, logContent, "Server started on localhost:3000")
39+
40+
// Verify markdown logger received the message
41+
mdPath := filepath.Join(logDir, "test.md")
42+
mdContent, err := os.ReadFile(mdPath)
43+
require.NoError(t, err)
44+
45+
mdLog := string(mdContent)
46+
assert.Contains(t, mdLog, "Server started on localhost:3000")
47+
}
48+
49+
// TestStartupWarn verifies that StartupWarn writes to the file logger with WARN level.
50+
func TestStartupWarn(t *testing.T) {
51+
tmpDir := t.TempDir()
52+
logDir := filepath.Join(tmpDir, "logs")
53+
54+
err := InitFileLogger(logDir, "test.log")
55+
require.NoError(t, err)
56+
defer CloseGlobalLogger()
57+
58+
StartupWarn("tracing provider failed: %v", "connection refused")
59+
60+
CloseGlobalLogger()
61+
62+
// Verify file logger received the message with WARN level
63+
logPath := filepath.Join(logDir, "test.log")
64+
content, err := os.ReadFile(logPath)
65+
require.NoError(t, err)
66+
67+
logContent := string(content)
68+
assert.Contains(t, logContent, "[WARN]")
69+
assert.Contains(t, logContent, "[startup]")
70+
assert.Contains(t, logContent, "tracing provider failed: connection refused")
71+
}
72+
73+
// TestStartupInfoWithoutFormatArgs verifies StartupInfo works with plain strings.
74+
func TestStartupInfoWithoutFormatArgs(t *testing.T) {
75+
tmpDir := t.TempDir()
76+
logDir := filepath.Join(tmpDir, "logs")
77+
78+
err := InitFileLogger(logDir, "test.log")
79+
require.NoError(t, err)
80+
defer CloseGlobalLogger()
81+
82+
StartupInfo("Environment validation passed")
83+
84+
CloseGlobalLogger()
85+
86+
logPath := filepath.Join(logDir, "test.log")
87+
content, err := os.ReadFile(logPath)
88+
require.NoError(t, err)
89+
90+
logContent := string(content)
91+
assert.Contains(t, logContent, "[INFO]")
92+
assert.Contains(t, logContent, "Environment validation passed")
93+
}

0 commit comments

Comments
 (0)