OpenTelemetry 데코레이터를 직접 만들 때 무너지는 것들

자동 계측 라이브러리를 붙이면 HTTP 요청과 DB 쿼리에 스팬이 생깁니다. 그런데 정작 알고 싶은 것은 그 사이입니다. 요청 하나가 6초 걸렸는데 DB는 200ms였다면, 나머지 5.8초가 어디에 쓰였는지는 자동 계측이 알려 주지 않습니다.

도메인 함수에 직접 스팬을 붙여야 하고, 매번 with 블록을 쓰는 대신 데코레이터를 만들게 됩니다. 몇 줄이면 될 것 같은 작업인데, 실제로 붙여 보면 스팬 길이가 0ms로 찍히거나 예외 이벤트가 두 개씩 달리거나 프레임워크가 깨집니다. 이 글에서는 그 지점들을 하나씩 정리합니다. 예시는 Python이지만 원인은 대부분 언어 공통입니다.

1. 가장 단순한 구현

시작은 대개 이렇습니다.

import functools
from opentelemetry import trace

tracer = trace.get_tracer(__name__)

def traced(func):
    @functools.wraps(func)
    def wrapper(*args, **kwargs):
        with tracer.start_as_current_span(func.__name__):
            return func(*args, **kwargs)
    return wrapper

동기 함수에는 잘 동작합니다. 문제는 여기서부터입니다.

2. async 함수를 감싸면 스팬이 아무것도 재지 않는다

같은 데코레이터를 코루틴 함수에 붙이면 이렇게 됩니다.

@traced
async def fetch_orders(user_id):
    await asyncio.sleep(2)          # 실제로 2초 걸린다
    return [...]

트레이스에는 0ms 남짓한 스팬이 찍힙니다. 이유는 func(*args, **kwargs)가 하는 일에 있습니다. 코루틴 함수를 호출하면 본문이 실행되는 것이 아니라 코루틴 객체가 즉시 반환됩니다. with 블록은 그 객체를 받는 순간 끝나고, 실제 작업은 호출자가 await할 때 블록 바깥에서 실행됩니다.

결과가 두 가지입니다. 스팬 길이가 실제 소요 시간과 무관해지고, 함수 본문이 만드는 자식 스팬들이 이 스팬이 아닌 다른 부모에 붙습니다. 트레이스 그림이 조용히 틀어지는데, 스팬 자체는 존재하므로 계측이 잘 되고 있다고 착각하기 쉽습니다.

동기와 비동기를 나눠야 합니다.

import inspect

def traced(func):
    if inspect.iscoroutinefunction(func):
        @functools.wraps(func)
        async def async_wrapper(*args, **kwargs):
            with tracer.start_as_current_span(func.__qualname__):
                return await func(*args, **kwargs)   # 블록 안에서 await
        return async_wrapper

    @functools.wraps(func)
    def sync_wrapper(*args, **kwargs):
        with tracer.start_as_current_span(func.__qualname__):
            return func(*args, **kwargs)
    return sync_wrapper

같은 함정이 제너레이터에도 있습니다. 제너레이터 함수를 호출하면 제너레이터 객체가 반환될 뿐 본문은 첫 next() 때 실행됩니다. inspect.isgeneratorfunction으로 분기해 yield from으로 감싸야 하는데, 여기서는 컨텍스트 detach 순서 문제가 추가로 생깁니다. 그 부분은 따로 다룰 만한 주제라 여기서는 감지해서 명시적으로 거부하는 것이 안전한 기본값이라는 것만 짚습니다.

    if inspect.isgeneratorfunction(func) or inspect.isasyncgenfunction(func):
        raise TypeError(f"{func.__qualname__}: 제너레이터는 이 데코레이터로 감쌀 수 없다")

조용히 틀린 스팬을 만드는 것보다 시작할 때 터지는 편이 낫습니다.

3. 예외를 손으로 기록하면 두 번 기록된다

다음으로 붙이는 것이 예외 처리입니다. 흔한 형태는 이렇습니다.

try:
    return func(*args, **kwargs)
except Exception as exc:
    span.set_status(Status(StatusCode.ERROR, str(exc)))
    span.record_exception(exc)
    raise

문서 예제에도 이 패턴이 나오기 때문에 자연스러워 보입니다. 그런데 start_as_current_span의 시그니처를 보면 기본값이 이미 잡혀 있습니다.

start_as_current_span(name, context=None, kind=SpanKind.INTERNAL,
                      attributes=None, links=None, start_time=None,
                      record_exception=True, set_status_on_exception=True,
                      end_on_exit=True)

파라미터 설명은 이렇습니다.

record_exception: Whether to record any exceptions raised within the context as error event on the span.

set_status_on_exception: Only relevant if the returned span is used in a with/context manager. Defines whether the span status will be automatically set to ERROR when an uncaught exception is raised in the span with block.

둘 다 기본이 True입니다. 컨텍스트 매니저를 빠져나갈 때 예외가 있으면 SDK가 이미 예외 이벤트를 달고 상태를 ERROR로 세팅합니다. 여기에 손으로 한 번 더 하면 같은 예외에 이벤트가 두 개 붙습니다.

스택 트레이스가 통째로 들어가는 이벤트라 크기가 작지 않습니다. 예외가 잦은 경로라면 저장량이 두 배가 되고, 백엔드 UI에서도 같은 예외가 중복 표시됩니다.

정리하면 선택지는 둘입니다.

• SDK에 맡긴다. try/except를 아예 쓰지 않고 예외가 컨텍스트 매니저를 통과하게 둔다. 가장 단순하다.
• 직접 제어한다. record_exception=False, set_status_on_exception=False로 끄고 원하는 대로 기록한다.

두 번째가 필요한 경우가 실제로 있습니다. NotFound처럼 예외지만 오류가 아닌 것을 ERROR로 만들고 싶지 않을 때입니다.

def traced(func=None, *, expected=()):
    if func is None:                 # @traced(expected=...) 형태로 쓸 때
        return functools.partial(traced, expected=expected)

    @functools.wraps(func)
    def wrapper(*args, **kwargs):
        with tracer.start_as_current_span(
            func.__qualname__,
            record_exception=False,
            set_status_on_exception=False,
        ) as span:
            try:
                return func(*args, **kwargs)
            except expected as exc:
                # 정상 흐름의 일부 - 상태는 건드리지 않고 흔적만 남긴다
                span.set_attribute("outcome", type(exc).__name__)
                raise
            except Exception as exc:
                span.set_status(Status(StatusCode.ERROR, str(exc)))
                span.record_exception(exc)
                raise
    return wrapper

어느 쪽이든 raise를 빼먹으면 안 됩니다. 계측 코드가 예외를 삼키면 함수의 동작 자체가 바뀝니다. 관측을 붙이다가 동작을 바꾸는 것이 가장 나쁜 결과입니다.

4. 성공했다고 상태를 OK로 세팅하지 않는다

대칭을 맞추고 싶어서 성공 경로에 set_status(Status(StatusCode.OK))를 넣게 되는데, 스펙이 이것을 말립니다.

Generally, Instrumentation Libraries SHOULD NOT set the status code to Ok, unless explicitly configured

그리고 상태에는 우선순위가 있습니다. Ok는 최종값이라 이후 변경이 무시됩니다. 즉 데코레이터가 성공 시점에 Ok를 박아 두면, 바깥에서 그 결과를 오류로 판정하고 싶어도 덮어쓸 수 없습니다. 예를 들어 함수는 정상 반환했지만 HTTP 계층에서 500으로 응답하는 경우가 그렇습니다.

Unset으로 두는 것이 기본이고, Ok는 애플리케이션이 명시적으로 "이건 성공으로 확정"이라고 판단할 때만 씁니다. 재사용 가능한 데코레이터는 라이브러리 쪽 규칙을 따라야 합니다.

5. 속성은 스팬을 만들 때 넘긴다

데코레이터에서 인자를 속성으로 남기고 싶을 때, 스팬을 만든 뒤 set_attribute로 붙이는 것이 자연스러워 보입니다. 스펙은 반대를 권합니다.

adding attributes at span creation is preferred to calling SetAttribute later, as samplers can only consider information already present during span creation

샘플러는 생성 시점의 속성만 봅니다. 나중에 붙인 값으로는 "이 테넌트의 요청은 전부 남긴다" 같은 규칙을 만들 수 없습니다. 데코레이터가 인자에서 속성을 뽑는다면 attributes=로 넘겨야 그 값이 샘플링에 쓰입니다.

def traced(func=None, *, attrs_from=None):
    if func is None:                 # @traced(attrs_from=...) 형태로 쓸 때
        return functools.partial(traced, attrs_from=attrs_from)

    @functools.wraps(func)
    def wrapper(*args, **kwargs):
        bound = inspect.signature(func).bind(*args, **kwargs)
        bound.apply_defaults()
        attrs = attrs_from(bound.arguments) if attrs_from else None
        with tracer.start_as_current_span(func.__qualname__, attributes=attrs):
            return func(*args, **kwargs)
    return wrapper


@traced(attrs_from=lambda a: {"tenant.id": a["tenant_id"]})
def process(tenant_id, payload): ...

여기서 주의할 것이 둘 있습니다.

속성 추출 자체가 비용입니다. signature().bind()는 호출마다 돌기에 무겁습니다. 시그니처는 데코레이터 적용 시점에 한 번만 계산해 두고 재사용해야 합니다.

추출한 값이 무엇인지 통제해야 합니다. 인자를 자동으로 전부 속성에 넣는 편의 기능을 만들면 언젠가 그 함수에 본문이나 자격 증명이 인자로 들어옵니다. 무엇을 넣을지는 스팬에 무엇을 넣지 말아야 하는가 (opens new window)에 정리했는데, 요약하면 허용 목록 방식이어야 하고 자동 수집은 만들면 안 됩니다.

6. 샘플링에서 빠진 스팬에는 계산을 하지 않는다

속성 값을 만드는 데 비용이 드는 경우가 있습니다. 직렬화하거나 길이를 세거나 해시를 계산하는 작업입니다. 이 스팬이 어차피 버려질 예정이라면 낭비입니다.

This flag SHOULD be used to avoid expensive computations of a Span attributes or events in case when a Span is definitely not recorded.

is_recording()이 거짓이면 스팬은 사실상 no-op이고 데이터는 즉시 버려집니다. 비싼 계산은 이 가드 뒤에 둡니다.

with tracer.start_as_current_span(name, attributes=cheap_attrs) as span:
    result = func(*args, **kwargs)
    if span.is_recording():
        span.set_attribute("result.digest", expensive_digest(result))
    return result

생성 시점 속성(cheap_attrs)은 가드 뒤로 옮길 수 없습니다. 그것이 있어야 샘플링 판정이 되기 때문입니다. 싼 것은 생성 시점에, 비싼 것은 is_recording() 뒤에가 정리된 규칙입니다.

7. functools.wraps를 빼면 프레임워크가 깨진다

데코레이터 관례라서 습관적으로 붙이지만, 계측 데코레이터에서는 실제 고장으로 이어집니다.

프레임워크가 함수 시그니처를 읽어 동작을 결정하는 경우가 많습니다. 요청 본문 모델을 만들거나 의존성을 주입할 때 타입 힌트를 봅니다. wraps 없이 *args, **kwargs 래퍼를 씌우면 프레임워크가 보는 시그니처가 그 래퍼의 것이 되어, 파라미터가 사라지거나 주입이 실패합니다.

@app.get("/orders/{order_id}")
@traced                      # wraps 없으면 order_id를 프레임워크가 못 본다
async def get_order(order_id: int, db: Session = Depends(get_db)): ...

functools.wraps는 __wrapped__를 남기므로 inspect.signature가 원본을 따라갑니다. 순서도 중요합니다. 라우트 데코레이터가 바깥, 계측이 안쪽이어야 프레임워크가 등록하는 대상이 래핑된 함수가 됩니다.

8. 데코레이터가 항상 답은 아니다

세 방식을 비교하면 이렇습니다.

	자동 계측	데코레이터	컨텍스트 매니저
코드 변경	없음	함수 단위 한 줄	블록마다 직접
스팬 경계	라이브러리가 결정	함수 = 스팬	원하는 범위
함수 일부만 재기	불가	불가	가능
async·제너레이터	라이브러리가 처리	직접 분기 필요	문제 없음
조건부 계측	어려움	어려움	쉬움

데코레이터의 전제는 **"함수 하나가 의미 있는 작업 단위"**라는 것입니다. 이 전제가 맞으면 가장 깔끔합니다. 맞지 않는 경우가 흔합니다. 함수가 길어서 안쪽 루프가 진짜 병목이거나, 같은 함수가 어떤 경로에서는 계측할 가치가 없거나, 반복문 안에서 수천 번 호출되어 스팬이 폭증하는 경우입니다.

스팬은 공짜가 아닙니다. 호출마다 컨텍스트가 만들어지고 익스포터 큐에 쌓입니다. 짧고 잦은 함수에 데코레이터를 붙이면 계측이 병목이 되고, 트레이스 하나에 스팬이 수천 개 달려 읽을 수 없게 됩니다. 판단 기준을 하나 두면, 그 함수 하나가 트레이스 화면에서 한 줄을 차지할 가치가 있는가입니다. 없다면 붙이지 않는 편이 낫습니다.

9. 직접 확인하는 방법

만든 데코레이터가 의도대로 도는지는 로컬에서 바로 볼 수 있습니다.

export OTEL_TRACES_EXPORTER=console
python -m myapp

확인할 것이 넷입니다.

# 인메모리 익스포터로 단언한다 - 계측 코드에 테스트를 붙일 수 있다
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import SimpleSpanProcessor
from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter

exporter = InMemorySpanExporter()
provider = TracerProvider()
provider.add_span_processor(SimpleSpanProcessor(exporter))
trace.set_tracer_provider(provider)

asyncio.run(fetch_orders(1))
spans = exporter.get_finished_spans()

s = spans[-1]   # 끝난 순서로 쌓이므로 부모 스팬은 맨 마지막이다
# 1. async 함수의 스팬이 실제 소요 시간을 담는가 (0이면 2절 문제)
assert s.end_time - s.start_time > 1_000_000_000
# 2. 예외 이벤트가 중복되지 않는가 (3절)
assert len([e for e in s.events if e.name == "exception"]) <= 1
# 3. 상태가 불필요하게 OK로 박히지 않았는가 (4절)
assert s.status.status_code is not StatusCode.OK
# 4. 자식 스팬이 이 스팬에 붙었는가
assert all(c.parent.span_id == s.context.span_id for c in spans[:-1])

1번과 4번이 async 문제를 잡습니다. 스팬 길이가 0에 가깝고 자식이 엉뚱한 부모에 붙어 있으면 코루틴을 동기 래퍼로 감싼 상태입니다.

10. 트러블슈팅

증상	원인	조치
async 함수 스팬이 0ms	코루틴 객체 반환 후 블록 종료	iscoroutinefunction으로 분기
자식 스팬이 다른 부모에 붙음	같은 원인	위와 동일
예외 이벤트가 두 개	SDK 기본 기록 + 수동 기록	한쪽만 사용
예외가 사라짐	except에서 raise 누락	반드시 재발생
오류가 아닌데 ERROR로 표시	모든 예외를 ERROR 처리	예상 예외를 분리
바깥에서 상태를 못 바꿈	데코레이터가 Ok를 박음	Unset으로 남김
샘플링 규칙이 안 먹음	속성을 생성 후에 추가	attributes=로 전달
라우트 파라미터 주입 실패	functools.wraps 누락	wraps 적용, 데코레이터 순서 확인
계측 후 지연 증가	잦은 호출 함수에 스팬	계측 대상 축소, 비싼 속성은 is_recording() 뒤로
제너레이터에서 이상한 스팬	본문 실행 시점이 다름	감지해서 거부하거나 별도 구현

11. 마무리

• 코루틴 함수를 동기 래퍼로 감싸면 스팬이 아무것도 재지 않습니다. 길이는 0이고 자식 스팬은 다른 부모에 붙습니다. inspect.iscoroutinefunction으로 분기해야 합니다.
• 컨텍스트 매니저는 예외를 이미 기록하고 상태도 ERROR로 세팅합니다. 손으로 한 번 더 하면 이벤트가 중복됩니다. SDK에 맡기거나 두 플래그를 끄고 직접 제어하거나, 둘 중 하나만 합니다.
• 성공 시 Ok를 세팅하지 않습니다. Ok는 최종값이라 바깥에서 덮어쓸 수 없게 만듭니다.
• 샘플러는 생성 시점 속성만 봅니다. 샘플링에 쓸 값은 attributes=로 넘기고, 비싼 계산은 is_recording() 뒤로 미룹니다.
• functools.wraps는 관례가 아니라 요구사항입니다. 시그니처를 읽는 프레임워크가 깨집니다.
• 데코레이터는 "함수 하나 = 작업 하나"일 때만 맞습니다. 트레이스 화면에서 한 줄을 차지할 가치가 없는 함수에는 붙이지 않습니다.

참고

• OpenTelemetry - Tracing API 스펙 (Span, Status, IsRecording) (opens new window)
• OpenTelemetry Python - Instrumentation 가이드 (opens new window)
• OpenTelemetry Python - opentelemetry.trace API 레퍼런스 (opens new window)
• OpenTelemetry - Exception 시맨틱 컨벤션 (opens new window)