로깅(Logging)의 중요성은 다들 머리로는 이해하고 있지만, 서비스를 직접 운영해보지 않으면 중요성을 직접 체감하기는 쉽지 않다.|
대부분의 개발 단계에서는 응답이 잘 오는지, 데이터가 예상대로 바뀌는지 정도만 확인하면 충분하기 때문이다.
그래서 보통은 간단한 로그를 찍어보면서 기능을 완성해 나간다.
하지만 Production 환경은 전혀 다르다.
테스트 환경에서는 한 번도 보지 못한 에러가 발생하는데, 단순 로직의 문제가 아닌 특정 트래픽 패턴에서만 발생하는 문제나 트랜잭션 경합, 데이터베이스 데드락, 타이밍 이슈 등이 발생하기도 한다.
이런 문제들은 재현 자체가 거의 불가능한 경우가 많다.
그리고 이때 제대로 된 로깅 체계가 없다면 배포 이후에는 그저 문제가 발생했다는 사실만 알 뿐, 왜 발생했는지는 알 수 없게 된다.
기존 로깅 체계
우리는 이전까지 Metabase를 활용한 간단한 로깅 구조를 사용하고 있었다.
구성은 다음과 같았다.
- Metabase와 로깅 서버는 Fargate 환경에서 운영
- 로깅 데이터 / 백업본은 EFS에 저장
- 각 애플리케이션에서 엔드포인트, 요청 / 응답, 지연 시간을 로깅 서버로 전송
이 방식은 단순해서 빠르게 도입 가능했고, 어떤 API에서 오류가 났는지 정도는 바로 확인 가능했다.
하지만 서비스가 커질수록 한계점을 드러내기 시작했다.
API 단위까지만 알 수 있고, 어디에서 오류가 발생했는지는 알 수 없다.
그리고 내부 로직이 복잡해질수록 로그 정보가 턱없이 부족하며, 서비스 간 호출이 늘어나면 흐름 자체를 추적할 수 없다.
그래서 우리는 내부 흐름까지 자세하게 로깅 하기 위해 Grafana를 도입하기로 하였다.
Grafana는 Trace와 Span을 기반으로 전체 흐름을 로깅할 수 있다.
Trace는 하나의 요청 Context인데, 내부에는 Span 단위로 API Gateway부터, 내부 비즈니스 로직, DB Query, 외부 API 호출까지 전부 기록할 수 있다.
그래서 기존에는 “API X에서 오류 발생” 만 알 수 있었다면, Grafana를 도입한 이후에는 “API X → A 서비스 호출 → B 함수 내부에서 DB 트랜잭션 대기 중 데드락 발생” 와 같이 한 눈에 파악할 수 있게 되었다.
이제 Controller에서부터 내려가면서 함수들 쿼리를 다 보면서 추측하는 디버깅은 안 해도 됐다.
이 글에서는 우리가 Grafana를 어떻게 Integration 했는지, Grafana에서 어떤 정보를 볼 수 있는지, 그리고 우리가 실제 운영에서 어떻게 활용하고 있는지를 중심으로 정리해보려고 한다.
구현
1. OpenTelemetry SDK 초기화
어떤 데이터를 생성하고, 어디로 내보낼지 정의하는 단계이다.
OpenTelemetry SDK는 로그(Log), 트레이스(Trace), 메트릭(Metric)을 각각 독립적으로 처리하지만, 하나의 런타임 안에서 통합 관리된다.
const logExporter = new OTLPLogExporter({
url: process.env.OTEL_EXPORTER_OTLP_LOGS_ENDPOINT,
});
const logRecordProcessor = new BatchLogRecordProcessor(logExporter);
const traceExporter = new OTLPTraceExporter({
url: process.env.OTEL_EXPORTER_OTLP_TRACES_ENDPOINT,
});
const otlpSpanProcessor = new BatchSpanProcessor(traceExporter);
const langfuseSpanProcessor = new LangfuseFilteredSpanProcessor();
// Initialize OpenTelemetry SDK
const sdk = new NodeSDK({
logRecordProcessor,
spanProcessors: [otlpSpanProcessor, langfuseSpanProcessor],
instrumentations: [
getNodeAutoInstrumentations({
// ...
}),
// ...
new PinoInstrumentation({
logKeys: {
traceId: 'traceId',
spanId: 'spanId',
traceFlags: 'traceFlags',
},
}),
],
});
sdk.start();몇몇 API는 LLM Call이 있어서 이는 Langfuse로도 로깅을 한다.
하나의 Span은 여러 SpanProcessor에 의해 동시에 소비될 수 있어서, 같은 Span이 Grafana Tempo로도 가고 Langfuse로도 갈 수 있다.
아래 설정 덕분에 HTTP 서버로 들어오는 모든 요청의 시작 지점에서 Root Span을 생성한다.
'@opentelemetry/instrumentation-http': { enabled: true }이후 생성되는 모든 Span의 부모가 되고, 하나의 요청 단위인 Trace의 시작점이 된다.
이외에도 Middleware나 Router 같은 레이어에 선택적으로 Span을 생성하지 않도록 하거나, 특정 API Endpoint는 로깅 대상에서 제외하도록 할 수 있다.
- 우리같은 경우에는 Middleware, Router, Request Handler는 Span을 생성하지 않도록 하였다.
- 그리고 Token Refresh 관련 API나 Health API는 로깅 대상에서 제외하도록 했다.
PinoInstrumentation도 중요한데, logger.info 같은 로깅 함수를 호출할 때 기본적으로 아래와 같은 데이터로 로깅이 된다.
{
"level": "info",
"msg": "Character Created"
}Loki에 Log가 쌓이긴 하지만, Tempo의 Trace와 연결할 수 없다.
위 로그 데이터만으로는 어떤 Trace와 연결돼 있는지 알 수 없기 때문이다.
Pino는 Context에 있는 traceId, spanId 와 같은 데이터를 로그에 추가해서 로그와 Trace를 연결해주는 역할을 한다.
{
"level": "info",
"msg": "Character Created",
"traceId": "abc123",
"spanId": "def456"
}2. Trace Decorator
Root Span 만으로는 깊은 분석을 할 수 없다.
이 요청에서 어떤 서비스 로직이 실행되었는지, 어디에서 시간이 가장 많이 소요되었는지, 어떤 입력값으로 호출되었는지, 실패가 발생했다면 어느 단계에서 발생했는지에서 자세히 알아야 로깅이 의미가 있다.
따라서 서비스 / 도메인 단위의 비즈니스 로직 계측이 필요하고, 이를 담당하는 것이 @Trace Decorator이다.
@Trace는 메서드 실행을 감싸서 다음을 수행한다.
- 현재 활성화된 OpenTelemetry Context를 가져온다
- 해당 Context를 부모로 하는 새로운 Span을 생성한다
- 메서드 실행 전후를 Span의 생명주기로 감싼다
- 실행 결과 또는 예외를 Span에 기록한다
재귀적으로 Span을 생성하고 구성함으로써, 실행 흐름과 똑같이 기록이 되며, 코드 구조와도 같아서 쉽게 분석이 가능하다.
export function Trace(options: TraceOptions = {}): MethodDecorator {
const {
spanName,
traceParams = true,
enableLogging = true,
maxDepth = 2,
additionalRedactFields = [],
attributes = {},
} = options;
return function (
target: object,
propertyName: string | symbol,
descriptor: PropertyDescriptor,
): PropertyDescriptor {
const originalMethod = descriptor.value
const tracer = trace.getTracer('backend', '1.0.0');
descriptor.value = function (...args) {
const executionContext = createExecutionContext(
target,
propertyName,
spanName,
enableLogging,
);
// 이 Span은 자동으로 부모 Span의 자식으로 들어감
const span = createSpan(tracer, executionContext, args, attributes);
try {
// 실제 함수 실행
const result = originalMethod.apply(this, args);
// 실행 후 결과 로깅
if (result && typeof result === 'object' && 'then' in result) {
const promise = result
return handleAsyncResult(promise, span, executionContext);
}
span.setStatus({ code: SpanStatusCode.OK });
logMethodSuccess(executionContext, result);
span.end();
return result;
} finally {
span.end();
}
};
return descriptor;
};
}3. Trace Decorator의 사용
이제 Span을 만들고자 하는 함수에 Decorator를 붙여준다.
@Injectable()
export class CommunityBusinessService {
// ...
@Trace()
async validateCharacterExists(characterId: string): {
// ...
}
}Service 계층 함수에는 대부분 Trace Decorator가 붙어있고, 우리는 데이터베이스 쿼리 성능 로깅을 위해 일부 Repository 계층의 함수에도 Trace Decorator를 붙였다.
getById, findAll 같은 쿼리가 간단하고 쉽게 성능이 예측이 되는 함수에는 Trace Decorator를 붙일 필요가 없다.
오히려 모든 함수에 붙이면 Span의 개수가 급증하여 비용이 많이 나올 수 있다.
4. PerformanceInterceptor 구현
지금까지의 설정을 통해 Trace로 요청의 흐름과 Log로 그 요청에서 어떤 일이 발생하는지 볼 수 있도록 하였다.
하지만 위 설정만으로는 서버 상태가 정상인지, 응답 속도가 점점 느려지고 있는지 등은 바로 파악하기 힘들다.
따라서 Metric을 수집해서 개별 요청이 아닌, 전체 시스템 상태에 대한 모니터링이 필요하다.
우리 같은 경우에는 NestInterceptor를 구현해서 Performance를 측정하고, 느린 요청은 따로 추가로 기록하도록 하였다.performance.duration_ms에 대해 평균을 보고 대부분의 요청 처리 시간을 파악할 수 있고, p90, p99로 비정상 상태에 대해서도 모니터링 할 수 있다.
@Injectable()
export class PerformanceInterceptor implements NestInterceptor {
private readonly meter = metrics.getMeter(
'backend-performance',
'1.0.0',
);
private readonly slowRequestCounter = this.meter.createCounter(
'slow_requests_total',
{
description: 'Number of slow requests (>1s)',
},
);
private readonly verySlowRequestCounter = this.meter.createCounter(
'very_slow_requests_total',
{
description: 'Number of very slow requests (>3s)',
},
);
private readonly requestDurationHistogram = this.meter.createHistogram(
'request_duration_ms',
{
description: 'Request duration in milliseconds',
},
);
intercept(context: ExecutionContext, next: CallHandler) {
const request = context
.switchToHttp()
.getRequest<RequestWithMethodAndUrl>();
const { method } = request;
const { url } = request;
const start = Date.now();
const span = trace.getActiveSpan();
return next.handle().pipe(
tap({
next: () => {
const duration = Date.now() - start;
this.requestDurationHistogram.record(duration, {
method: String(method),
endpoint: String(url),
status: 'success',
});
span?.setAttributes({
'performance.duration_ms': duration,
'performance.is_slow': duration > 3000,
'performance.is_very_slow': duration > 5000,
});
if (duration > 3000) {
this.slowRequestCounter.add(1, {
method: String(method),
endpoint: String(url),
});
if (duration > 5000) {
this.verySlowRequestCounter.add(1, {
method: String(method),
endpoint: String(url),
});
}
},
error: (error: Error) => {
const duration = Date.now() - start;
this.requestDurationHistogram.record(duration, {
method: String(method),
endpoint: String(url),
status: 'error',
});
span?.setAttributes({
'performance.duration_ms': duration,
'performance.failed': true,
});
span?.recordException(error);
},
}),
);
}
}로그 처리 아키텍쳐
위에서 설명한 백엔드 구현을 통해, Log/Trace/Metric 데이터를 보낼 수 있게 되었다.
그러면 이 데이터들은 어떻게 / 어디로 보내지는 걸까?
우리는 EKS 환경에서 앱을 운영하고 있고, 각 노드에는 Grafana Alloy (DaemonSet)가 하나 씩 배포되어 있다.
백엔드 애플리케이션은 관측 데이터를 생성한 뒤, 이를 OTLP(OpenTelemetry Protocol) 를 통해 Grafana Alloy로 전송한다.
이때 애플리케이션은 Loki, Tempo, Mimir와 같은 구체적인 스토리지의 존재를 전혀 알지 못한다.
백엔드는 OpenTelemetry 표준 형식으로 데이터를 생성하고, OTLP 엔드포인트로 전송하기만 하면 된다.
Open Telemetry란?
로그, 트레이스, 메트릭을 표준화된 방식으로 생성·전송하기 위한 표준
애플리케이션이 OTLP로만 데이터를 전송하면 알아서 분기해서 처리
Grafana Alloy란?
OpenTelemetry Collector 기반으로 구성된 수집기(Collector)
Alloy는 Grafana Cloud와 연동되어 애플리케이션으로부터 전달받은 OTLP 데이터를 데이터의 종류에 따라 적절한 스토리지로 분기한다.
정리하자면, 백엔드에서 생성된 Log/Trace/Metric 데이터는 OLTP를 통해 Grafana Alloy로 전달되고, Alloy는 이를 분기하여 Log는 Loki, Trace는 Tempo, Metric은 Mimir에 저장한다.
Grafana는 이 저장소들을 데이터 소스로 사용해 관측 데이터를 시각화하여 사용자에게 보여준다.
Grafana Dashboard
Grafana Dashboard 는 자주 사용하는 패널을 등록해서 그래프 / 표 형태로 쉽게 볼 수 있는 공간이다.
우리가 대시보드 내에 등록해놓은 주요 패널은 HTTP 요청 처리 시간, 주요 API들의 p50, p95, p99 그래프 등이 있다.
대시보드에 패널을 등록할 때는 아래와 같이 TraceQL 문법으로 원하는 Service, Span 등을 Filter 해서 시각화 할 수 있다.
Grafana Drilldown
1. Logs
2. Traces
3. Metrics
Grafana Explore
아래와 같이 오류가 났을 때, 그 Trace를 분석해보면 어디서 오류가 났는지 특정할 수 있다.@Trace가 붙은 함수들에 대해 Span이 재귀적으로 생기기 때문에 Service / Repository 계층까지 로깅이 되어서 오류 위치를 정확히 파악할 수 있다.
각 Span을 열어보면, 어떤 엔드포인트에서 발생했는지, 어떤 함수에서 발생했는지, 오류 메시지와 함께 매우 자세히 볼 수 있다.
우리는 어떻게 사용하고 있나?
1. 주요 엔드포인트의 p50, p95, p99 모니터링
우리는 여러 API의 지연 통계를 주기적으로 모니터링 하면서 비효율적인 API나 데이터베이스 쿼리가 있는지 분석하고 있다.
- Create Branch API
- Prepare Inference API
- Chat Records API
- Chatlist API
- Browsing API
- Create / Update Character API
- …등등
Trace 내에 어떤 함수에서 얼마나 지연되고 있는지 파악 가능하므로, 그 함수에서 호출하는 데이터베이스 쿼리를 분석하면 지연 원인을 쉽게 찾을 수 있다.
애초에 인덱스와 스키마 설계를 꼼꼼히 하고 들어가기 때문에 데이터베이스 쿼리를 최적화 시킨 적은 거의 없었다.
이전에 Delete User API 에서 시간이 지나치게 오래 걸리는 문제가 있었는데, Cascade 옵션 때문에 연결된 모든 리소스가 지워지느라 오래 걸리는 이슈였다.
그래서 User에 Soft Delection을 도입했던 기억이 난다.
2. Backend Error Alert
우리는 아래와 같이 디스코드 웹훅과 연동하여 주기적으로 백엔드 에러 알람을 보내도록 하고 있다.
View Trace를 누르면 바로 Grafana Trace Detail을 볼 수 있어서 바로 오류 분석을 할 수 있다.
3. 느린 엔드포인트는 즉시 알림
백엔드에서 1초 이상, 5초 이상 걸린 Span은 Interceptor에서 따로 수집하도록 처리했는데, 5초 이상은 바로 디스코드 웹훅으로 알림이 오도록 해서 바로 그 원인을 파악하도록 했다.
마무리
Grafana를 도입한 이후, 가장 크게 달라진 점은 대응 속도와 심리적 안정감이었다.
에러가 발생하면 알림이 디스코드로 즉시 전달되고, 문제가 있다는 사실을 나중에 로그를 뒤져서 알게 되는 일이 사라졌다.
이제는 발생과 동시에 인지하고 대응할 수 있는 구조가 되었다.
또 하나의 변화는 문제 분석 방식 자체였다.
Trace / Span 기반으로 요청 흐름이 모두 기록되다 보니 정확히 어느 함수, 어느 구간에서 지연이나 오류가 발생했는지 알 수 있어서, 사실상 문제의 원인이 되는 함수 하나만 보면 되는 수준이었다.
그 결과 문제 해결 속도는 체감할 정도로 빨라졌다.
물론 가장 이상적인 건 애초에 오류가 나지 않는 구조를 만드는 것이다.
하지만 현실적으로 모든 상황을 예측하고, 모든 케이스를 사전에 막는 건 거의 불가능에 가깝다.
트래픽 패턴, 외부 의존성, 데이터 상태는 언제든 예상 밖의 조합을 만들어낸다.
그래서 중요한 건 오류가 났을 때 즉시 이해하고, 빠르게 복구할 수 있는 구조를 만드는 것이라고 생각하게 되었다.
댓글 남기기