개발환경 : Typescript, NestJS, DataDog Agent가 세팅되어 있음
서론
우리 팀은 자체 제작 로깅 모듈, 트레이싱 전용 객체를 만들어 로깅을 하고 있었다. 그러나 다른 팀과 로깅 모듈을 통일시키고, 기존에 사용 중이었던 데이터독으로 트레이싱도 가능케 하자는 의견이 나와 진행하게 되었다. 이에 데이터독에서 제공하는 dd-trace에 대해 알아보고 적용하기까지의 이야기를 간략하게 정리해보기로 했다.
APM이란?
APM이란 Application Performance Monitoring 의 줄임말로, 애플리케이션 성능 모니터링를 말한다. APM은 말 그대로 실시간 데이터를 이용해 애플리케이션의 성능과 유저의 사용 경험을 모니터링하는 프로세스이다. APM 서비스는 skywalking, pinpoint, scouter, elastic apm 등이 있다.
간단한 예시를 들어보자. 강아지를 자랑할 수 있는 사이트에서 로딩되는 데 걸리는 시간이 너무 길다는 유저의 피드백을 받았다고 해보자. 언제 어디서 어떻게 할 때 얼마나 오래 걸리는지 따로 전달하지 않았다면, 개발자는 아래 사항들+@를 의심하며 추적을 해야한다.
- 인프라 : 메모리 사용량, CPU 사용률
- 백엔드 : 데이터베이스 쿼리 성능
- 프론트엔드 : 웹 브라우저 렌더링
- 유저 : 환경(와이파이, 데이터, 위치 등)
그러나 직접 디버깅을 해보며 추적을 하는 건 시간을 오래 소요하며, 기록된 로그가 없다면 디버깅이 더욱 힘들어진다. apm을 도입하면 이런 식의 트랜잭션, 이슈 추적에 용이하여 개발자가 이슈를 빠르게 파악할 수 있고, 유저가 인지하기 전에 예방이 가능해진다. 또한 모니터링된 데이터를 분석해 필요한 지표를 얻을 수도 있다. 때문에 apm 도입은 운영 리소스의 절약과 사용자의 긍정적인 사용 경험으로 이어질 수 있다.
dd-trace
데이터독에서는 dd-trace 이라는 APM 서비스를 제공하고 있다.dd-trace의 장점은 당연하게도 데이터독과의 높은 호환성이다. 우리 팀의 경우 이미 데이터독을 사용하고 있기 때문에 다른 apm 서비스를 접목시키기 보다는 데이터독에서 지원하는 APM을 사용하는 게 더 효율적이라 판단했다. nestjs를 지원하고 있지 않아 프로젝트 단위로 사용하려면 모듈을 커스텀해야 한다는 단점이 있으나, 비공식 nestjs-ddtrace 라이브러리 가 존재하고 있어 이를 사용해도 무방하다. 팀에서는 라이브러리를 import 하는 대신 파일들을 직접 가져와 사용하기로 했다.
Pino logger
pino 로거는 로거 라이브러리 중 하나로 로깅에 필요한 최소한의 리소스를 사용한다는 특징이 있다. 타 라이브러리에 비해 업데이트 주기도 빠르며 스토틀링Throttling 기법을 사용해 주어진 시간 동안 중복되는 요청에 대해 새 메세지를 생성하는 대신 기존 메세지에 정보를 더하는 방법을 사용한다. 이 기법을 통해 로깅 리소스를 보다 절약할 수 있을 것이다. winston에 비해 인지도는 낮은 편이나 dd-trace에서 공식적으로 full support가 되는 라이브러리이고 사용법이 간단하여 적용에 큰 문제가 되지는 않는다. 단점은 winston에 비해 풀이 작아 자료가 많지 않다는 점. (한국어로 된 자료는 손에 꼽을 수준이다.)
QuickStart
1. 필요 라이브러리 설치
yarn add dd-trace nestjs-pino pino-http pino-pretty
yarn remove winston
2. pino logger 적용
a. config
import 'reflect-metadata';
import { Params } from 'nestjs-pino';
import { RequestMethod } from '@nestjs/common';
const isLocal = 'local' === process.env.NODE_ENV || '';
['local'].includes(process.env.NODE_ENV || '');
const loggerConfigOptions: Params = {
pinoHttp: {
base: {
hostname: undefined,
},
level: 'debug',
formatters: {
level: (label) => {
return { level: label.toUpperCase() };
},
},
timestamp: () => `,"timestamp":"${new Date(Date.now()).toISOString()}"`,
customSuccessMessage: (res) => {
return `Request completed :: ${res.method}: ${res.url}`;
},
hooks: {
logMethod(inputArgs, method) {
const logObject = inputArgs[0] as any;
if (logObject.res && logObject.res.statusCode >= 400) {
return false;
}
return method.call(this, ...inputArgs);
},
},
transport: isLocal ? { target: 'pino-pretty' } : undefined,
},
exclude: [{ method: RequestMethod.GET, path: '/' }],
};
export { loggerConfigOptions };// app.module.ts
// ...생략
import { LoggerModule as PinoLoggerModule } from 'nestjs-pino';
import { loggerConfigOptions } from './modules/logger/loggerConfig';
@Module({
imports: [
// ...생략
PinoLoggerModule.forRoot({ ...loggerConfigOptions }),
],
// ...생략
})
export class AppModule {}
b. 생성자 주입
import { InjectPinoLogger, PinoLogger } from 'nestjs-pino';
@Injectable()
export class ExampleService {
constructor(
@InjectPinoLogger(ExampleService.name)
private readonly logger: PinoLogger,
) {}
c. 로깅 처리
winston은 파라미터 순서가 msg, obj 였다. pino의 경우 파라미터 순서가 반대인 obj, msg 이다.
// 로깅 예시
this.logger.debug({ accountAddress, tokenReqDto }, `generateToken method is requested`);
// 출력 예시
[16:04:58.863] INFO: generateToken method is requested
req: {
"id": 1,
"method": "POST",
"url": "/api/v1/private/auth/token",
"query": {},
"params": {
"0": "v1/private/auth/token"
},
"headers": {
"content-type": "application/json",
"user-agent": "PostmanRuntime/7.34.0",
"accept": "*/*",
"cache-control": "no-cache",
"postman-token": "pooooostman-toooooken",
"host": "localhost:3000",
"accept-encoding": "gzip, deflate, br",
"connection": "keep-alive",
"content-length": "23"
},
"remoteAddress": "127.0.0.1",
"remotePort": 63411
}
context: "AuthController"
accountAddress: "some address"
tokenReqDto: {
"hashedPin": "00"
}
d. 에러 로깅
this.logger.error(error, error.message);
this.logger.error({err: error, …other objects, error.message})
pino에서는 error 객체를 obj 파라미터에 담으면 알아서 stack(+커스텀 에러라면 추가적인 Property까지)을 출력해준다.
만약 obj에 error 외 다른 객체도 담고 싶다면 err 이라는 property에 값을 담아야 error 객체로 인식한다.
그렇지 않으면 일반 객체로 인식하게 되어 stack이 출력되지 않는다…
(pino 로거에서 특정 객체에 대해 출력 방식을 커스텀할 수 있긴 하나 귀찮아서 그냥 err에 에러 객체를 담는 걸 추천한다.)
3. dd-trace 적용
a. dd-trace 파일 추가
nestjs-ddtrace 라이브러리를 import 했다면 이 과정을 거치지 않아도 된다.
dd-trace 디렉토리 내에 추가될 코드들은 다음과 같다. 코드에 대한 설명은 직접 만드신 분의 설명영상을 참고하자.
// constant.ts
export enum Constants {
SPAN_METADATA = 'DATADOG_SPAN_METADATA',
SPAN_METADATA_ACTIVE = 'DATADOG_SPAN_METADATA_ACTIVE',
TRACE_INJECTORS = 'DATADOG_TRACE_INJECTORS',
}// datadog-trace.module.ts
import { DynamicModule, Module } from '@nestjs/common';
import { FactoryProvider } from '@nestjs/common/interfaces/modules/provider.interface';
import { Constants } from './constants';
import { DecoratorInjector } from './decorator.injector';
import { Injector } from './injector.interface';
import { TraceService } from './trace.service';
@Module({})
export class DatadogTraceModule {
static forRoot(
options: {
/**
* if true, automatically add a span to all controllers.
*/
controllers?: boolean;
/**
* * if true, automatically add a span to all providers.
*/
providers?: boolean;
} = {},
): DynamicModule {
return {
global: true,
module: DatadogTraceModule,
providers: [TraceService, DecoratorInjector, this.buildInjectors(options)],
exports: [TraceService],
};
}
private static buildInjectors(options: { controllers?: boolean; providers?: boolean }): FactoryProvider {
return {
provide: Constants.TRACE_INJECTORS,
useFactory: async (...injectors: Injector[]) => {
for await (const injector of injectors) {
if (injector.inject) {
await injector.inject(options);
}
}
},
inject: [DecoratorInjector],
};
}
}// decorator.injector.ts
import { Injectable, Logger } from '@nestjs/common';
import { Controller, Injectable as InjectableInterface } from '@nestjs/common/interfaces';
import { MetadataScanner, ModulesContainer } from '@nestjs/core';
import { InstanceWrapper } from '@nestjs/core/injector/instance-wrapper';
import tracer, { Span } from 'dd-trace';
import { Constants } from './constants';
import { Injector } from './injector.interface';
@Injectable()
export class DecoratorInjector implements Injector {
private readonly metadataScanner: MetadataScanner = new MetadataScanner();
private readonly logger = new Logger();
constructor(private readonly modulesContainer: ModulesContainer) {}
public inject(options: { controllers?: boolean; providers?: boolean }) {
this.injectProviders(options.providers || false);
this.injectControllers(options.controllers || false);
}
/**
* Returns whether the prototype is annotated with @Span or not.
* @param prototype
* @returns
*/
private isDecorated(prototype: any): boolean {
return Reflect.hasMetadata(Constants.SPAN_METADATA, prototype);
}
/**
* Returns whether the prototype has already applied wrapper or not.
* @param prototype
* @returns
*/
private isAffected(prototype: any): boolean {
return Reflect.hasMetadata(Constants.SPAN_METADATA_ACTIVE, prototype);
}
/**
* Returns the span name specified in span annotation.
* @param prototype
* @returns
*/
private getSpanName(prototype: any): string {
return Reflect.getMetadata(Constants.SPAN_METADATA, prototype);
}
/**
* Tag the error that occurred in span.
* @param error
* @param span
*/
private static recordException(error: unknown, span: Span) {
span.setTag('error', error);
throw error;
}
/**
* Find providers with span annotation and wrap method.
*/
private injectProviders(injectAll: boolean) {
const providers = this.getProviders();
for (const provider of providers) {
if (injectAll) {
Reflect.defineMetadata(Constants.SPAN_METADATA, 1, provider.metatype);
}
const isProviderDecorated = this.isDecorated(provider.metatype);
const methodNames = this.metadataScanner.getAllMethodNames(provider.metatype.prototype);
for (const methodName of methodNames) {
const method = provider.metatype.prototype[methodName];
// If span annotation is attached to class, @Span is applied to all methods.
if (
(isProviderDecorated && !this.isAffected(method)) ||
(this.isDecorated(method) && !this.isAffected(method))
) {
const spanName = this.getSpanName(method) || `${provider.name}.${methodName}`;
provider.metatype.prototype[methodName] = this.wrap(method, spanName);
this.logger.log(`Mapped ${provider.name}.${methodName}`, this.constructor.name);
}
}
}
}
/**
* Find controllers with span annotation and wrap method.
*/
private injectControllers(injectAll: boolean) {
const controllers = this.getControllers();
for (const controller of controllers) {
if (injectAll) {
Reflect.defineMetadata(Constants.SPAN_METADATA, 1, controller.metatype);
}
const isControllerDecorated = this.isDecorated(controller.metatype);
const methodNames = this.metadataScanner.getAllMethodNames(controller.metatype.prototype);
for (const methodName of methodNames) {
const method = controller.metatype.prototype[methodName];
// If span annotation is attached to class, @Span is applied to all methods.
if (
(isControllerDecorated && !this.isAffected(method)) ||
(this.isDecorated(method) && !this.isAffected(method))
) {
const spanName = this.getSpanName(method) || `${controller.name}.${methodName}`;
controller.metatype.prototype[methodName] = this.wrap(method, spanName);
this.logger.log(`Mapped ${controller.name}.${methodName}`, this.constructor.name);
}
}
}
}
/**
* Wrap the method
* @param prototype
* @param spanName
* @returns
*/
private wrap(prototype: Record<any, any>, spanName: string) {
const method = {
// To keep function.name property
[prototype.name]: function (...args: any[]) {
const activeSpan = tracer.scope().active() || undefined;
const span = tracer.startSpan(spanName, { childOf: activeSpan });
return tracer.scope().activate(span, () => {
if (prototype.constructor.name === 'AsyncFunction') {
return prototype
.apply(this, args)
.catch((error: unknown) => {
DecoratorInjector.recordException(error, span);
})
.finally(() => span.finish());
} else {
try {
const result = prototype.apply(this, args);
return result;
} catch (error) {
DecoratorInjector.recordException(error, span);
} finally {
span.finish();
}
}
});
},
}[prototype.name];
// Flag that wrapping is done
Reflect.defineMetadata(Constants.SPAN_METADATA_ACTIVE, 1, prototype);
// Copy existing metadata
const source = prototype;
const keys = Reflect.getMetadataKeys(source);
for (const key of keys) {
const meta = Reflect.getMetadata(key, source);
Reflect.defineMetadata(key, meta, method);
}
return method;
}
/**
* Get all the controllers in the module container.
*/
private *getControllers(): Generator<InstanceWrapper<Controller>> {
for (const module of this.modulesContainer.values()) {
for (const controller of module.controllers.values()) {
if (controller && controller.metatype?.prototype) {
yield controller as InstanceWrapper<Controller>;
}
}
}
}
/**
* Get all the providers in the module container.
*/
private *getProviders(): Generator<InstanceWrapper<InjectableInterface>> {
for (const module of this.modulesContainer.values()) {
for (const provider of module.providers.values()) {
if (provider && provider.metatype?.prototype) {
yield provider as InstanceWrapper<InjectableInterface>;
}
}
}
}
}// injector.interface.ts
export interface Injector {
inject(options: { controllers?: boolean; providers?: boolean }): void;
}// span.decorator.ts
import { SetMetadata } from '@nestjs/common';
import { Constants } from './constants';
export const Span = (name?: string) => SetMetadata(Constants.SPAN_METADATA, name);// trace.service.ts
import { Injectable } from '@nestjs/common';
import tracer, { Span, Tracer } from 'dd-trace';
@Injectable()
export class TraceService {
public getTracer(): Tracer {
return tracer;
}
public getActiveSpan(): Span | null {
return tracer.scope().active();
}
}// tracing.ts
import tracer from 'dd-trace';
tracer.init({
logInjection: true,
});
export default tracer;// index.ts
export * from './trace.service';
export * from './span.decorator';
export * from './datadog-trace.module';
모든 파일을 추가하면 이렇게 보인다.
b. main.ts 에 pino 로거 추가
// main.ts
import './dd-trace/tracing'; // AppModule보다 import를 먼저 해야 트레이싱이 된다.
import { Logger as PinoLogger } from 'nestjs-pino';
// ...(중략)
const app = await NestFactory.create(AppModule, { bufferLogs: true });
app.useLogger(app.get(PinoLogger));
main.ts에 pino logger를 추가하면 이후 아래와 같이 로그에 dd 객체가 추가된다.
// 출력 예시
dd: {
"trace_id": "6362970217613089691",
"span_id": "352981399115346571",
"service": "kkr-wallet-api",
"version": "0.2.7"
}적용 후기
소규모 프로젝트를 진행할 때 로깅을 적용한 적은 있으나 그 필요성에 대해서 깊게 와닿지 않았다. 실무에서 오류 디버깅을 해보며 로깅의 중요성을 알게 되었으나 기존의 커스텀 로그를 어떻게 발전시켜야 할 지에 대해 어려움을 겪고 있었다. 이번에 dd-trace를 적용하면서 APM의 개념도 알게 되고 이를 적용하는 법에 대해서도 공부하게 되었다. pino 라는 새로운 로그 라이브러리도 사용해보게 되었는데, 개인적으로 winston이 익숙하긴 하지만 다소 무겁다는 느낌이 있었다. pino는 처음 사용해보는 거였음에도 적용이 쉽고 빠르게 적응할 수 있는 게 큰 장점으로 다가왔다. dd-trace는 아직 스테이징 서버에서만 쓰이고 있어 실서비스에서 얼마나 효율적으로 쓰일 지는 잘 모르는 상태지만, 좋은 결과를 얻게 되길 기대하고 있다.
참고 자료
https://docs.datadoghq.com/ko/tracing/
https://www.npmjs.com/package/dd-trace
https://stackoverflow.com/questions/62359024/how-i-can-serialize-an-error-object-with-pino
https://youtu.be/Zs_werD3bP8?feature=shared
https://cocologue-study.tistory.com/entry/APM이란-종류와-흔한-이슈-발견-방법
'기타 딩가딩가' 카테고리의 다른 글
| 2023년 회고, 2024년 다짐 (2) | 2024.01.01 |
|---|---|
| [React] 대시보드 특화 프레임워크 Refine 맛보기 (0) | 2022.11.18 |
| [React] React 간단 맛보기 (0) | 2022.11.18 |
| [디자인 패턴] 0. 들어가며 (0) | 2020.12.24 |