Rust 로깅 (log와 tracing)

프로그램에서 문제가 생기면, 바로 직전에 프로그램이 뭘 하고 있었는지 알고 싶어져요. 로깅(logging)은 바로 그걸 위한 거예요. 로그는 배의 항해 일지와 비슷해요. 시각과 중요도가 붙은 짧은 메모들인데, 나중에 읽어 보면 무슨 일이 있었는지 이해할 수 있어요.

여기저기 println!을 뿌려 둘 수도 있지만, 금방 한계에 부딪혀요. 코드를 고치지 않고는 끌 수 없어요. “경고만 보여 줘”라고 말할 수도 없어요. 게다가 디버그용 메모가 프로그램의 진짜 출력과 섞여 버려요. Rust의 로깅 크레이트는 이 세 가지 문제를 모두 해결해 줘요. 이 페이지에서는 가장 인기 있는 두 가지, log(env_logger와 함께)와 tracing을 배워요.

그냥 println!을 쓰면 안 될까요?

차이를 표 하나로 정리하면 이래요.

	println!	로깅 크레이트
다시 컴파일하지 않고 켜고 끄기	안 돼요	돼요. RUST_LOG 변수로요
레벨(error, warn, info, …)	없어요	있어요
메시지가 어디서 왔는지 표시	안 해요	해요(모듈 이름)
출력되는 곳	stdout	기본은 stderr(env_logger)

마지막 줄은 보기보다 중요해요. stdout은 프로그램의 진짜 결과예요. 누군가 파일이나 다른 프로그램으로 파이프해서 넘길 수도 있는 그거요. stderr는 실행 에 관한 메시지를 위한 옆길이에요. 로그는 stderr에 있어야 해요. 그래야 my_app > result.txt가 결과만 저장하고, 로그는 여전히 터미널에 보여요.

log 퍼사드와 env_logger

log 크레이트는 레벨마다 하나씩, 매크로 다섯 개를 줘요. 가장 심각한 것부터 차례로 error!, warn!, info!, debug!, trace!예요. println!과 똑같이 {} 포맷을 써요.

그런데 log만으로는 아무것도 출력되지 않아요. log는 퍼사드(facade)예요. 메시지를 어떻게 보여 줄지는 정하지 않고, 모든 라이브러리가 쓸 수 있는 표준 매크로 모음만 제공해요. 메시지를 실제로 써 내는 로거(logger)는 애플리케이션이 골라요. 가장 간단한 건 env_logger예요. 둘 다 프로젝트에 추가하세요.

cargo add log env_logger

[dependencies]
log = "0.4"
env_logger = "0.11"

이제 main 맨 앞에서 env_logger::init()을 한 번 부르고, 마음껏 로그를 남기면 돼요.

use log::{debug, error, info, warn};

fn divide(a: f64, b: f64) -> Option<f64> {
    debug!("divide 호출: a={a}, b={b}");
    if b == 0.0 {
        warn!("0으로는 나눌 수 없어요: {a} / 0");
        return None;
    }
    Some(a / b)
}

fn main() {
    env_logger::init();
    info!("계산기 시작");

    println!("10 / 4 = {:?}", divide(10.0, 4.0));
    println!("1 / 0 = {:?}", divide(1.0, 0.0));

    error!("에러 줄은 이렇게 보여요");
}

실행 결과:

10 / 4 = Some(2.5)
1 / 0 = None

▶ 직접 실행해 보기

위의 실행 결과는 stdout, 즉 프로그램의 진짜 결과만 보여 줘요. 로그 줄은 stderr로 가요. Playground에서는 따로 있는 “Standard Error” 영역에 나와요.

하나 눈여겨볼 게 있어요. env_logger는 기본적으로 에러만 보여 줘요. 더 보고 싶으면 프로그램을 실행할 때 RUST_LOG 환경 변수를 설정하세요. 아래는 터미널에서 RUST_LOG=debug cargo run으로 실행했을 때 stderr와 stdout이 함께 보인 모습이에요(타임스탬프는 …로 바꿨어요. 여러분 화면에는 현재 날짜와 시각이 나와요).

[… INFO  my_app] 계산기 시작
[… DEBUG my_app] divide 호출: a=10, b=4
10 / 4 = Some(2.5)
[… DEBUG my_app] divide 호출: a=1, b=0
[… WARN  my_app] 0으로는 나눌 수 없어요: 1 / 0
1 / 0 = None
[… ERROR my_app] 에러 줄은 이렇게 보여요

로그 줄마다 레벨과, 그 로그를 남긴 모듈(크레이트 이름인 my_app)이 나와요. 대괄호가 없는 평범한 줄은 println!의 출력이에요.

RUST_LOG로 볼 것 고르기

레벨을 하나 고르면 그 레벨과 그보다 심각한 것 전부가 보여요. 그래서 RUST_LOG=warn은 경고와 에러를, RUST_LOG=trace는 모든 걸 보여 줘요.

RUST_LOG=debug cargo run     # debug, info, warn, error
RUST_LOG=warn cargo run      # warn과 error만
RUST_LOG=off cargo run       # 로그를 전혀 안 보여요

Windows PowerShell에서는 변수를 먼저 설정하세요. $env:RUST_LOG="debug"; cargo run

모듈별로 거를 수도 있어요. 어떤 라이브러리가 너무 수다스러울 때나, 내 코드의 한 부분만 궁금할 때 아주 좋아요. 다음은 db 모듈이 있는 프로그램이에요.

use log::{debug, info};

mod db {
    use log::{debug, trace};

    pub fn find_user(id: u32) -> Option<&'static str> {
        trace!("사용자 {id} 찾는 중");
        let name = match id {
            1 => Some("Ada"),
            2 => Some("Linus"),
            _ => None,
        };
        debug!("조회 결과: {name:?}");
        name
    }
}

fn main() {
    env_logger::init();
    info!("서버 시작");

    for id in [1, 3] {
        match db::find_user(id) {
            Some(name) => println!("사용자 {id}: {name}"),
            None => println!("사용자 {id}: 찾을 수 없음"),
        }
    }

    debug!("조회 모두 끝");
}

실행 결과:

사용자 1: Ada
사용자 3: 찾을 수 없음

▶ 직접 실행해 보기

필터 몇 가지를 직접 써 보고 stderr에 나온 내용이에요(타임스탬프는 …로 바꿨어요).

$ RUST_LOG=my_app=trace cargo run       # 우리 크레이트의 로그 전부
[… INFO  my_app] 서버 시작
[… TRACE my_app::db] 사용자 1 찾는 중
[… DEBUG my_app::db] 조회 결과: Some("Ada")
사용자 1: Ada
[… TRACE my_app::db] 사용자 3 찾는 중
[… DEBUG my_app::db] 조회 결과: None
사용자 3: 찾을 수 없음
[… DEBUG my_app] 조회 모두 끝

$ RUST_LOG=my_app::db=debug cargo run   # db 모듈만, debug 이상
[… DEBUG my_app::db] 조회 결과: Some("Ada")
사용자 1: Ada
[… DEBUG my_app::db] 조회 결과: None
사용자 3: 찾을 수 없음

규칙은 쉼표로 이어 붙일 수 있어요. RUST_LOG=info,my_app::db=trace는 “전체는 info, 하지만 db 모듈은 trace”라는 뜻이에요. 작은 함정이 하나 있어요. 필터에는 밑줄을 쓴 크레이트 이름을 써야 해요. my-app이라는 패키지는 my_app으로 로그를 남겨요.

코드에서 기본 레벨 정하기

RUST_LOG를 설정하지 않아도 info는 보이게 하고 싶을 때가 많아요. 그럴 때는 init() 대신 env_logger::Builder를 쓰세요. 타임스탬프를 끌 수도 있는데, 짧은 도구에서는 이게 편해요.

use env_logger::Env;
use log::{debug, info};

fn main() {
    // RUST_LOG가 따로 정하지 않으면 `info` 이상을 보여 줘요.
    env_logger::Builder::from_env(Env::default().default_filter_or("info"))
        .format_timestamp(None)
        .init();

    info!("앱 시작");
    debug!("RUST_LOG=debug일 때만 보여요");

    let total: u32 = (1..=10).sum();
    println!("합계 = {total}");
}

실행 결과:

합계 = 55

▶ 직접 실행해 보기

타임스탬프가 없으니 cargo run의 실제 stderr가 짧고 깔끔해요.

[INFO  my_app] 앱 시작

tracing으로 구조화된 로그 남기기

log가 주는 건 텍스트 줄이에요. tracing은 데이터가 붙은 이벤트를 주고, 그 이벤트들을 스팬(span)으로 묶어요. Tokio 팀이 만들었고, axum 같은 비동기(async) 웹 프레임워크가 쓰는 것도 이거예요. 이렇게 추가하세요.

cargo add tracing tracing-subscriber

알아 둘 개념은 세 가지예요.

• 이벤트(event)는 로그 줄과 비슷해요. info!, warn! 같은 매크로로, 이름도 log와 같아요.
• 필드(field)는 데이터를 key = value 형태로 붙여요. info!(user_id = 42, "로그인함")처럼요. 도구가 텍스트를 뜯어보는 대신 이 필드로 검색하고 거를 수 있어요.
• 스팬은 “주문 7번 처리 중”처럼 일이 진행되는 한 구간을 나타내요. 스팬 안에서 일어난 이벤트에는 모두 그 스팬이 표시돼요.

log처럼 tracing도 뭔가를 보여 주려면 구독자(subscriber)가 필요해요. 표준 구독자는 tracing_subscriber::fmt()예요. 한 가지 의외인 점은 기본으로 stdout에 쓴다는 거예요. 그래서 .with_writer(std::io::stderr)로 stderr에 보내요.

use tracing::{info, info_span, warn};

fn main() {
    tracing_subscriber::fmt()
        .with_writer(std::io::stderr)
        .init();

    info!(user_id = 42, "로그인함");

    let span = info_span!("checkout", order_id = 7);
    let _guard = span.enter();

    let items = [1200, 350, 999];
    let total: u32 = items.iter().sum();
    info!(items = items.len(), total, "장바구니 합계 계산함");

    if total > 2000 {
        warn!(total, limit = 2000, "주문을 직접 검토해야 해요");
    }

    println!("주문 합계: {total}");
}

실행 결과:

주문 합계: 2549

▶ 직접 실행해 보기

직접 실행했을 때의 stderr예요(타임스탬프는 …로 바꾸고, 색은 뺐어요).

…  INFO my_app: 로그인함 user_id=42
…  INFO checkout{order_id=7}: my_app: 장바구니 합계 계산함 items=3 total=2549
…  WARN checkout{order_id=7}: my_app: 주문을 직접 검토해야 해요 total=2549 limit=2000

마지막 두 줄이 checkout{order_id=7}로 시작하는 게 보이나요? 그게 스팬이에요. _guard가 살아 있는 동안에는 모든 이벤트가 checkout “안”에 있어요. total만 적는 건 total = total의 줄임 표현이에요.

#[instrument]: 호출할 때마다 스팬 만들기

스팬을 손으로 만들다 보면 지쳐요. 함수에 #[instrument]를 붙이면, tracing이 호출할 때마다 스팬을 만들고 인자를 필드로 기록해 줘요(인자는 Debug를 구현해야 해요).

use tracing::{debug, info, instrument};

#[instrument]
fn apply_discount(price: u32, percent: u32) -> u32 {
    let off = price * percent / 100;
    debug!(off, "할인액 계산함");
    price - off
}

fn main() {
    tracing_subscriber::fmt()
        .with_max_level(tracing::Level::DEBUG)
        .with_writer(std::io::stderr)
        .init();

    let final_price = apply_discount(2500, 10);
    info!(final_price, "완료");
    println!("최종 가격: {final_price}");
}

실행 결과:

최종 가격: 2250

▶ 직접 실행해 보기

직접 실행했을 때의 stderr예요.

… DEBUG apply_discount{price=2500 percent=10}: my_app: 할인액 계산함 off=250
…  INFO my_app: 완료 final_price=2250

fmt() 구독자는 따로 말하지 않으면 info 이상을 보여 줘요. 그래서 .with_max_level(tracing::Level::DEBUG)를 설정했어요. env_logger처럼 RUST_LOG를 쓰고 싶다면 env-filter 기능을 켜고 EnvFilter를 쓰세요.

[dependencies]
tracing = "0.1"
tracing-subscriber = { version = "0.3", features = ["env-filter"] }

use tracing_subscriber::EnvFilter;

tracing_subscriber::fmt()
    .with_env_filter(EnvFilter::from_default_env())
    .with_writer(std::io::stderr)
    .init();

어떤 걸 골라야 할까요?

• 작은 CLI 도구나 스크립트인가요? log + env_logger. 준비가 아주 간단하고, 평범한 텍스트면 충분해요.
• 웹 서버나 비동기 코드처럼 여러 작업이 한꺼번에 돌아가나요? tracing. 요청 수백 개가 동시에 돌아가도, 스팬 덕분에 메시지가 어느 요청의 것인지 알 수 있어요.
• 라이브러리를 만들고 있나요? 매크로(log나 tracing)만 쓰고, init()은 절대 부르지 마세요. 로그를 어떻게 보여 줄지는 애플리케이션이 정해요.

평생 하나만 써야 하는 건 아니에요. tracing-subscriber의 기본 설정은 log 크레이트의 메시지도 받아 주기 때문에, 어느 쪽을 쓰는 라이브러리든 로그가 함께 나와요.

자주 하는 실수

로거 설정을 잊어버리기. env_logger::init()(또는 tracing 구독자의 init())을 한 번도 부르지 않으면, 매크로는 문제없이 컴파일되는데 출력은… 아무것도 없어요. 에러도 경고도 없어요. 로그가 사라졌다면 이것부터 확인하고, 그다음에 RUST_LOG를 확인하세요.

init()을 두 번 부르기. 전역 로거는 하나만 있을 수 있어요. 두 번째 호출은 패닉을 일으켜요. 실제 메시지는 이래요.

thread 'main' (12345) panicked at …/env_logger-0.11.11/src/logger.rs:901:16:
env_logger::init should not be called after logger initialized: SetLoggerError(())

“로거가 초기화된 뒤에는 env_logger::init을 부르면 안 된다”는 뜻이에요. main 맨 위에서 딱 한 번만 부르세요. 테스트에서는 let _ = env_logger::builder().is_test(true).try_init();을 쓰세요. 이건 패닉 대신 에러를 돌려줘요.

스팬 가드를 바로 버리기. let _ = span.enter();는 별문제 없어 보이지만, _는 변수 이름이 아니에요. 가드가 같은 줄에서 바로 버려져서 스팬도 곧바로 끝나요. 직접 실행해 보니 스팬이 전혀 없는 INFO my_app: 요청 처리 중이 출력됐어요. let _guard = span.enter();처럼 가드에 이름을 붙여서 스코프가 끝날 때까지 살아 있게 하세요.

정리

• println! 대신 로깅 크레이트를 쓰세요. 레벨로 거를 수 있고, 로그를 stderr에 둬서 진짜 출력과 떼어 놓을 수 있어요.
• log는 error!, warn!, info!, debug!, trace!를 주고, env_logger::init()이 그걸 출력해요.
• RUST_LOG가 무엇을 볼지 정해요. RUST_LOG=debug, RUST_LOG=my_app=trace, RUST_LOG=info,my_app::db=trace처럼요.
• tracing은 구조화된 필드(info!(user_id = 42, "로그인함"))와 스팬을 더해 줘요. #[instrument]는 함수 호출마다 스팬을 만들어요.
• 라이브러리는 매크로만 쓰고, 로거는 애플리케이션이 한 번만 설정해요.

이해도 점검

이해도 점검

1. env_logger를 쓰는 프로그램을 RUST_LOG 없이 실행했어요. 어떤 로그 줄이 보일까요?

전부 다 info! 이상만 error!만 하나도 안 보여요

2. env_logger는 기본적으로 로그 메시지를 어디에 쓸까요?

stdout stderr log.txt라는 파일

3. RUST_LOG=warn은 무엇을 보여 줄까요?

경고만 경고와 그보다 덜 심각한 것 전부 경고와 에러

4. 함수에 #[instrument]를 붙이면 어떻게 될까요?

함수 실행 시간을 재서 출력해요 호출할 때마다 스팬을 만들고, 인자를 필드로 기록해요 함수가 더 빨리 실행돼요 프로그램 전체의 로깅이 켜져요

5. 라이브러리 크레이트를 만들고 있어요. 로깅은 어떻게 해야 할까요?

로깅 매크로는 쓰되, 로거 설정은 애플리케이션에 맡겨요 라이브러리가 로드될 때 env_logger::init()을 불러요 항상 보이도록 println!을 써요

점수: 0 / 5

더 알아보기

• log 크레이트 문서 (영어): 매크로 다섯 개와 퍼사드가 동작하는 방식, 라이브러리 작성자를 위한 조언까지 있어요.
• env_logger 문서 (영어): RUST_LOG 문법 전체와 Builder의 모든 옵션이에요.
• tracing 문서 (영어): 스팬, 이벤트, 필드, #[instrument]를 깊이 있게 다뤄요.
• tracing-subscriber 문서 (영어): 포맷 옵션, EnvFilter, JSON 출력을 설명해요.
• Getting started with Tracing — Tokio (영어): tracing을 관리하는 팀이 쓴 친절한 입문 안내예요.