Backend structured logging with traceId

[test3207]

Parent Epic: #190

Overview

Enhance M3W backend logging with structured JSON output and request tracing for better observability in Loki.

Log Format Specification

Common Fields (Auto-injected)

Field	Type	Source	Description
timestamp	string	Auto	ISO8601 format
level	string	Manual	error / warn / info / debug
service	string	Config	Fixed m3w-backend
region	string	Env var	jp / sea (from REGION)
traceId	string	Middleware	Request trace ID (from X-Trace-Id header)
gateway	string	Header	Which gateway handled the request (from X-Gateway header)
userId	string	Middleware	Current user ID

Business Fields (Manual)

Field	Type	Description
source	string	filename.functionName (手写)
col1	string	Business category (e.g., auth, upload, playlist)
col2	string	Sub-category (e.g., login, delete, create)
col3	string	Business ID (e.g., githubId, songId)
raw	object	Arbitrary raw data
error	string	Error message (for error level only)
errorStack	string	Error stack trace (for error level only)
message	string	Human-readable description

Log Levels

Level	Usage
error	Errors requiring attention (API failures, exceptions)
warn	Abnormal but recoverable situations (token expired, invalid input)
info	Key business events (login, upload, delete)
debug	Debug info (disabled in production)

Example: Info Log

{
  "timestamp": "2025-12-22T10:30:00.000Z",
  "level": "info",
  "service": "m3w-backend",
  "region": "jp",
  "traceId": "550e8400-e29b-41d4-a716-446655440000",
  "gateway": "gateway1",
  "userId": "user_123",

  "source": "auth.handleOAuthCallback",
  "col1": "auth",
  "col2": "login",
  "col3": "20714425",
  "raw": { "isNewUser": false, "email": "test@example.com" },

  "message": "User logged in successfully"
}

Example: Error Log

{
  "timestamp": "2025-12-22T10:30:00.000Z",
  "level": "error",
  "service": "m3w-backend",
  "region": "jp",
  "traceId": "550e8400-e29b-41d4-a716-446655440000",
  "gateway": "gateway1",
  "userId": "user_123",

  "source": "auth.handleOAuthCallback",
  "col1": "auth",
  "col2": "login",
  "col3": "20714425",
  "raw": { "response": { "status": 401 } },

  "error": "GitHub API returned 401",
  "errorStack": "Error: GitHub API returned 401\n    at fetchUser (auth.ts:82)\n    at handleOAuthCallback (auth.ts:142)",

  "message": "GitHub OAuth failed"
}

Implementation

1. TraceId Middleware

// src/lib/trace-middleware.ts
export const traceMiddleware = () => {
  return async (c: Context, next: Next) => {
    const traceId = c.req.header('x-trace-id') || crypto.randomUUID();
    c.set('traceId', traceId);
    c.header('x-trace-id', traceId);
    await next();
  };
};

2. Logger Factory

// src/lib/logger.ts
import pino from 'pino';

const baseLogger = pino({
  level: process.env.LOG_LEVEL || 'info',
  // ... existing config
});

export function createLogger(c?: Context) {
  const base = {
    service: 'm3w-backend',
    region: process.env.REGION || 'unknown',
    traceId: c?.get('traceId'),
    gateway: c?.req.header('x-gateway'),
    userId: c?.get('userId'),
  };

  return {
    info: (source: string, col1: string, col2: string, col3: string, raw: object, message: string) => {
      baseLogger.info({ ...base, source, col1, col2, col3, raw, message });
    },
    warn: (source: string, col1: string, col2: string, col3: string, raw: object, message: string) => {
      baseLogger.warn({ ...base, source, col1, col2, col3, raw, message });
    },
    error: (source: string, col1: string, col2: string, col3: string, raw: object, err: Error, message: string) => {
      baseLogger.error({
        ...base, source, col1, col2, col3, raw,
        error: err.message,
        errorStack: err.stack,
        message,
      });
    },
  };
}

3. Usage Example

// routes/auth.ts
async function handleOAuthCallback(c: Context) {
  const log = createLogger(c);

  // Success log
  log.info(
    'auth.handleOAuthCallback',  // source
    'auth',                       // col1
    'login',                      // col2
    user.githubId,                // col3
    { isNewUser, email },         // raw
    'User logged in'              // message
  );

  // Error log
  log.error(
    'auth.handleOAuthCallback',
    'auth',
    'login',
    githubId || '',
    { response: data },
    error,
    'GitHub OAuth failed'
  );
}

4. Frontend Log Endpoint

// routes/logs.ts
app.post('/api/logs', async (c) => {
  const logs = await c.req.json();
  // Validate, sanitize, rate limit
  // Output to stdout (picked up by Alloy)
  for (const log of logs) {
    baseLogger[log.level || 'info']({
      ...log,
      service: 'm3w-frontend',  // Override to ensure correct service
    });
  }
  return c.json({ ok: true });
});

Tasks

Backend (m3w)

• Create src/lib/trace-middleware.ts (PR feat: implement Epic 3.5 observability logging #265)
• Update src/lib/logger.ts with createLogger() factory (PR feat: implement Epic 3.5 observability logging #265)
• Apply trace middleware in src/index.ts (PR feat: implement Epic 3.5 observability logging #265)
• Create POST /api/logs endpoint for frontend logs (PR feat: implement Epic 3.5 observability logging #265)
• Migrate existing logger.info/warn/error calls to new format (PR refactor(backend): migrate to structured logging with createLogger #267)
• Add REGION env var to deployment config

Gateway (m3w-k8s)

修改 gateway-routing.lua.j2：

-- 生成或透传 traceId
local trace_id = ngx.req.get_headers()["X-Trace-Id"]
if not trace_id or trace_id == "" then
    trace_id = ngx.var.request_id  -- nginx 内置请求 ID
end
ngx.req.set_header("X-Trace-Id", trace_id)
ngx.req.set_header("X-Gateway", "{{ inventory_hostname }}")

• Modify gateway-routing.lua.j2 to set X-Trace-Id header (generate if not present)
• Modify gateway-routing.lua.j2 to set X-Gateway header (e.g., gateway1)
• Redeploy gateways

Loki Query Examples

# Query all backend logs
{service="m3w-backend"}

# Query by source
{service="m3w-backend"} | json | source =~ "auth.*"

# Query by business category
{service="m3w-backend"} | json | col1 = "upload"

# Query errors
{service="m3w-backend"} | json | level = "error"

# Query by user
{service="m3w-backend"} | json | userId = "user_123"

# Trace full request chain
{service=~"m3w-.*"} | json | traceId = "550e8400..."

Dependencies

• Set up Grafana Cloud + deploy Alloy agents #251 Grafana Alloy agents (completed ✅)

[test3207]

PR #265 Implementation Review

PR #265 实现了大部分 logging 功能，以下是对 header 流动的分析：

✅ 已实现

组件	实现	说明
Backend trace-middleware	✅	读取 X-Trace-Id 和 X-Gateway，若无则生成 traceId
Backend logger factory	✅	createLogger(c) 自动注入 traceId, gateway, userId
Backend /api/logs endpoint	✅	接收前端日志并输出
Frontend logger-client	✅	生成 traceId, sessionId, 收集客户端上下文
Frontend router.ts	✅	对 API 请求设置 X-Trace-Id header

⚠️ 需要在 m3w-k8s 补充

Gateway 需要设置 X-Trace-Id 和 X-Gateway headers。已创建 issue: m3w-k8s#1

📝 设计决策

1. /api/logs 不追踪自身请求 - 避免无限循环，这是正确的
2. 前端不需要响应中的 traceId - 前端自己生成 traceId，不需要从后端获取
3. 不需要 CORS Expose-Headers - 前端不读取自定义响应头

📋 剩余任务

此 issue 的剩余任务主要是代码迁移（将现有 logger 调用迁移到新格式），已在 PR #265 中部分完成。