[준섭] 1130(목) 개발 기록 ‐ NestJS Interceptor와 로거
Interceptor는 Guard와 Pipe 사이, Exception Filter와 클라이언트로 나가는 Response 사이에 존재한다.
즉, Guard를 넘어서 오는 요청을 변경하거나 Exception Filter를 거쳐 나가는 응답을 변경할 수 있는 것
NestJS Lifecycle에서 유일하게 요청과 응답 모두를 핸들링할 수 있음
- 우리가 짠 메소드들(Controller, Service 등)을 실행하기 전과 후에 추가 로직을 적용할 수 있음
- 함수에서 반환된 결과를 변형할 수 있음
- 함수에서 던진 에러를 변형할 수 있음
- 기본 함수 로직에 추가 기능을 넣을 수 있음
- 특정한 상황에 어떠한 함수를 완전히 오버라이드 할 수 있음 (캐싱 등의 목적으로 사용)
→ 원한다면 Interceptor를 적용한 함수에 거의 무엇이든 할 수 있음
RxJS라는 stream을 extend하는 패키지를 사용하여 Interceptor 사용
import ...
@Injectable()
export class InterceptorExample implements NestInterceptor {
// 요청이 들어올 때와 응답이 나갈 때 타임스탬프를 찍는 로그 기능
intercept(context: ExecutionContext, next: CallHandler<any>): Observable<any> {
const now = new Date(); // 현재 시각
const req = context.switchToHttp().getRequest(); // req 객체 가져오기
const path = req.originalUrl; // 요청이 들어온 url
// 요청 로그 형식: [REQ] {요청 path} {요청 시간}
console.log(`[REQ] ${path} ${now.toLocaleString('kr')}`);
// 이 위에까지는 서버 라우트(Controller) 메소드들이 실행되기 전에, 즉 요청이 들어오자마자 실행됨
// return next.handle()을 실행하는 순간 라우트의 로직이 전부 실행되고 응답이 Observable로 반환
return next
.handle()
.pipe( // pipe에는 우리가 원하는 RxJS에서 지원하는 모든 함수를 넣어줄 수 있고 함수들은 순서대로 실행
tap( // pipe 함수 안에서 순서가 tab() 함수를 지나갈 때마다 전달되는 값들을 모니터링 할 수 있음
(observable) => { // 가장 처음에 한 tap의 파라미터로 들어온 observable은 응답
console.log(observable); // 라우트 로직을 지나서 생성된 응답이 console.log()로 출력됨
}
),
map( // 응답 내용을 변형할 때 사용하는 map (tap은 변형은 못함)
(observable) => {
return { // return 해주는 것이 실제 응답으로 들어가는 것
message: "응답이 변경 됐습니다."
response: observable
}
),
tap( // 응답이 변형된 후 다시 출력
(observable) => {
console.log(observable);
}
),
);
}
}@Get()
@UseInterceptors(InterceptorExample)
getPosts() {
return this.postsService.findAll();
}위처럼 @UesInterceptors(LogInterceptor)로 사용 가능
이제 Postman으로 Api 콜을 해보면, 다음과 같이 서버 로그에 찍힘
[REQ] /posts 11/30/2023, 1:14:10 AM # next.handle() 하기 전(라우트 로직 실행 전)에 찍힌 로그
{ # next.handle().pipe() 안의 첫 함수인 tap의 console.log(observable);의 결과
data: [
PostsModel {
id: 1,
updatedAt: 2023-11-29T23:01:34.750Z,
# 생략.. (map으로 응답 변환)
{ # 두 번째 tap의 결과
message: "응답이 변경 됐습니다.",
response: {
data: [ [PostsModel] ],
cursor: { after: 135 },
count: 1,
next: "~~"
}
}map()의 결과로 다음과 같이 응답도 바뀜 (message 추가, 원래 응답이 response안에 들어간 모습
// interceptor/log.interceptor.ts
import ...
@Injectable()
export class LogInterceptor implements NestInterceptor {
intercept(
context: ExecutionContext,
next: CallHandler<any>,
): Observable<any> {
const now = new Date();
const req = context.switchToHttp().getRequest();
const path = req.originalUrl;
const method = req.method;
const randomId = getRandomId();
const reqString = `${LogColorCode.blue}[REQ - ${randomId}]${LogColorCode.reset}`;
const pathString = `${LogColorCode.leaf}[${method} ${path}]${LogColorCode.reset}`;
const reqTimeString = `${LogColorCode.warmgray}[${now.toLocaleString(
'kr',
)}]${LogColorCode.reset}`;
let userString: string;
let reqLog = `${reqString} ${pathString} ${reqTimeString}`;
if (req.user) {
userString = `${LogColorCode.purple}[${req.user.username}]${LogColorCode.reset}`;
reqLog += ` ${userString}`;
}
Logger.log(reqLog);
return next.handle().pipe(
catchError((error) => {
const errTime = new Date();
const errString = `${LogColorCode.red}[ERR - ${randomId}]${LogColorCode.reset}`;
const errTimeString = `${
LogColorCode.warmgray
}[${errTime.toLocaleString('kr')} - ${
errTime.getMilliseconds() - now.getMilliseconds()
}ms]${LogColorCode.reset}`;
let errLog = `${errString} ${pathString} ${errTimeString}`;
if (req.user) {
errLog += ` ${userString}`;
}
Logger.error(errLog);
Logger.error(error);
throw error;
}),
tap(() => {
const resTime = new Date();
const resString = `${LogColorCode.orange}[RES - ${randomId}]${LogColorCode.reset}`;
const resTimeString = `${
LogColorCode.warmgray
}[${resTime.toLocaleString('kr')} - ${
resTime.getMilliseconds() - now.getMilliseconds()
}ms]${LogColorCode.reset}`;
let resLog = `${resString} ${pathString} ${resTimeString}`;
if (req.user) {
resLog += ` ${userString}`;
}
Logger.log(resLog);
}),
);
}
}이제 이 LogInterceptor를 사용하여 api콜을 하면
위와 같이 로그가 찍힘
이렇게 요청과 응답을 모두 만질 수 있는 것은 Interceptor밖에 없어서 많이 사용되는 것
트랜잭션은 queryRunner를 생성하고, 성공하면 커밋, 실패하면 롤백하는 과정을 가짐
→ Interceptor를 활용해서 쿼리러너 생성, 응답이 성공적으로 나오면 커밋, 중간 과정에서 에러가 발생하면 롤백을 하게 하고자 함
// interceptor/transaction.interceptor.ts
import ...
@Injectable()
export class TransactionInterceptor implements NestInterceptor {
constructor(private readonly dataSource: DataSource) {}
async intercept(
context: ExecutionContext,
next: CallHandler<any>,
): Promise<Observable<any>> {
const req = context.switchToHttp().getRequest();
const path = req.originalUrl;
const method = req.method;
const queryRunner: QueryRunner = this.dataSource.createQueryRunner();
await queryRunner.connect();
await queryRunner.startTransaction();
const startTime = new Date();
const randomId = getRandomId();
const transactionString = `${LogColorCode.orange}[Transaction - ${randomId}]${LogColorCode.reset}`;
const pathString = `${LogColorCode.leaf}[${method} ${path}]${LogColorCode.reset}`;
const startTimeString = `${
LogColorCode.warmgray
}[${startTime.toLocaleString('kr')}]${LogColorCode.reset}`;
const transactionMentString = `- ${LogColorCode.orange}Transaction Start${LogColorCode.reset}`;
const transactionStartLog = `${transactionString} ${pathString} ${startTimeString} ${transactionMentString}`;
Logger.log(transactionStartLog);
req.queryRunner = queryRunner;
return next.handle().pipe(
catchError(async (error) => {
await queryRunner.rollbackTransaction();
await queryRunner.release();
const rollbackTime = new Date();
const rollbackString = `${LogColorCode.red}[Transaction - ${randomId}]${LogColorCode.reset}`;
const rollbackTimeString = `${
LogColorCode.warmgray
}[${rollbackTime.toLocaleString('kr')}]${LogColorCode.reset}`;
const rollbackMentString = `- ${LogColorCode.red}Transaction Rollback${LogColorCode.reset}`;
const rollbackLog = `${rollbackString} ${pathString} ${rollbackTimeString} ${rollbackMentString}`;
Logger.error(rollbackLog);
Logger.error(error);
throw new InternalServerErrorException("Can't process your request");
}),
tap(async () => {
await queryRunner.commitTransaction();
await queryRunner.release();
const commitTime = new Date();
const commitString = `${LogColorCode.aqua}[Transaction - ${randomId}]${LogColorCode.reset}`;
const commitTimeString = `${
LogColorCode.warmgray
}[${commitTime.toLocaleString('kr')} - ${
startTime.getMilliseconds() - commitTime.getMilliseconds()
}ms]${LogColorCode.reset}`;
const commitMentString = `- ${LogColorCode.aqua}Transaction Commit${LogColorCode.reset}`;
const commitLog = `${commitString} ${pathString} ${commitTimeString} ${commitMentString}`;
Logger.log(commitLog);
}),
);
}
}
를 더 파보고 싶다면
사실 tap과 map만 알아도 많은 일을 할 수 있음