안녕하세요.
볼드나인 백엔드 개발자 잭슨입니다.
이번에는 의존성 주입을 통한 로그 트래킹이라는 주제로 이야기해 보겠습니다.
로그는 서버로 들어오는 다양한 요청들의 정보와 그 요청을 처리하는 과정에서 발생하는 에러, 그리고 개발자가 디버깅용으로 출력한 정보들을 포함하고 있습니다.
잘 기록된 로그는 사용자로부터의 문의나 서버장애를 처리하는 데 많은 도움을 줍니다. 만약 서버에 로그가 하나도 기록되지 않거나 정보가 부족하다면 서버 개발자들은 사용자 문의나 장애를 처리하기 위해서 동일한 요청을 다시 호출하거나 심지어 요청을 다시 호출하더라도 동일한 현상을 재현할 수 없을지도 모릅니다. 그렇게 되면 문제의 원인을 찾을수가 없겠죠.
이번 글은 서버로 들어오는 하나의 요청 내부에서 기록되는 다양한 로그를 어떤 요청에서 발생한 로그인지 식별할 수 있는 방법에 대해서 이야기합니다.
서버에 로그가 잘 기록되어 있더라도 어떤 요청에서 발생한 로그인지 알 수 없다면 디버깅이 쉽지 않겠죠?
저희 서비스에서도 원래는 아래와 같이 로그가 필요한 곳에서 로거를 직접 import하여서 사용하였습니다.
import logger from 'src/logger';
import userRepository from 'src/repository/userRepository';
import User from 'src/types/user'
class UserService {
...
async creatUser(user: User) {
try {
logger.info('회원등록 시작.');
const result = await userRepository.create(user);
logger.info(`회원등록 성공. ID: ${result.id}`);
logger.info('회원등록 끝.');
return result;
} catch(error) {
logger.error('에러 발생!!');
}
}
...
}
TypeScript
복사
위 코드의 logger는 winston 모듈을 사용해서 파일로 저장하거나 로깅 서버로 전송하도록 구현할 수 있는데 구현 방법은 검색하면 쉽게 찾을 수 있으므로 여기서는 따로 설명하지 않습니다. (gcp의 cloud logging으로 전송하는 글은 여기 참고).
이제 특정 요청에서 UserService 클래스를 이용해서 creatUser 메서드를 호출하게 되면 아래와 같이 로그가 기록됩니다.
이렇게 요청이 한 개만 있을때는 각 로그가 어떤 요청으로부터 발생한 로그인지 한눈에 알 수가 있습니다.
하지만 서버에는 1초에 수십 번에서 수백 번의 요청이 올 수 있습니다.
만약 creatUser 메서드를 호출하는 요청이 동시에 여러 번 온다면 아래과 같이 로그가 서로 섞여버릴 수가 있습니다.
위의 로그를 보면 동시에 회원등록 요청이 3번이 들어왔다는 것은 알 수가 있지만 각 로그가 어떤 요청으로부터 생성된 로그인지는 알 수가 없습니다.
예를 들어 네 번째 줄에 있는 회원등록 성공. ID: lee123 이 첫 번째 줄의 회원등록 시작 로그과 연결된 로그인지 두 번째 줄의 회원등록 시작 로그와 연결된 로그인지 알 수가 없습니다.
이렇게 간단한 로그에서는 대충 눈으로 예상이 가능하지만 수천 수만 줄씩 기록된 로그에서는 중간중간에 기록된 로그나 에러가 서로 섞여 있으면 디버깅할 때 어떤 로그를 봐야 할지 구별하기가 힘듭니다.
그래서 요청을 구분하기 위해서 각 요청에 request ID를 부여하고 로그마다 request ID를 붙여서 어떤 로그들이 같은 요청으로 생성된 로그인지 구분해보겠습니다.
예제는 express 기준으로 설명하겠습니다.
먼저 미들웨어에 등록할 함수를 정의합니다.
// loggingMiddleWare.ts
import { NextFunction, Request, Response } from 'express';
import { v4 as uuidv4 } from 'uuid';
import logger from 'src/logger';
const logging = (req: Request, res: Response, next: NextFunction) => {
const { body, params, query, headers, method, originalUrl } = req;
// 각 요청마다 부여할 reqeust ID 생성후
res.locals.requestid = uuidv4();
const inputs = {
headers,
body,
params,
requestId: res.locals.requestid,
};
const originPath = headers.host + originalUrl;
const logMessage = `[${
res.locals.requestid
}] ${originPath} ${method} \n ${JSON.stringify(inputs)}`;
// 요청정보가 포함된 로그에 request ID를 추가하여 로깅
logger.info(logMessage);
next();
};
export default logging;
TypeScript
복사
import express from 'express';
import loggingMiddleWare from 'src/middleWare/loggingMiddleWare';
const app = express()
const port = 3000
...
// 로깅 미들웨어 등록
app.use(loggingMiddleWare);
...
app.listen(port, () => {
console.log(`Example app listening on port ${port}`)
})
TypeScript
복사
express 설정에 따라 코드가 훨씬 길지만 설명을 위해서 최대한 생략하였습니다.
logging 미들웨어를 보면 uuid 모듈을 사용해서 요청이 들어올 때마다 새로운 uuid를 생성하고 이를 다른 곳에서 사용할 수 있게 response 객체의 locals에 저장합니다. 그리고 헤더나 http method 등 요청에 대한 정보를 logger 모듈을 이용해서 기록해 줍니다.
이제 response 객체의 locals에 저장된 request ID를 각 요청에서 로그를 기록할 때 사용하도록 해보겠습니다.
우선 기존에 직접 import해서 사용하던 logger에 request ID를 자동으로 추가해서 로그를 기록할 수 있도록 함수는 하나 작성하겠습니다.
import * as winston from 'winston';
import logger from './logger';
export const getLogger = (requestId: string = ''): CustomLogger => ({
info: (message: string) => logger.info(`[${requestId}] ${message}`),
error: (message: string) => logger.error(`[${requestId}] ${message}`),
});
export interface CustomLogger {
info: (message: string) => winston.Logger;
error: (error: any) => winston.Logger;
}
TypeScript
복사
기존에 사용하던 getLogger 함수를 통해서 얻은 logger를 사용해서 로그를 기록하게 되면 reqeust ID를 무조건 앞에 붙어서 함께 출력되게 됩니다.
이제 이 함수를 각 라우터에서 사용하는 서비스들에 전달하고 각 서비스들은 직접 logger를 import하지 않고 전달받은 logger를 이용해서 로깅을 하도록 하면 됩니다.
import logger from 'src/logger';
import userRepository from 'src/repository/userRepository';
import User from 'src/types/user'
class UserService {
constructor(private logger: CustomLogger) {}
...
async creatUser(user: User) {
try {
this.logger.info('회원등록 시작.');
const result = await userRepository.create(user);
this.logger.info(`회원등록 성공. ID: ${result.id}`);
this.logger.info('회원등록 끝.');
return result;
} catch(error) {
this.logger.error('에러 발생!!');
}
}
...
}
TypeScript
복사
우선 처음에 봤던 UserService 클래스를 수정하겠습니다. UserService 클래스의 생성자에서 logger를 받을 수 있게 하고 클래스 내의 메서드들은 logger를 사용할 때 클래스의 멤버 변수의 logger를 사용하도록 합니다.
이제 이 서비스를 호출하는 라우터에서 로그를 생성한 뒤, UserService를 인스턴스화 시킬때 전달하도록 하겠습니다.
import { NextFunction, Request, Response, Router } from 'express';
import UserService from 'src/services/userService';
import { CustomLogger, getLogger } from '../config/getLogger';
export default function userRouter(): Router {
const router: Router = Router();
let logger: CustomLogger;
router.use('/', (req: Request, res: Response, next: NextFunction) => {
// 다른 라우터에서 생성하는 서비스들에게 전달할 logger 저장
logger = getLogger(res.locals.requestid);
next();
});
router.post('/', (req: Request, res: Response, next: NextFunction) => {
try {
// reqeust ID가 부여된 logger를 서비스에 전달
const userService = new UserService(logger);
const user = userService.createUser({
name: '이민호',
id: 'lee123',
password: 'qwert1234!',
});
return res.json(user);
} catch (error) {
next(error);
}
});
return router;
}
TypeScript
복사
라우터 구성은 서비스나 프로젝트 구조에 따라 달라지기 때문에 로거를 생성해서 서비스에 전달한다는 컨셉을 이해합시다.
이제 요청을 다시 호출해 보면 아래와 같이 출력이 됩니다.
이런 식으로 각 라우터에서 미리 생성된 logger를 주입받아 사용하게 되면 로그가 기록될 때마다 request ID가 함께 기록이 될거고 어떤 요청과 연관 있는 로그인지 확인할 수 있습니다.
이렇게 로그를 request ID로 구분할 수 있게 되면 로그가 어떤 요청으로부터 생성되었는지 확실히 알 수가 있어 디버깅 시 매우 유용합니다.
이상입니다.