-
Notifications
You must be signed in to change notification settings - Fork 1
fix(logging): Access logs output multiline JSON instead of single condensed line #207
Description
Problem
Issue #194 implemented condensed access log format, but in production (journald/systemd) logs appear multiline instead of single-line:
Jan 25 06:10:33 gitlab-mcp.sw.foundation node[38111]: [06:10:33.989] INFO (gitlab-mcp): [2026-01-25T04:10:33.989Z] 192.168.95.254 d57319d3.. - - GET / 400 2ms | - - | - - | -
Jan 25 06:10:33 gitlab-mcp.sw.foundation node[38111]: accessLog: {
Jan 25 06:10:33 gitlab-mcp.sw.foundation node[38111]: "timestamp": "2026-01-25T04:10:33.989Z",
Jan 25 06:10:33 gitlab-mcp.sw.foundation node[38111]: "clientIp": "192.168.95.254",
Jan 25 06:10:33 gitlab-mcp.sw.foundation node[38111]: "session": "d57319d3..",
...
Jan 25 06:10:33 gitlab-mcp.sw.foundation node[38111]: }
Expected:
Jan 25 06:10:33 gitlab-mcp.sw.foundation gitlab-mcp[38111]: 192.168.95.254 d57319d3.. - - GET / 400 2ms | - - | - - | -
Root Cause
In src/logging/request-tracker.ts:257:
logger.info({ accessLog: entry }, logLine);pino-pretty outputs:
- The formatted message (
logLine) - Then the structured object (
accessLog) as pretty-printed multiline JSON
Issues
- Multiline output -
pino-prettypretty-prints theaccessLogobject after the message - Duplicate timestamp -
[2026-01-25T04:10:33.989Z]in message is redundant (journald/pino already adds timestamp) - Duplicate data - Same info appears in message AND in
accessLogobject
Solution: Two Mutually Exclusive Log Modes
Implement clean separation between human-readable and machine-parseable log formats.
Environment Variable
| Variable | Default | Description |
|---|---|---|
LOG_JSON |
false |
Enable full JSON log output for log aggregators |
Mode: Plain Text (default, LOG_JSON=false)
Human-readable single-line format for journald/systemd/console:
[06:10:33.989] INFO: 192.168.95.254 d57319d3.. - - GET / 400 2ms | - - | - - | -
[06:10:34.181] INFO: Session created sessionId=2aea1f2b activeSessions=5
[06:10:34.500] INFO: Tool executed tool=browse_projects action=list duration=45ms
Characteristics:
- Uses
pino-prettytransport - Single line per log entry
- No JSON objects in output
- Timestamp from pino prefix only (no duplicate in message)
- Key=value format for structured fields in message
Mode: JSON (LOG_JSON=true)
Full JSON output for log aggregators (Loki, ELK, Datadog, etc.):
{"level":30,"time":1737781833989,"name":"gitlab-mcp","msg":"192.168.95.254 d57319d3.. - - GET / 400 2ms | - - | - - | -","accessLog":{"clientIp":"192.168.95.254","session":"d57319d3..","method":"GET","path":"/","status":400,"durationMs":2,"tool":null,"action":null}}
{"level":30,"time":1737781834181,"name":"gitlab-mcp","msg":"Session created","sessionId":"2aea1f2b-21dc-41de-934c-f57ee3173f79","activeSessions":5}
{"level":30,"time":1737781834500,"name":"gitlab-mcp","msg":"Tool executed","tool":"browse_projects","action":"list","durationMs":45}Characteristics:
- No
pino-prettytransport (raw pino JSON) - One JSON object per line (NDJSON)
- All structured data preserved as fields
- Machine-parseable for log aggregators
- Full
accessLogobject included for access log entries
Implementation
1. Update src/logger.ts
import { pino, type LoggerOptions } from "pino";
const isTestEnv = process.env.NODE_ENV === "test" || process.env.JEST_WORKER_ID !== undefined;
const isJsonMode = process.env.LOG_JSON === "true";
export const createLogger = (name?: string) => {
const options: LoggerOptions = {
name,
level: process.env.LOG_LEVEL ?? "info",
};
// JSON mode: raw pino output (no pretty printing)
// Plain mode: pino-pretty for human-readable output
// Test mode: skip transport to avoid Jest worker thread leak
if (!isTestEnv && !isJsonMode) {
options.transport = {
target: "pino-pretty",
options: {
colorize: true,
translateTime: true,
ignore: "pid,hostname",
destination: 2,
},
};
}
return pino(options);
};
export const logger = createLogger("gitlab-mcp");
// Export for conditional logging
export const LOG_JSON = isJsonMode;2. Update src/logging/request-tracker.ts
import { logger, LOG_JSON } from "../logger.js";
// In closeStack():
if (LOG_JSON) {
// JSON mode: include full structured accessLog object
logger.info({ accessLog: entry }, logLine);
} else {
// Plain mode: message only, no object (prevents multiline output)
logger.info(logLine);
}3. Update src/logging/access-log.ts
Remove timestamp from formatAccessLog() - pino already adds it:
// Before:
// [2026-01-25T04:10:33.989Z] 192.168.95.254 d57319d3.. ...
// After:
// 192.168.95.254 d57319d3.. - - GET / 400 2ms | - - | - - | -4. Update other log calls
Ensure all log calls follow the pattern:
- Plain mode:
logger.info("Message with key=value pairs") - JSON mode:
logger.info({ field: value }, "Message")
For structured data in plain mode, format as key=value in message:
// Instead of:
logger.info({ sessionId, activeSessions }, "Session created");
// Use:
if (LOG_JSON) {
logger.info({ sessionId, activeSessions }, "Session created");
} else {
logger.info(`Session created sessionId=${sessionId} activeSessions=${activeSessions}`);
}Or create a helper:
export function logInfo(message: string, data?: Record<string, unknown>): void {
if (LOG_JSON) {
logger.info(data ?? {}, message);
} else if (data) {
const pairs = Object.entries(data).map(([k, v]) => `${k}=${v}`).join(" ");
logger.info(`${message} ${pairs}`);
} else {
logger.info(message);
}
}Documentation
Add to docs/guide/configuration.md:
Logging Configuration
| Variable | Default | Description |
|---|---|---|
LOG_LEVEL |
info |
Log level: debug, info, warn, error |
LOG_JSON |
false |
Output logs as JSON (for log aggregators) |
Plain Text Mode (default)
Human-readable single-line format suitable for journald, systemd, and console viewing:
# Default - no configuration needed
gitlab-mcpOutput:
[12:34:56.789] INFO: 192.168.1.100 abc123.. mygroup/proj - POST /mcp 200 142ms | browse_projects list | GL:200 98ms | items=15
[12:34:57.123] INFO: Session created sessionId=abc12345 activeSessions=3
JSON Mode
Full JSON output for log aggregation systems (Loki, Elasticsearch, Datadog):
LOG_JSON=true gitlab-mcpOutput:
{"level":30,"time":1737781833989,"name":"gitlab-mcp","msg":"...","accessLog":{...}}Each line is a valid JSON object (NDJSON format), suitable for ingestion by log aggregators.
Docker example:
docker run -e LOG_JSON=true -e GITLAB_TOKEN=xxx ghcr.io/structured-world/gitlab-mcp:latestsystemd example:
[Service]
Environment="LOG_JSON=true"
Environment="GITLAB_TOKEN=xxx"
ExecStart=/usr/bin/node /opt/gitlab-mcp/dist/server.jsAcceptance Criteria
-
LOG_JSON=false(default): All logs as single-line plain text -
LOG_JSON=true: All logs as single-line JSON (NDJSON) - No multiline output in either mode
- Timestamp removed from access log message (already in pino prefix)
- Structured
accessLogobject only in JSON mode - Other structured fields formatted as key=value in plain mode
- Documentation updated in
docs/guide/configuration.md - Environment variable documented in README feature flags table
Files to Change
| File | Change |
|---|---|
src/logger.ts |
Add LOG_JSON detection, conditional transport |
src/logging/access-log.ts |
Remove timestamp from formatAccessLog() |
src/logging/request-tracker.ts |
Conditional accessLog object inclusion |
src/server.ts |
Update other log calls to use helper or pattern |
docs/guide/configuration.md |
Add logging configuration section |
README.md.in |
Add LOG_JSON to feature flags table (optional) |
Testing
# Plain mode (default)
yarn dev:sse
# Verify single-line output in terminal
# JSON mode
LOG_JSON=true yarn dev:sse
# Verify JSON output, pipe to jq for validation:
LOG_JSON=true yarn dev:sse 2>&1 | jq .Related
- feat(logging): Implement condensed access log format with request stack aggregation #194 - Original condensed logging implementation (closed)
src/logging/request-tracker.ts:257- Current log call with objectsrc/logger.ts- pino configuration