Skip to content

fix(logging): Access logs output multiline JSON instead of single condensed line #207

@polaz

Description

@polaz

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:

  1. The formatted message (logLine)
  2. Then the structured object (accessLog) as pretty-printed multiline JSON

Issues

  1. Multiline output - pino-pretty pretty-prints the accessLog object after the message
  2. Duplicate timestamp - [2026-01-25T04:10:33.989Z] in message is redundant (journald/pino already adds timestamp)
  3. Duplicate data - Same info appears in message AND in accessLog object

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-pretty transport
  • 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-pretty transport (raw pino JSON)
  • One JSON object per line (NDJSON)
  • All structured data preserved as fields
  • Machine-parseable for log aggregators
  • Full accessLog object 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-mcp

Output:

[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-mcp

Output:

{"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:latest

systemd example:

[Service]
Environment="LOG_JSON=true"
Environment="GITLAB_TOKEN=xxx"
ExecStart=/usr/bin/node /opt/gitlab-mcp/dist/server.js

Acceptance 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 accessLog object 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

Metadata

Metadata

Assignees

No one assigned

    Labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions