feat(logging): Implement condensed access log format with request stack aggregation #194
Description
Problem
Current logging outputs multiple separate lines per request:
[12:34:56] INFO: MCP endpoint request received
[12:34:56] INFO: Tool called: browse_projects
[12:34:56] INFO: Connection verified: 17.8.0 Ultimate
[12:34:56] INFO: Executing tool: browse_projects
[12:34:56] DEBUG: Tool result: {...}
[12:34:57] INFO: MCP session closed: abc12345
This makes log analysis difficult:
- Hard to correlate events for single request
- No timing information for request duration
- Verbose output floods logs in production
- No clear request lifecycle visibility
Solution
Implement request stack aggregation - collect all events during request lifecycle and output single condensed line when request completes.
Request Lifecycle
Request arrives -> Open stack (record start time)
-> Accumulate events (tool calls, GitLab responses, etc.)
Request completes -> Close stack, calculate duration, output single line
Stack closes on:
- Success response sent to client
- Error returned to client
- Disconnect/timeout detected
Proposed Access Log Format
Single-line format inspired by nginx/envoy:
[timestamp] client_ip session ctx ro method path status duration_ms | tool action | gitlab_status gitlab_duration_ms | details
nginx-style alignment: All fields are always present with - for missing/unavailable values. This ensures consistent log format for parsing and grep operations.
Examples:
# All fields present - successful tool call with context and read-only off
[2026-01-25T12:34:56Z] 192.168.1.100 abc123.. mygroup/proj - POST /mcp 200 142ms | browse_projects list | GL:200 98ms | namespace=test/backend items=15
# Read-only mode enabled
[2026-01-25T12:34:56Z] 192.168.1.100 abc123.. mygroup/proj RO POST /mcp 200 85ms | browse_files list | GL:200 45ms | path=src/
# No context selected, read-only off
[2026-01-25T12:34:56Z] 192.168.1.100 abc123.. - - POST /mcp 200 142ms | browse_projects list | GL:200 98ms | namespace=test items=15
# Missing session (new connection)
[2026-01-25T12:34:56Z] 192.168.1.100 - - - POST /mcp 200 142ms | browse_projects list | GL:200 98ms | namespace=test items=15
# No tool call (health check)
[2026-01-25T12:34:56Z] 192.168.1.100 - - - GET /health 200 5ms | - - | - - | -
# Rate limited (no tool execution, no GitLab call)
[2026-01-25T12:34:56Z] 192.168.1.100 - - - POST /mcp 429 2ms | - - | - - | rate_limit=true
# Connection timeout
[2026-01-25T12:34:56Z] 192.168.1.100 abc123.. mygroup/proj - POST /mcp 504 30000ms | browse_pipelines list | GL:timeout 30000ms | project=test/backend
Format Fields
| Field | Description |
|---|---|
timestamp |
ISO 8601 UTC |
client_ip |
Client IP address |
session |
Session ID (truncated 8 chars + ..) or - if none |
ctx |
Selected context (project/namespace path) or - if none |
ro |
Read-only mode: RO if enabled, - if not |
method |
HTTP method |
path |
Request path |
status |
HTTP response status |
duration_ms |
Total request processing time |
tool |
MCP tool name or - |
action |
CQRS action (list/get/create/etc.) or - |
gitlab_status |
GitLab API response status (GL:200, GL:404, GL:timeout) or - |
gitlab_duration_ms |
Time spent waiting for GitLab or - |
details |
Context-specific key=value pairs or - |
Part 2: Connection Close Logging
Separate log entry when SSE/persistent connection closes:
Connection Close Format
[timestamp] CONN_CLOSE client_ip session duration reason | requests tools errors
Examples:
# Normal client disconnect
[2026-01-25T12:40:00Z] CONN_CLOSE 192.168.1.100 abc123.. 5m32s client_disconnect | reqs=42 tools=15 errs=0
# Idle timeout
[2026-01-25T12:40:00Z] CONN_CLOSE 192.168.1.100 abc123.. 30m0s idle_timeout | reqs=3 tools=2 errs=0
# Server shutdown
[2026-01-25T12:40:00Z] CONN_CLOSE 192.168.1.100 abc123.. 2h15m server_shutdown | reqs=156 tools=89 errs=2
# Error disconnect
[2026-01-25T12:40:00Z] CONN_CLOSE 192.168.1.100 abc123.. 45s transport_error | reqs=5 tools=3 errs=1 last_err="write EPIPE"
Connection Close Fields
| Field | Description |
|---|---|
duration |
Connection lifetime (human readable: 5m32s, 2h15m) |
reason |
client_disconnect, idle_timeout, server_shutdown, transport_error, auth_expired |
reqs |
Total HTTP requests on this connection |
tools |
Total tool invocations |
errs |
Total errors encountered |
last_err |
Last error message if applicable |
Implementation Notes
Request Context Stack
interface RequestStack {
startTime: number;
clientIp: string;
sessionId?: string;
context?: string; // Selected project/namespace context
readOnly?: boolean; // Read-only mode flag
method: string;
path: string;
// Accumulated during request
tool?: string;
action?: string;
gitlabStatus?: number | 'timeout';
gitlabDuration?: number;
details: Record<string, string | number>;
// Set on completion
status?: number;
error?: string;
}Connection Stats
interface ConnectionStats {
connectedAt: number;
clientIp: string;
sessionId: string;
requestCount: number;
toolCount: number;
errorCount: number;
lastError?: string;
}Log Levels
| Event | Level |
|---|---|
| Access log line | info |
| Connection close | info |
| SSE heartbeat | debug |
| Stack accumulation events | debug (only when LOG_LEVEL=debug) |
Backwards Compatibility
- Keep existing detailed logs available via
LOG_FORMAT=verboseenv var - Default to condensed format (
LOG_FORMAT=condensedor unset) - Both formats use same Pino infrastructure
Acceptance Criteria
- Single access log line per request (success, error, or timeout)
- Request duration automatically calculated
- GitLab API call timing captured
- Connection close events logged separately
- Connection statistics (requests, tools, errors) tracked
- Disconnect reason captured (client, timeout, error, shutdown)
- Format configurable via
LOG_FORMATenv var - Context and read-only mode displayed in log line
- No change to existing functionality, only logging output
Related
- Current logging implementation:
src/logger.ts,src/utils/request-logger.ts - Request handling:
src/server.ts,src/handlers.ts