Node.js 로깅 - JSON 한 줄 로그와 요청 id, 비밀값 가리기 (Node.js API 9단원)

이 단원에서 배우는 것

사용자가 "아까 메모 저장이 안 됐어요"라고 말한다. 언제, 어떤 요청이, 몇 번 상태로, 얼마나 걸려 끝났는지 알 수 없으면 할 수 있는 말은 "다시 해 보세요"뿐이다. 로그는 서버가 남기는 일지다. 사람이 읽을 수 있으면서 프로그램으로 검색하고 집계할 수 있어야 하고, 남기면 안 되는 것은 남기지 않아야 한다.

• 한 줄에 JSON 하나(JSON Lines)로 찍는 작은 로거를 만든다. 로그 수준(debug·info·warn·error)으로 양을 조절한다.
• 요청마다 번호(reqId)를 붙이고, 응답이 끝나면 메서드·경로·상태·걸린 시간을 한 줄로 남긴다.
• 비밀번호, 토큰, 쿠키 같은 값을 자동으로 가린다.
• 예상하지 못한 오류를 스택과 함께, 어느 요청에서 났는지까지 남긴다.

문제 상황

지금까지 서버는 console.log로 시작 메시지만 찍었다. 오류가 나면 console.error로 스택을 찍었는데, 요청이 몰리면 여러 요청의 출력이 뒤섞여 어느 스택이 어느 요청 것인지 알 수 없다. 누군가 디버깅하려고 console.log('로그인 요청', req)를 넣었다가 비밀번호가 로그 파일에 그대로 남은 적도 있다.

이 단원에서 memo-api에 더하는 파일은 lib/logger.mjs, lib/access-log.mjs, console-trap.mjs이고 server.mjs를 바꾼다. app.mjs는 그대로다.

완성 코드

console.log의 두 문제: console-trap.mjs

// console-trap.mjs — console.log 로 객체를 찍으면 생기는 두 가지 문제
const user = { id: 7, email: 'me@example.com', password: 'hunter2-example' };
const req = { method: 'POST', path: '/login', body: user, meta: { a: { b: { c: { d: 1 } } } } };

console.log('로그인 요청', req);                   // 1) 비밀번호가 그대로 남는다 2) 깊은 곳은 [Object] 로 잘린다
console.log(JSON.stringify({ msg: '로그인 요청', method: req.method, path: req.path, userId: user.id }));

lib/logger.mjs

// lib/logger.mjs — 한 줄에 JSON 하나씩 찍는 작은 로거
const LEVELS = { debug: 10, info: 20, warn: 30, error: 40 };
const HIDDEN = new Set(['authorization', 'cookie', 'password', 'token', 'apitoken']);

// 비밀이 들어갈 만한 키는 값을 가린다 (중첩 객체까지)
function redact(value) {
  if (Array.isArray(value)) return value.map(redact);
  if (value === null || typeof value !== 'object') return value;
  if (value instanceof Error) return { name: value.name, message: value.message, stack: value.stack };
  const out = {};
  for (const [k, v] of Object.entries(value)) {
    out[k] = HIDDEN.has(k.toLowerCase()) ? '[숨김]' : redact(v);
  }
  return out;
}

export function createLogger({ level = 'info', stream = process.stdout, base = {} } = {}) {
  const min = LEVELS[level];

  function write(lvl, msg, fields = {}) {
    if (LEVELS[lvl] < min) return;                    // 설정보다 낮은 단계는 버린다
    const entry = { time: new Date().toISOString(), level: lvl, msg, ...base, ...redact(fields) };
    stream.write(JSON.stringify(entry) + '\n');
  }

  return {
    debug: (msg, fields) => write('debug', msg, fields),
    info: (msg, fields) => write('info', msg, fields),
    warn: (msg, fields) => write('warn', msg, fields),
    error: (msg, fields) => write('error', msg, fields),
    child: (extra) => createLogger({ level, stream, base: { ...base, ...extra } }),
  };
}

lib/access-log.mjs

// lib/access-log.mjs — 요청마다 번호를 붙이고, 응답이 끝나면 한 줄 기록한다
import { randomUUID } from 'node:crypto';

export function withAccessLog(app, log) {
  return (req, res) => {
    const started = process.hrtime.bigint();
    const reqId = randomUUID().slice(0, 8);            // 짧게 잘라도 한 서버 안에서 구분하기엔 충분하다
    res.setHeader('x-request-id', reqId);
    req.log = log.child({ reqId });                    // 이 요청 안에서 찍는 로그에는 reqId 가 붙는다
    req.log.debug('요청 헤더', { headers: req.headers });

    res.on('finish', () => {
      const ms = Number(process.hrtime.bigint() - started) / 1e6;
      const path = new URL(req.url, 'http://localhost').pathname;   // 쿼리 문자열은 남기지 않는다
      const fields = { method: req.method, path, status: res.statusCode, ms: Math.round(ms * 10) / 10 };
      if (res.statusCode >= 500) req.log.error('요청 처리', fields);
      else if (res.statusCode >= 400) req.log.warn('요청 처리', fields);
      else req.log.info('요청 처리', fields);
    });
    return app(req, res);
  };
}

server.mjs

// server.mjs — 8단원 서버에 JSON 로그를 붙였다
import { createServer } from 'node:http';
import { createApp } from './app.mjs';
import { createMemoStore } from './lib/store.mjs';
import { loadConfig, describeConfig } from './lib/config.mjs';
import { withToken } from './lib/auth.mjs';
import { createLogger } from './lib/logger.mjs';
import { withAccessLog } from './lib/access-log.mjs';

let config;
try {
  config = loadConfig();
} catch (err) {
  console.error(`설정 오류로 시작하지 않습니다:\n${err.message}`);
  process.exit(1);
}
const log = createLogger({ level: config.logLevel });
log.info('설정', describeConfig(config));

const store = createMemoStore(config.dataFile);
const app = createApp({
  store,
  onError: (err, req) => (req.log ?? log).error('처리하지 못한 오류', { err }),
});

const server = createServer(withAccessLog(withToken(app, config.apiToken), log));
server.listen(config.port, config.host, () => {
  log.info('서버 시작', { url: `http://${config.host}:${config.port}`, pid: process.pid });
});

줄별 해설

왜 JSON 한 줄인가

console.log('로그인 요청', req)는 사람이 보기엔 좋지만 여러 줄로 퍼지고, 깊은 객체는 [Object]로 잘린다. 로그 수집 도구(서버의 로그 파일, 클라우드 로그 서비스)는 한 줄을 한 사건으로 본다. 한 줄에 JSON 하나를 찍으면 level이 error인 것만, reqId가 특정 값인 것만 골라내기가 쉽다. 사람이 읽을 때도 grep 한 번으로 한 요청의 기록을 모두 모을 수 있다.

그림 9-1. JSON 로그 한 줄의 구성

로그 수준

  function write(lvl, msg, fields = {}) {
    if (LEVELS[lvl] < min) return;                    // 설정보다 낮은 단계는 버린다
    const entry = { time: new Date().toISOString(), level: lvl, msg, ...base, ...redact(fields) };
    stream.write(JSON.stringify(entry) + '\n');
  }

수준은 숫자로 바꿔 비교한다. 설정이 info(20)이면 debug(10)는 버려지고 나머지는 찍힌다. 개발할 때는 LOG_LEVEL=debug로 요청 헤더까지 보고, 운영에서는 info로 요청 한 줄씩만 남긴다. 8단원에서 만든 설정 검증이 여기서 쓰인다. 틀린 수준 이름은 서버가 뜨기 전에 거절된다.

로그 수준을 고르는 기준

수준	숫자	언제	이 책의 예
debug	10	개발 중에만	요청 헤더
info	20	평소 흐름	서버 시작 · 2xx 요청
warn	30	이상하지만 서비스는 됨	4xx 요청
error	40	사람이 봐야 함	5xx · 처리 못 한 오류

모든 줄에 time(ISO 8601 형식, UTC)과 level, msg가 들어가고, 그 뒤에 base(로거에 붙여 둔 값)와 이번 호출에서 준 필드가 붙는다. 시각을 UTC로 찍어 두면 서버가 어느 나라에 있든 로그끼리 비교할 수 있다.

자식 로거와 요청 번호

req.log = log.child({ reqId });                    // 이 요청 안에서 찍는 로그에는 reqId 가 붙는다

child는 같은 설정에 필드 몇 개를 더 붙인 새 로거를 만든다. 요청이 들어올 때 reqId가 붙은 자식 로거를 만들어 req에 달아 두면, 이 요청을 처리하는 동안 어디서 찍든 같은 번호가 붙는다. 동시에 들어온 요청 100개의 로그가 섞여도 번호로 풀어낼 수 있다. 번호는 x-request-id 응답 헤더로도 알려 준다. 사용자가 오류 화면에서 이 번호를 알려 주면 바로 그 요청의 로그를 찾는다. 6단원 연습 문제에서 말한 "사용자가 알려 준 번호로 로그 찾기"가 이것이다.

응답이 끝날 때 한 줄

    res.on('finish', () => {
      const ms = Number(process.hrtime.bigint() - started) / 1e6;
      const path = new URL(req.url, 'http://localhost').pathname;   // 쿼리 문자열은 남기지 않는다
      const fields = { method: req.method, path, status: res.statusCode, ms: Math.round(ms * 10) / 10 };
      if (res.statusCode >= 500) req.log.error('요청 처리', fields);
      else if (res.statusCode >= 400) req.log.warn('요청 처리', fields);
      else req.log.info('요청 처리', fields);
    });

응답을 다 보낸 순간 res가 finish 사건을 알린다. 이때 상태 코드와 걸린 시간을 기록하면, 404든 401이든 500이든 모든 응답이 빠짐없이 한 줄씩 남는다. 시간은 process.hrtime.bigint()로 잰다. 시계를 사람이 바꾸거나 시각 동기화로 시계가 움직여도 영향을 받지 않는, 계속 늘어나기만 하는 나노초 단위 값이다. 상태 코드에 따라 수준을 나눠 500대는 error, 400대는 warn으로 찍는다. 운영 중에 error만 모아 보면 서버 쪽 문제만 보인다.

경로는 pathname만 남기고 쿼리 문자열은 버린다. 검색어나 이메일, 때로는 토큰이 쿼리에 실려 오기 때문이다(연습 문제 1번).

남기면 안 되는 것 가리기

function redact(value) {
  if (Array.isArray(value)) return value.map(redact);
  if (value === null || typeof value !== 'object') return value;
  if (value instanceof Error) return { name: value.name, message: value.message, stack: value.stack };
  const out = {};
  for (const [k, v] of Object.entries(value)) {
    out[k] = HIDDEN.has(k.toLowerCase()) ? '[숨김]' : redact(v);
  }
  return out;
}

redact는 객체를 끝까지 따라 내려가면서 키 이름이 authorization, cookie, password, token, apitoken이면 값을 [숨김]으로 바꾼다. 대소문자는 구분하지 않는다. 로그를 찍는 사람이 매번 조심하지 않아도 로거가 막아 준다. Error 객체는 그대로 JSON.stringify하면 {}가 되므로(메시지와 스택이 열거되지 않는 속성이다), 이름·메시지·스택을 꺼내 평범한 객체로 바꾼다.

다만 이 목록은 키 이름이 정확히 같을 때만 가린다. userPassword나 pw는 통과한다(연습 문제 2번). 가리는 장치는 마지막 안전망이고, 첫 번째 원칙은 "비밀이 든 객체를 통째로 로그에 넘기지 않는다"이다.

로그에 남길 것과 남기지 않을 것

항목	남기나	이유
메서드 · 경로	남긴다	무엇을 요청했나
쿼리 문자열	뺀다	검색어 · 이메일 · 토큰
상태 · 걸린 시간	남긴다	결과와 성능
요청 번호	남긴다	한 요청의 기록 묶기
요청 본문	남기지 않는다	비밀번호 · 개인정보
authorization · 쿠키	가린다	계정 탈취 방지

미들웨어 두 겹

const server = createServer(withAccessLog(withToken(app, config.apiToken), log));

그림 9-2. 미들웨어 순서와 로그

요청은 바깥부터 안으로 withAccessLog → withToken → app 순서로 지나간다. 로그를 가장 바깥에 두었으므로 토큰 확인에서 막힌 401도 기록된다. 순서를 바꾸면 401은 로그에 남지 않는다. 프레임워크에서 미들웨어 등록 순서가 중요한 이유가 이것이다. onError는 req.log가 있으면 그것으로 찍어 오류에도 reqId가 붙는다.

실제 실행 결과

먼저 console.log의 두 문제를 본다.

$ node console-trap.mjs
로그인 요청 {
  method: 'POST',
  path: '/login',
  body: { id: 7, email: 'me@example.com', password: 'hunter2-example' },
  meta: { a: { b: [Object] } }
}
{"msg":"로그인 요청","method":"POST","path":"/login","userId":7}

비밀번호가 그대로 찍혔고, 깊은 곳의 값은 [Object]로 잘렸다. 두 번째 줄처럼 필요한 필드만 골라 JSON으로 찍는 것이 이 단원의 방향이다.

서버를 LOG_LEVEL=debug API_TOKEN=dev-token-0123456789abcd node server.mjs로 띄우고, 토큰 없이 한 번, 토큰과 함께 세 번 요청했다.

$ node call.mjs 'POST /memos {"title":"로그 보기"}'
POST /memos -> 401
  {"error":{"code":"UNAUTHORIZED","message":"쓰기 요청에는 토큰이 필요합니다"}}

$ API_TOKEN=dev-token-0123456789abcd node call.mjs 'POST /memos {"title":"로그 보기"}' "GET /memos/1" "GET /memos/99"
POST /memos -> 201
  {"id":1,"title":"로그 보기","done":false}
GET /memos/1 -> 200
  {"id":1,"title":"로그 보기","done":false}
GET /memos/99 -> 404
  {"error":{"code":"MEMO_NOT_FOUND","message":"99번 메모가 없습니다"}}

서버 쪽 출력(표준 출력)은 이렇다. 한 줄이 길어서 화면에서는 줄이 접혀 보일 수 있다.

{"time":"2026-09-23T15:42:42.469Z","level":"info","msg":"설정","production":false,"host":"127.0.0.1","port":3700,"dataFile":"<프로젝트>/data/memos.json","logLevel":"debug","apiToken":"[숨김]"}
{"time":"2026-09-23T15:42:42.475Z","level":"info","msg":"서버 시작","url":"http://127.0.0.1:3700","pid":47177}
{"time":"2026-09-23T15:42:42.582Z","level":"debug","msg":"요청 헤더","reqId":"fdbcd039","headers":{"host":"127.0.0.1:3700","connection":"keep-alive","content-type":"application/json","accept":"*/*","accept-language":"*","sec-fetch-mode":"cors","user-agent":"node","accept-encoding":"gzip, deflate","content-length":"25"}}
{"time":"2026-09-23T15:42:42.583Z","level":"warn","msg":"요청 처리","reqId":"fdbcd039","method":"POST","path":"/memos","status":401,"ms":1.5}
{"time":"2026-09-23T15:42:42.657Z","level":"debug","msg":"요청 헤더","reqId":"d935ed7a","headers":{"host":"127.0.0.1:3700","connection":"keep-alive","content-type":"application/json","authorization":"[숨김]","accept":"*/*","accept-language":"*","sec-fetch-mode":"cors","user-agent":"node","accept-encoding":"gzip, deflate","content-length":"25"}}
{"time":"2026-09-23T15:42:42.659Z","level":"info","msg":"요청 처리","reqId":"d935ed7a","method":"POST","path":"/memos","status":201,"ms":2.6}
{"time":"2026-09-23T15:42:42.664Z","level":"debug","msg":"요청 헤더","reqId":"64de4070","headers":{"host":"127.0.0.1:3700","connection":"keep-alive","authorization":"[숨김]","accept":"*/*","accept-language":"*","sec-fetch-mode":"cors","user-agent":"node","accept-encoding":"gzip, deflate"}}
{"time":"2026-09-23T15:42:42.665Z","level":"info","msg":"요청 처리","reqId":"64de4070","method":"GET","path":"/memos/1","status":200,"ms":0.3}
{"time":"2026-09-23T15:42:42.667Z","level":"debug","msg":"요청 헤더","reqId":"c3561a4f","headers":{"host":"127.0.0.1:3700","connection":"keep-alive","authorization":"[숨김]","accept":"*/*","accept-language":"*","sec-fetch-mode":"cors","user-agent":"node","accept-encoding":"gzip, deflate"}}
{"time":"2026-09-23T15:42:42.667Z","level":"warn","msg":"요청 처리","reqId":"c3561a4f","method":"GET","path":"/memos/99","status":404,"ms":0.3}

첫 줄은 설정이다. describeConfig가 이미 설정됨(24자)로 바꾼 값인데, 로거가 apiToken이라는 키 이름을 보고 한 번 더 가렸다. debug 줄에 요청 헤더가 모두 찍혔지만 authorization은 [숨김]이다. 요청마다 요청 헤더와 요청 처리 두 줄이 같은 reqId로 묶였다. 401과 404는 warn, 201과 200은 info다. ms는 실행할 때마다 조금씩 달라진다.

이번에는 데이터 파일을 일부러 중간에서 끊어 놓고 node server.mjs(기본 수준 info)로 띄운 뒤 목록을 요청했다.

$ node call.mjs "GET /memos"
GET /memos -> 500
  {"error":{"code":"INTERNAL","message":"서버에서 문제가 생겼습니다"}}

{"time":"2026-09-23T15:42:42.783Z","level":"info","msg":"설정","production":false,"host":"127.0.0.1","port":3700,"dataFile":"<프로젝트>/data/memos.json","logLevel":"info","apiToken":"[숨김]"}
{"time":"2026-09-23T15:42:42.790Z","level":"info","msg":"서버 시작","url":"http://127.0.0.1:3700","pid":47180}
{"time":"2026-09-23T15:42:42.900Z","level":"error","msg":"처리하지 못한 오류","reqId":"91062df6","err":{"name":"Error","message":"/home/me/node-book/memo-api/data/memos.json 의 JSON 이 깨졌습니다: Expected ',' or '}' after property value in JSON at position 27 (line 1 column 28)","stack":"Error: /home/me/node-book/memo-api/data/memos.json 의 JSON 이 깨졌습니다: Expected ',' or '}' after property value in JSON at position 27 (line 1 column 28)\n    at loadMemos (file:///home/me/node-book/memo-api/lib/memo-file.mjs:17:11)\n    at async current (file:///home/me/node-book/memo-api/lib/store.mjs:9:15)\n    at async Object.list (file:///home/me/node-book/memo-api/lib/store.mjs:28:15)\n    at async async.req.req (file:///home/me/node-book/memo-api/app.mjs:12:19)\n    at async dispatch (file:///home/me/node-book/memo-api/app.mjs:61:47)\n    at async app (file:///home/me/node-book/memo-api/app.mjs:73:7)"}}
{"time":"2026-09-23T15:42:42.901Z","level":"error","msg":"요청 처리","reqId":"91062df6","method":"GET","path":"/memos","status":500,"ms":2.3}

클라이언트는 일반적인 500 문장만 받았다. 로그에는 같은 reqId로 묶인 두 줄이 남았다. 첫 줄의 err.message가 원인(어느 파일의 JSON이 몇 번째 글자에서 깨졌는지)을, stack이 경로(loadMemos ← current ← list ← 라우트)를 알려 준다. 3단원에서 오류에 파일 경로를 붙여 둔 것이 여기서 쓸모를 보인다. 이번에는 info 수준이라 요청 헤더 줄은 없다.

실무에서 자주 틀리는 것

1. 요청 본문을 통째로 찍는다

"디버깅용으로 잠깐만" 넣은 log.info('요청', { body })가 운영까지 간다. 회원가입 본문에는 비밀번호가, 결제 본문에는 카드 정보가 있다. 본문은 찍지 않는다. 필요하면 필드 몇 개를 골라 찍는다.

2. 로그 수준을 다 info로 찍는다

모든 것이 info이면 운영에서 수준으로 거를 수 없다. "사람이 당장 봐야 한다"는 error, "이상하지만 서비스는 된다"는 warn, "평소 흐름"은 info, "개발 중에만 필요"는 debug로 나눈다.

3. 앱이 로그 파일을 직접 쓰고 돌린다

앱 안에서 날짜별 파일을 만들고 오래된 파일을 지우는 코드는 생각보다 까다롭다. 서버 앱은 표준 출력에 한 줄씩 쓰고, 파일 저장과 보관 기간은 프로세스 관리자(systemd, PM2, 컨테이너 런타임)나 로그 수집기에 맡기는 것이 요즘 흔한 방식이다(11단원).

4. 오류를 err.message만 찍는다

메시지만 있으면 "어디서"를 모른다. 스택까지 남긴다. 반대로 스택은 응답에는 절대 넣지 않는다(6단원).

연습 문제

1. 접근 로그에 req.url(쿼리 포함)을 그대로 남기면 어떤 문제가 생길 수 있는가? 예를 들어 설명하라.
2. log.info('가입', { user: { email: 'a@example.com', userPassword: 'x1' } })를 찍으면 userPassword는 가려지는가? 가리려면 redact를 어떻게 바꾸는가?
3. createServer(withToken(withAccessLog(app, log), config.apiToken))처럼 순서를 바꾸면 토큰 없이 보낸 POST는 로그에 어떻게 남는가?

정답과 해설

1. 쿼리 문자열에는 검색어(?q=병원 이름), 이메일(?email=...), 비밀번호 재설정 링크의 일회용 토큰(?token=...) 같은 값이 실린다. 로그는 여러 사람이 보고 오래 보관되므로 이런 값이 그대로 쌓이면 개인정보나 계정을 넘겨주는 셈이다. 이 책의 접근 로그는 pathname만 남긴다. 쿼리가 꼭 필요하면 안전한 이름(page, size)만 골라 남긴다.
2. 가려지지 않는다. HIDDEN은 키 이름이 정확히 같을 때만 가리기 때문이다(검증 스크립트로 x1이 그대로 찍히는 것을 확인). 키 이름에 password, token, secret 같은 낱말이 들어 있으면 가리도록 바꿀 수 있다. 예: const SENSITIVE = /pass|token|secret|authorization|cookie/i;로 두고 SENSITIVE.test(k)로 검사한다. 너무 넓히면 tokenCount처럼 가릴 필요 없는 값까지 가려지므로 팀의 필드 이름 규칙과 함께 정한다.
3. 아무것도 남지 않는다. 바깥쪽 withToken이 401을 보내고 끝내서 요청이 안쪽의 withAccessLog까지 가지 않기 때문이다. 인증 실패는 공격 시도를 알아채는 데 가장 중요한 기록인데 그것이 사라진다. 로그와 요청 번호처럼 "모든 요청에 적용할 것"은 가장 바깥에 둔다.

로그로 문제를 "발견"할 수 있게 됐다. 다음 단원에서는 문제가 운영까지 가기 전에 잡는 테스트를 node:test로 만든다.