Danh sách bài viết

Bài 80: Trace Layer + Structured Logging — Production Observability

Bài 80 của series Rust RESTful API — bài thứ 5 Group 8 Middleware Sâu (B80/B85), wire tower-http::TraceLayer + crate tracing structured log cho Shop API qua 2 format multi-env (pretty cho Local dev colored multi-line vs JSON cho Staging/Production log aggregator parse native); customize span qua make_span_with inject request_id từ X-Request-Id header (B39 lock continued); lifecycle hook on_request / on_response / on_failure ba điểm log per request với log level by status MANDATORY (2xx/3xx INFO + 4xx WARN + 5xx ERROR) thay default TraceLayer chỉ DEBUG/INFO; EnvFilter pattern lock RUST_LOG per-module (info,shop_api=debug,sqlx=warn,tower_http=debug Local vs warn,shop_api=info Production); refactor crates/shop-api/src/main.rs với fn init_tracing(env: Environment) match Environment::Local pretty + fmt::layer().pretty() vs Staging/Production fmt::layer().json().with_target.with_current_span thay tracing_subscriber::fmt::init() basic; NEW crates/shop-api/src/middleware/trace_layer.rs custom_trace_layer() function build TraceLayer với make_span_with closure đọc request.headers().get(X_REQUEST_ID) + tracing::info_span! 4 field method/uri/version/request_id; on_request emit "started processing" event; on_response 3 match arm Level by status emit "finished processing" với latency_ms + status field; on_failure emit error event với error + latency_ms; handler module-level log pattern tracing::info!(field = value, "message") tự inherit span TraceLayer kèm request_id; PII sanitize MANDATORY mask phone last 4 + card last 4 + skip password (OWASP A09 Logging Failures prevention); helper mask_phone pattern lock reuse cho mọi sensitive field; log aggregator support Loki/Grafana/Elasticsearch/Datadog JSON parse native; multi-env RUST_LOG default mapping; verify pretty Local + JSON Production 4 scenario test 2xx info + 4xx warn + 5xx error + span nested handler auto inherit; foundation cho B81 (metrics Prometheus middleware) + G15 OpenTelemetry distributed tracing.

16/06/2026
13 phút đọc
1 lượt xem
1

Mục Tiêu Bài Học

Sau bài học, bạn sẽ:

  • Hiểu crate tracing vs crate log trong Rust ecosystem — structured logging native vs string-based message.
  • Setup tracing_subscriber với 2 format multi-env: pretty cho dev + JSON cho production.
  • Áp tower-http::TraceLayer wire vào router stack Shop API.
  • Customize trace span với request_id correlation (B39 lock continued) inject từ X-Request-Id header.
  • Implement log level by status MANDATORY: 2xx/3xx → INFO, 4xx → WARN, 5xx → ERROR thay default TraceLayer cố định.
  • JSON log format cho production stack log aggregator (Loki / Grafana / Elasticsearch / Datadog).
  • Multi-env config: pretty + debug Local, JSON + info Staging/Production qua RUST_LOG EnvFilter.
  • PII sanitize MANDATORY (OWASP A09 Logging Failures) — mask phone / card last 4 + skip password.
2

tracing Vs log Crate

Rust có 2 crate logging chính, lựa chọn ảnh hưởng đến mọi quyết định observability tương lai. Shop API lock tracing từ B10 và B80 deep dive lý do.

Crate log (legacy, từ Rust 1.0):

  • Macro info!(), warn!(), error!() đơn giản — chỉ message string.
  • String-based formatting info!("user {} logged in", id) — log line là plain text.
  • KHÔNG structured: không có key-value field, log aggregator phải regex parse — fragile khi format đổi.
  • KHÔNG context propagation: không có "span" lifecycle scope, log nested call mất ngữ cảnh.
  • Backend qua trait Log — implementation phổ biến env_logger, simplelog.
  • Phù hợp CLI tool nhỏ, script đơn giản.

Crate tracing (modern, tokio ecosystem, recommended):

  • Macro tracing::info!(user_id = %id, action = "login", "user logged in")structured native, key=value field tách khỏi message.
  • Span: track lifecycle scope (request, transaction, background job) — nested call tự inherit field span cha.
  • Event: emit log point trong span (info!/warn!/error!/debug!/trace!).
  • Subscriber: process log (format + filter + output) — pluggable qua tracing-subscriber.
  • Async-aware: span tự attach Future qua .instrument(); tokio task switch không mất ngữ cảnh.
  • Output đa dạng: pretty colored cho dev, JSON cho production, OpenTelemetry export cho distributed tracing.

Decision lock Shop API: tracing (modern, structured, async-aware) — quyết định từ B10 với tracing = "0.1" + tracing-subscriber = "0.3" trong [workspace.dependencies]. B80 extend feature flag để bật JSON output + EnvFilter.

Workspace dep update shop/Cargo.toml:

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

Feature lock:

  • env-filter: EnvFilter parse RUST_LOG env per-module level (vd info,shop_api=debug,sqlx=warn).
  • json: fmt::layer().json() output JSON Lines cho log aggregator parse native.
  • fmt: fmt::layer().pretty() output colored multi-line cho dev terminal.
3

tracing_subscriber Setup Multi-Env

Refactor crates/shop-api/src/main.rs thay tracing_subscriber::fmt::init() basic bằng fn init_tracing(env: Environment) branch theo môi trường (B56 Environment enum lock continued).

// File: crates/shop-api/src/main.rs (refactor B80)
use tracing_subscriber::{fmt, prelude::*, EnvFilter};
use shop_api::config::Environment;

fn init_tracing(env: Environment) {
    // EnvFilter parse RUST_LOG; fallback per-env default.
    let env_filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| match env {
        Environment::Local => {
            EnvFilter::new("info,shop_api=debug,sqlx=warn,tower_http=debug")
        }
        Environment::Staging | Environment::Production => {
            EnvFilter::new("warn,shop_api=info,sqlx=warn,tower_http=info")
        }
    });

    match env {
        Environment::Local => {
            // Pretty format dev — colored multi-line, dễ đọc terminal.
            tracing_subscriber::registry()
                .with(env_filter)
                .with(fmt::layer().pretty())
                .init();
        }
        Environment::Staging | Environment::Production => {
            // JSON format production — log aggregator parse native.
            tracing_subscriber::registry()
                .with(env_filter)
                .with(
                    fmt::layer()
                        .json()
                        .with_target(true)         // module path field "target"
                        .with_current_span(true)   // span hiện tại embed JSON
                        .with_span_list(false),    // span list parent omit (giảm noise)
                )
                .init();
        }
    }
}

#[tokio::main]
async fn main() -> anyhow::Result<()> {
    dotenvy::dotenv().ok();

    let config = shop_api::config::AppConfig::from_env()?;
    init_tracing(config.environment);

    tracing::info!(
        env = ?config.environment,
        version = env!("CARGO_PKG_VERSION"),
        "starting shop-api"
    );

    // ... build pool + router + axum::serve (giữ nguyên B57)
    Ok(())
}

Pretty format Local — output 1 event:

  2026-06-16T10:00:00.123456Z  INFO shop_api: starting shop-api
    env: Local
    version: "0.1.0"
    at crates/shop-api/src/main.rs:42

JSON format Production — cùng event:

{"timestamp":"2026-06-16T10:00:00.123456Z","level":"INFO","target":"shop_api","fields":{"message":"starting shop-api","env":"Production","version":"0.1.0"}}

EnvFilter pattern lock qua biến môi trường RUST_LOG:

  • RUST_LOG=debug — toàn bộ crate level DEBUG.
  • RUST_LOG=info,shop_api=debug — global INFO, crate shop_api DEBUG.
  • RUST_LOG=info,shop_api=debug,sqlx=warn — thêm crate sqlx chỉ WARN (giảm noise query log).
  • RUST_LOG=info,shop_api[create_order]=debug — chỉ span name create_order trong crate shop_api DEBUG.
  • Khi env var không set → fallback theo môi trường (Local debug, Production info).

Lock decision Shop API:

  • Local: pretty + info,shop_api=debug,sqlx=warn,tower_http=debug — đủ chi tiết debug + ẩn query noise.
  • Staging: JSON + warn,shop_api=info,sqlx=warn,tower_http=info — log aggregator + info app code.
  • Production: JSON + warn,shop_api=info,sqlx=warn,tower_http=info — same Staging, separate dashboard.
4

tower-http TraceLayer Setup

tower-http::TraceLayer là middleware tower wrap mỗi HTTP request trong 1 span riêng — mọi log event trong handler/service nested tự inherit span đó kèm method/uri. Default API setup:

use tower_http::trace::{TraceLayer, DefaultOnRequest, DefaultOnResponse, DefaultOnFailure};
use tower_http::LatencyUnit;
use tracing::Level;

// Default TraceLayer — span "request" với method + uri auto.
let trace_layer = TraceLayer::new_for_http()
    .on_request(DefaultOnRequest::new().level(Level::INFO))
    .on_response(
        DefaultOnResponse::new()
            .level(Level::INFO)
            .latency_unit(LatencyUnit::Millis),
    )
    .on_failure(DefaultOnFailure::new().level(Level::ERROR));

Default span tạo ra mỗi request:

  INFO request{method=POST uri=/api/v1/orders version=HTTP/1.1}: started processing request
  INFO request{method=POST uri=/api/v1/orders version=HTTP/1.1}: finished processing request latency=125 ms status=201

Default đủ tốt cho prototype nhưng thiếu 3 điểm Shop API cần:

  • KHÔNG có request_id: correlation cross-service vô dụng — load balancer route 5 instance, log Loki query {request_id="abc-123"} không thấy gì.
  • Log level cố định: DefaultOnResponse INFO mọi status — 5xx error rớt vào INFO bucket bị alert filter bỏ qua.
  • KHÔNG redact sensitive header: Authorization: Bearer ... hoặc Cookie: session=... log raw → leak credentials.

B80 customize tất cả 3 điểm qua make_span_with + closure custom on_request / on_response / on_failure.

Wire layer vào router stack (preview, deep ở Bước 5):

use crate::middleware::trace_layer::custom_trace_layer;

Router::new()
    // ... routes
    // OUTERMOST 2 — trace layer wrap mọi request, span "request" với request_id field.
    .layer(custom_trace_layer())
    // OUTERMOST 1 — global RequestBodyLimitLayer 100MB cap (B79 lock continued)
    .layer(RequestBodyLimitLayer::new(GLOBAL_BODY_LIMIT))

Lưu ý ordering: trace_layer đặt INNER hơn RequestBodyLimitLayer để 413 reject KHÔNG được log như request bình thường (raw bytes reject sớm trước khi trace span tạo). Pattern lock B76 continued.

5

Customize Span — request_id Correlation

NEW crates/shop-api/src/middleware/trace_layer.rs — file riêng theo pattern lock B76 (1 file/layer):

// File: crates/shop-api/src/middleware/trace_layer.rs
use axum::body::Body;
use axum::http::{Request, Response};
use std::time::Duration;
use tower_http::classify::ServerErrorsFailureClass;
use tower_http::trace::{MakeSpan, OnFailure, OnRequest, OnResponse, TraceLayer};
use tracing::{Level, Span};

use shop_common::headers::X_REQUEST_ID;

/// Build trace layer Shop API với 4 customize:
/// 1. make_span_with — inject request_id từ X-Request-Id header (B39 continued).
/// 2. on_request — log "started processing" mỗi request.
/// 3. on_response — log "finished processing" với level by status (2xx INFO / 4xx WARN / 5xx ERROR).
/// 4. on_failure — log error chi tiết khi service trả error.
pub fn custom_trace_layer() -> TraceLayer<
    tower_http::classify::SharedClassifier<tower_http::classify::ServerErrorsAsFailures>,
    ShopMakeSpan,
    ShopOnRequest,
    ShopOnResponse,
    (),
    (),
    ShopOnFailure,
> {
    TraceLayer::new_for_http()
        .make_span_with(ShopMakeSpan)
        .on_request(ShopOnRequest)
        .on_response(ShopOnResponse)
        .on_failure(ShopOnFailure)
}

#[derive(Clone)]
pub struct ShopMakeSpan;

impl<B> MakeSpan<B> for ShopMakeSpan {
    fn make_span(&mut self, request: &Request<B>) -> Span {
        let request_id = request
            .headers()
            .get(X_REQUEST_ID)
            .and_then(|v| v.to_str().ok())
            .unwrap_or("-");

        tracing::info_span!(
            "request",
            method = %request.method(),
            uri = %request.uri(),
            version = ?request.version(),
            request_id = %request_id,
        )
    }
}

ShopOnRequest log entry mỗi request — mức INFO mặc định:

#[derive(Clone)]
pub struct ShopOnRequest;

impl<B> OnRequest<B> for ShopOnRequest {
    fn on_request(&mut self, _request: &Request<B>, _span: &Span) {
        tracing::info!("started processing request");
    }
}

ShopOnResponselog level by status MANDATORY, lock pattern vĩnh viễn:

#[derive(Clone)]
pub struct ShopOnResponse;

impl<B> OnResponse<B> for ShopOnResponse {
    fn on_response(self, response: &Response<B>, latency: Duration, _span: &Span) {
        let status = response.status();
        let latency_ms = latency.as_millis() as u64;

        // Log level by status — MANDATORY Shop API lock.
        if status.is_server_error() {
            // 5xx — ERROR, alert pipeline kích hoạt.
            tracing::error!(
                status = status.as_u16(),
                latency_ms,
                "finished processing request"
            );
        } else if status.is_client_error() {
            // 4xx — WARN, monitor nhưng không alert.
            tracing::warn!(
                status = status.as_u16(),
                latency_ms,
                "finished processing request"
            );
        } else {
            // 2xx/3xx — INFO, normal traffic.
            tracing::info!(
                status = status.as_u16(),
                latency_ms,
                "finished processing request"
            );
        }
    }
}

ShopOnFailure — log error khi service trả lỗi internal (panic, timeout, IO error trước khi response build xong):

#[derive(Clone)]
pub struct ShopOnFailure;

impl OnFailure<ServerErrorsFailureClass> for ShopOnFailure {
    fn on_failure(
        &mut self,
        failure: ServerErrorsFailureClass,
        latency: Duration,
        _span: &Span,
    ) {
        tracing::error!(
            error = ?failure,
            latency_ms = latency.as_millis() as u64,
            "request failed"
        );
    }
}

Update crates/shop-api/src/middleware/mod.rs re-export:

// File: crates/shop-api/src/middleware/mod.rs
pub mod cors;
pub mod enrich_error;
pub mod idempotency;
pub mod rate_limit;
pub mod request_id;
pub mod security_headers;
pub mod trace_layer;   // NEW B80

pub use trace_layer::custom_trace_layer;

Lock pattern Shop API:

  • Span name: "request" (1 span per HTTP request).
  • Field span: method + uri + version + request_id (KHÔNG body để tránh leak PII).
  • on_request: log "started processing request" INFO.
  • on_response: log "finished processing request" với 3 level rẽ nhánh theo status.
  • on_failure: log error chi tiết khi service trả failure class.

Lock log level by status MANDATORY:

  • 2xx/3xx → INFO — normal traffic, retained 7 ngày, không alert.
  • 4xx → WARN — client error, retained 14 ngày, monitor dashboard nhưng không page on-call.
  • 5xx → ERROR — server error, retained 30 ngày, alert pipeline trigger PagerDuty / Slack.
6

Module-Level Log Trong Handler

Handler dùng macro tracing::info! với field key=value — log event tự inherit span của TraceLayer (đã set method/uri/request_id) qua context propagation tokio task-local. Pattern lock cho mọi handler Shop API:

// File: crates/shop-api/src/routes/orders.rs (preview B66)
use axum::Extension;
use shop_common::dto::order::{CreateOrderDto, OrderResponseDto};
use shop_common::error::AppError;
use crate::extractors::ValidatedJson;
use crate::middleware::request_id::RequestId;
use crate::responses::Created;
use crate::state::AppState;
use axum::extract::State;

pub async fn create_order(
    State(state): State<AppState>,
    Extension(_req_id): Extension<RequestId>,
    ValidatedJson(dto): ValidatedJson<CreateOrderDto>,
) -> Result<Created<OrderResponseDto>, AppError> {
    // Log entry handler — input field summary, KHÔNG full body.
    tracing::info!(
        user_id = 1, // TODO: từ CurrentUser extractor B116
        item_count = dto.items.len(),
        payment_type = ?dto.payment.payment_type,
        "create order request"
    );

    // ... business logic gọi service layer
    let order = state
        .order_service
        .create_order(1, dto.items, &dto.payment)
        .await?;

    // Log success — kết quả + ID, KHÔNG raw DTO.
    tracing::info!(
        order_id = order.id,
        total = %order.total,
        "order created successfully"
    );

    Ok(Created {
        location: format!("/api/v1/orders/{}", order.id),
        data: OrderResponseDto::from(order),
    })
}

Output Local pretty — log 3 event nested trong span request:

  2026-06-16T10:00:00.100Z  INFO request{method=POST uri=/api/v1/orders version=HTTP/1.1 request_id=abc-123}: started processing request
  2026-06-16T10:00:00.105Z  INFO request{method=POST uri=/api/v1/orders version=HTTP/1.1 request_id=abc-123}: shop_api::routes::orders: create order request user_id=1 item_count=2 payment_type=Cod
  2026-06-16T10:00:00.245Z  INFO request{method=POST uri=/api/v1/orders version=HTTP/1.1 request_id=abc-123}: shop_api::routes::orders: order created successfully order_id=42 total=1500000
  2026-06-16T10:00:00.250Z  INFO request{method=POST uri=/api/v1/orders version=HTTP/1.1 request_id=abc-123}: finished processing request status=201 latency_ms=150

Output Production JSON — handler event auto kèm span context:

{"timestamp":"2026-06-16T10:00:00.105Z","level":"INFO","target":"shop_api::routes::orders","fields":{"message":"create order request","user_id":1,"item_count":2,"payment_type":"Cod"},"span":{"name":"request","method":"POST","uri":"/api/v1/orders","version":"HTTP/1.1","request_id":"abc-123"}}

Lock pattern handler log Shop API:

  • Entry handler: 1 event "<action> request" với input field summary (count, type, ID — KHÔNG full DTO).
  • Success: 1 event "<action> successfully" với kết quả ID + tổng giá trị.
  • Error: không cần log thủ công — AppError::IntoResponse B16/B48 lock đã log chi tiết qua ? bubble. on_response trả 4xx/5xx tự log level tương ứng.
  • Span nested auto inherit: handler info!() không cần repeat request_id — tracing-subscriber tự gắn vào output.

Số event log per request typical: 3 (entry + success + finished) cho happy path; 2 (entry + finished với WARN/ERROR) cho error path.

7

PII Sanitize Trong Log

OWASP Top 10 2021 mục A09 Security Logging and Monitoring Failures nêu rõ: log raw PII (Personally Identifiable Information) = vi phạm GDPR (EU), CCPA (California), Nghị định 13/2023 (Việt Nam) — phạt tới 4% doanh thu toàn cầu.

Pattern lock Shop API B80 vĩnh viễn — danh sách trường KHÔNG được log raw:

  • Password / password_hash: KHÔNG bao giờ log dưới bất kỳ dạng nào.
  • Card number: mask ****-****-****-4242 (PCI DSS yêu cầu mask, chỉ giữ last 4).
  • CVV / PIN / OTP: KHÔNG log.
  • Phone full: mask ***1234 (chỉ giữ last 4).
  • Email full: pattern lock mask u***@example.com hoặc log email_hash SHA-256.
  • National ID / SSN: mask last 4 hoặc skip.
  • JWT / session token: log jti claim (token ID) thay full token.
  • API key / secret: KHÔNG log, sanitize header Authorization trước khi log header map.

Helper mask_phone pattern lock — reuse cho mọi sensitive field:

// File: crates/shop-common/src/sanitize.rs (NEW B80 preview, fully implement G15)
/// Mask phone giữ last 4 ký tự: "0912345678" → "***5678".
pub fn mask_phone(phone: &str) -> String {
    if phone.len() <= 4 {
        return "****".into();
    }
    format!("***{}", &phone[phone.len() - 4..])
}

/// Mask card giữ last 4: "4242424242424242" → "****-****-****-4242".
pub fn mask_card(card: &str) -> String {
    if card.len() < 4 {
        return "****".into();
    }
    format!("****-****-****-{}", &card[card.len() - 4..])
}

/// Mask email giữ char đầu + domain: "[email protected]" → "u***@example.com".
pub fn mask_email(email: &str) -> String {
    match email.split_once('@') {
        Some((local, domain)) if local.len() >= 1 => {
            format!("{}***@{}", &local[..1], domain)
        }
        _ => "***@***".into(),
    }
}

Apply trong handler:

use shop_common::sanitize::{mask_email, mask_phone};

// ✅ ĐÚNG — mask trước khi log.
tracing::info!(
    user_id = user.id,
    email = %mask_email(&user.email),
    phone = %mask_phone(user.phone.as_str()),
    "user registered"
);

// ❌ SAI — log raw PII, vi phạm OWASP A09.
// tracing::info!(email = %user.email, phone = %user.phone, "user registered");

// ❌ SAI — log password dù đã hash.
// tracing::info!(password_hash = %user.password_hash, "...");

Sanitize header sensitive — Shop API TraceLayer KHÔNG log toàn bộ HeaderMap (chỉ method/uri/version) nên tránh được leak Authorization / Cookie tự nhiên. Khi cần log header debug (vd middleware custom), pattern lock skip 4 header:

const SENSITIVE_HEADERS: &[&str] = &[
    "authorization",
    "cookie",
    "set-cookie",
    "x-api-key",
];

fn sanitize_headers(headers: &http::HeaderMap) -> Vec<(String, String)> {
    headers
        .iter()
        .map(|(name, value)| {
            let key = name.as_str().to_ascii_lowercase();
            let val = if SENSITIVE_HEADERS.contains(&key.as_str()) {
                "[REDACTED]".to_string()
            } else {
                value.to_str().unwrap_or("[non-utf8]").to_string()
            };
            (key, val)
        })
        .collect()
}

OWASP A09 reference: OWASP Top 10 2021 — A09. Lock pattern Shop API: KHÔNG bao giờ log raw PII; mọi field nhạy cảm phải qua helper mask_*.

8

Verify Log Output + Multi-Env Test

Khởi động Shop API Local pretty format:

APP_ENV=local RUST_LOG=info,shop_api=debug cargo run -p shop-api
# >   2026-06-16T10:00:00.000Z  INFO shop_api: starting shop-api env=Local version="0.1.0"
# >   2026-06-16T10:00:00.050Z  INFO shop_api: shop-api listening addr=0.0.0.0:3000

Test 1 — 2xx INFO normal traffic:

curl -i http://localhost:3000/api/v1/products
# > HTTP/1.1 200 OK
# > ...

# Server log:
#   INFO request{method=GET uri=/api/v1/products version=HTTP/1.1 request_id=abc-123}: started processing request
#   INFO request{...}: shop_api::routes::products: list products request page=1 per_page=20
#   INFO request{...}: shop_api::routes::products: list products successfully total=42
#   INFO request{...}: finished processing request status=200 latency_ms=18

Test 2 — 4xx WARN client error:

curl -i -X POST http://localhost:3000/api/v1/products \
  -H 'Content-Type: application/json' \
  -d '{"name":""}'
# > HTTP/1.1 422 Unprocessable Entity
# > {"error":"validation failed","code":"VALIDATION_FAILED",...}

# Server log:
#   INFO request{method=POST uri=/api/v1/products request_id=def-456}: started processing request
#   WARN request{...}: finished processing request status=422 latency_ms=8

Test 3 — 5xx ERROR server failure:

# Simulate DB down (stop postgres container).
docker stop shop-postgres
curl -i http://localhost:3000/api/v1/products
# > HTTP/1.1 500 Internal Server Error
# > {"error":"internal error","code":"INTERNAL",...}

# Server log:
#   INFO request{method=GET uri=/api/v1/products request_id=ghi-789}: started processing request
#   ERROR request{...}: shop_common::error: database error: connection refused
#   ERROR request{...}: finished processing request status=500 latency_ms=5012

Test 4 — Production JSON format:

APP_ENV=production RUST_LOG=warn,shop_api=info cargo run -p shop-api 2>&1 | head -5
# Output (JSON Lines):
{"timestamp":"2026-06-16T10:00:00.000Z","level":"INFO","target":"shop_api","fields":{"message":"starting shop-api","env":"Production","version":"0.1.0"}}
{"timestamp":"2026-06-16T10:00:00.050Z","level":"INFO","target":"shop_api","fields":{"message":"shop-api listening","addr":"0.0.0.0:3000"}}
{"timestamp":"2026-06-16T10:00:05.123Z","level":"INFO","target":"tower_http::trace::on_request","fields":{"message":"started processing request"},"span":{"name":"request","method":"GET","uri":"/api/v1/products","version":"HTTP/1.1","request_id":"abc-123"}}
{"timestamp":"2026-06-16T10:00:05.141Z","level":"INFO","target":"tower_http::trace::on_response","fields":{"message":"finished processing request","status":200,"latency_ms":18},"span":{"name":"request","method":"GET","uri":"/api/v1/products","version":"HTTP/1.1","request_id":"abc-123"}}

Verify log aggregator integration:

  • Loki + Grafana: scrape stdout container qua Promtail; query LogQL {app="shop-api"} | json | request_id="abc-123" trace 1 request cross-instance.
  • Elasticsearch: Filebeat ship JSON lines; Kibana visualize level:ERROR AND status:>=500.
  • Datadog: agent auto-detect JSON format; service:shop-api status:error trigger monitor.
  • Honeycomb: trace.trace_id auto-correlate khi G15 wire OpenTelemetry.

Span nested verify: query Loki {request_id="abc-123"} trả 3 event (entry handler + finished + nested debug) — đủ context debug 1 request mà không cần cross-reference.

9

Tổng Kết

  • Crate tracing modern structured logging — field key=value + span lifecycle, replace log crate string-based.
  • tracing-subscriber 2 format multi-env: pretty cho Local dev colored multi-line, JSON cho Staging/Production log aggregator parse native.
  • EnvFilter control level per-module qua RUST_LOG — pattern lock info,shop_api=debug,sqlx=warn,tower_http=debug Local; warn,shop_api=info Production.
  • tower-http::TraceLayer wrap mọi request — auto span generate với method/uri/version.
  • make_span_with customize: inject request_id từ X-Request-Id header (B39 continued) — correlation cross-service MANDATORY.
  • on_request / on_response / on_failure ba lifecycle hook custom — full control log point per request.
  • Log level by status MANDATORY: 2xx/3xx INFO (normal), 4xx WARN (client error monitor), 5xx ERROR (server error alert pipeline).
  • Handler log pattern: entry event (input field summary) + success (result + ID) + error (delegate AppError::IntoResponse B16/B48).
  • Span nested auto inherit: handler tracing::info!() tự kèm request_id span TraceLayer — không cần repeat field.
  • PII sanitize MANDATORY: mask phone / card / email part, skip password / CVV / OTP / JWT / API key.
  • OWASP A09 prevention: KHÔNG bao giờ log raw PII — vi phạm GDPR / CCPA / Nghị định 13.
  • Helper mask_phone / mask_card / mask_email pattern lock reuse cho mọi sensitive field — file shop-common::sanitize.
  • Multi-env config: pretty + debug Local, JSON + info Staging/Production qua fn init_tracing(env: Environment) match branch.
  • Log aggregator support: Loki / Grafana / Elasticsearch / Datadog / Honeycomb parse JSON Lines native — không cần regex parse fragile.
  • File path lock: NEW crates/shop-api/src/middleware/trace_layer.rs; extend crates/shop-api/src/main.rs::init_tracing; re-export middleware/mod.rs.
  • Middleware stack giờ 8 layer (7 cũ B79 + trace_layer mới B80).
  • Foundation cho B81 (metrics Prometheus middleware refactor B57), G15 OpenTelemetry distributed tracing cross-service.
10

Bài Tập Củng Cố

Tự trả lời, đáp án ở cuối:

  1. tracing vs log crate — phân biệt structured logging vs string-based. Pros/cons mỗi crate? Tại sao Shop API lock tracing từ B10?
  2. tracing_subscriber::EnvFilter + RUST_LOG — pattern info,shop_api=debug,sqlx=warn. Cho ví dụ filter per-module scenario thực tế debug 1 endpoint mà không bị noise sqlx query.
  3. make_span_with customize TraceLayer — tại sao MANDATORY inject request_id? B39 correlation pattern hoạt động ra sao cross-service?
  4. Log level by status — 4xx WARN vs 5xx ERROR. Cho ví dụ scenario log filter level>=ERROR cho alert pipeline; tại sao 4xx KHÔNG nên ERROR?
  5. PII sanitize log — OWASP A09. Cho ví dụ scenario raw log password / phone → exploit GDPR violation; pattern mask_* helper lock Shop API.
Đáp án
  1. tracing vs log crate: Crate log (legacy từ Rust 1.0) — macro info!("user {} logged in", id) string-based interpolation tại compile time → log line plain text dạng "INFO user 42 logged in". Pros: đơn giản học 5 phút, API stable 10 năm, dep nhẹ, phù hợp CLI tool/script không cần observability. Cons: KHÔNG structured (log aggregator phải regex parse fragile khi format đổi vd thêm field giữa câu), KHÔNG span context (log nested call mất ngữ cảnh — handler gọi service A gọi service B, log của B không biết thuộc request nào), KHÔNG async-aware (tokio task switch mất TLS context), backend dynamic dispatch overhead khi log volume cao. Crate tracing (modern, tokio ecosystem 2019+) — macro tracing::info!(user_id = %id, action = "login", "user logged in") field key=value tách khỏi message → output structured JSON {"level":"INFO","msg":"user logged in","user_id":42,"action":"login"}. Pros: structured native (log aggregator parse JSON 1 lệnh không regex), span lifecycle scope cho request/transaction/job — nested call tự inherit field cha qua tokio task-local storage, async-aware (.instrument() attach Future tracking cross await point), pluggable subscriber (pretty dev, JSON prod, OTel export distributed tracing G15, custom subscriber for sampling/aggregation), Level enum 5 mức (TRACE/DEBUG/INFO/WARN/ERROR) per-module filter qua EnvFilter. Cons: API học 1-2 ngày (span/event/subscriber concept), dep nặng hơn (tracing-subscriber + feature flag), overhead nhỉnh hơn log ~5% benchmark (negligible production). Tại sao Shop API lock tracing từ B10: (a) production web API MUST structured log cho log aggregator parse (Loki/ES/Datadog), log string-based fragile khi schema log đổi; (b) request scope span foundation cho B39 request_id correlation cross-service; (c) tokio ecosystem alignment — sqlx/axum/tower-http/tonic đều tracing native, dùng log phải bridge qua tracing-log double overhead; (d) future-proof G15 OpenTelemetry export — tracing có tracing-opentelemetry bridge sẵn, log không có path; (e) async-aware MANDATORY khi handler gọi 5-10 service await point — log mất ngữ cảnh ở mỗi await. Lock B10 vĩnh viễn: workspace dep tracing = "0.1" + tracing-subscriber = "0.3"; KHÔNG dùng log trực tiếp; nếu dep transitively dùng log (vd hyper) thì bridge qua tracing-log::LogTracer::init() route log event qua tracing subscriber.
  2. EnvFilter + RUST_LOG per-module pattern: EnvFilter parse string format "<level>,<target>=<level>,..." — global level mặc định + override per-crate/module/span. Cú pháp: info,shop_api=debug,sqlx=warn = global INFO, crate shop_api DEBUG, crate sqlx WARN. Granularity sâu hơn: shop_api::routes::orders=trace chỉ module orders.rs TRACE; shop_api[create_order]=debug chỉ span name create_order DEBUG. Scenario thực tế debug 1 endpoint: dev đang điều tra bug POST /api/v1/orders trả 422 mà DTO valid; cần xem chi tiết deserialize step + validate step nhưng KHÔNG muốn 1000 dòng sqlx query log noise mỗi request. Set RUST_LOG=info,shop_api::routes::orders=trace,shop_api::extractors=trace,sqlx=warn,tower_http=info → output: chỉ 2 module liên quan TRACE (route orders + extractors), sqlx WARN (chỉ slow query / error), tower_http INFO (trace layer entry/exit). Filter granularity giúp signal-to-noise ratio cao 100x so với RUST_LOG=trace flat. Pattern lock Shop API: Local default info,shop_api=debug,sqlx=warn,tower_http=debug — đủ debug app code + ẩn query verbose; Production default warn,shop_api=info,sqlx=warn,tower_http=info — giảm log volume tiết kiệm storage aggregator (1 request = 4 event INFO thay 20 event DEBUG); incident on-call temporary set RUST_LOG=info,shop_api=debug qua env var không cần redeploy. Hot-reload: B80 implement initial config; G15 deploy thêm tracing-subscriber::reload::Layer + admin endpoint PATCH /admin/log-level đổi level runtime không restart instance — pattern Netflix/Spotify production. EnvFilter directive precedence: directive cụ thể hơn thắng — shop_api::routes::orders=trace override shop_api=debug override info global. Test directive: EnvFilter::try_new(directive).is_ok() validate trước khi apply tránh typo silent break log.
  3. make_span_with customize TraceLayer + request_id MANDATORY: default TraceLayer::new_for_http() tạo span "request" với 3 field auto method/uri/version — đủ minimal cho 1-instance dev nhưng production multi-instance 10+ pod sau load balancer thì 1 request rớt vào 1 pod random, log Loki query {app="shop-api"} method="POST" uri="/api/v1/orders" trả về hàng nghìn match cùng giờ — không thể isolate 1 request bug user báo. Pattern request_id correlation B39 lock: middleware request_id_middleware (B39) đọc header X-Request-Id client gửi hoặc generate UUID v4 mới nếu absent → inject vào Extension<RequestId> + set response header X-Request-Id echo về client. Client log error kèm X-Request-Id từ response header → support engineer query log aggregator {request_id="abc-123-def"} trả CHÍNH XÁC log của 1 request đó cross-instance. make_span_with trong B80 implement ShopMakeSpan đọc request.headers().get(X_REQUEST_ID) trước khi handler chạy (middleware request_id đã set header trước layer trace nhờ ordering INNER hơn) → inject field request_id = %request_id vào span info_span!("request", ..., request_id = %request_id) → mọi event nested trong handler (info!/warn!/error!) tự inherit field qua span context propagation. Cross-service correlation: Shop API gọi service Stripe / S3 / Redis pubsub → forward header X-Request-Id qua reqwest client; service downstream log cùng request_id → query Loki across service trả full distributed trace 1 lệnh. Foundation OpenTelemetry G15: request_id = trace_id OTel standard; B80 inject manual qua header, G15 wire tracing-opentelemetry auto-propagate qua traceparent W3C header thay X-Request-Id custom. Nếu KHÔNG có request_id: debug 1 user complain "order create fail 30 phút trước" — engineer query log không có anchor, scan thủ công 50K event cùng timeframe, tốn 30-60 phút thay 30 giây với request_id. Pattern industry: AWS X-Ray, GCP Trace, Honeycomb đều require trace_id MANDATORY mọi event. Lock Shop API B39 + B80: mọi log event MUST có request_id field; missing = bug middleware ordering.
  4. Log level by status — 4xx WARN vs 5xx ERROR: 4xx Client Error (400/401/403/404/409/422/429) = lỗi client (bad input, missing auth, conflict business rule) — KHÔNG phải lỗi server, NGƯỜI DÙNG hoặc client SDK gửi sai. Volume cao bình thường: 5-15% traffic 422 validation fail từ form người dùng nhập sai, 1-3% 401 token expire chờ refresh, 0.5% 404 link cũ bookmark. Log INFO sẽ chìm trong noise traffic 2xx; log ERROR sẽ trigger PagerDuty page on-call mỗi 5 phút 24/7 (alert fatigue → engineer disable alert hoặc nghỉ việc). Lock WARN: 4xx event vẫn vào log aggregator để dashboard monitor trend (vd spike 401 = JWT key rotation lỗi, spike 422 = bug client SDK release mới), retain 14 ngày, KHÔNG page on-call. 5xx Server Error (500/502/503/504) = lỗi server thực sự (DB down, panic Rust, timeout upstream, OOM) — RARE bình thường < 0.1% traffic; mọi 5xx MUST investigate. Lock ERROR: trigger alert pipeline (PagerDuty/OpsGenie/Slack) ngay khi rate > 0.5% sustained 5 phút; retain 30 ngày cho post-mortem; engineer on-call page 2 AM nếu cần. Scenario alert pipeline: Grafana alert rule sum(rate({app="shop-api"} | json | level="ERROR" | status>=500 [5m])) by (status) > 0.1 = nếu > 0.1 event ERROR/sec sustained 5 min → trigger PagerDuty severity P2; status=500 + error="connection pool exhausted" trigger runbook auto-restart pool. Tại sao 4xx KHÔNG ERROR: (a) volume — 100 req/s × 10% 4xx = 10 event/s ERROR fake → alert pipeline overload, on-call burnout; (b) signal — 4xx là expected behavior contract API design (validation fail = expected khi user input sai), KHÔNG phải bug; (c) liability — 4xx do client gửi sai, KHÔNG phải bug Shop API → log WARN đủ trace mà không page; (d) cost — Datadog/ES storage tính theo level ERROR cao gấp 5x INFO/WARN, log 4xx ERROR tăng bill 5x không lợi ích. Edge case 4xx → ERROR upgrade: 429 spike đột biến (DDoS) trigger ERROR temporary + alert; 401 spike đột biến (auth service down) trigger ERROR. Pattern lock Shop API B80: mặc định 4xx WARN; G19 thêm rate-based alert escalate WARN → ERROR khi anomaly detect.
  5. PII sanitize log + OWASP A09: A09 Security Logging and Monitoring Failures = 1 trong Top 10 web security risk 2021 OWASP; bao gồm 2 mặt: (1) KHÔNG đủ log (security event không track → forensic incident không truy được); (2) log SAI cách (PII raw → vi phạm privacy law + data breach exposed). Mặt 2 là focus B80. Scenario raw log password exploit: dev junior log tracing::info!(email = %dto.email, password = %dto.password, "login attempt") debug auth flow — code merge production; mọi login event ghi password plaintext vào log aggregator (Datadog retain 30 ngày, 100M event); 6 tháng sau employee bị social-engineered cung cấp Datadog credential cho attacker; attacker query {app="shop-api"} | json | password!="" trả 100M password user kèm email → mass account takeover; Shop bị GDPR phạt 4% revenue (€20M cho công ty €500M), CCPA class action lawsuit $750/user × 100M = $75B liability, reputation damage permanent. Scenario raw log phone full: log phone = %user.phone "0912345678" + address = %user.address "123 Nguyễn Trãi Hà Nội" → log aggregator search bằng phone trả full profile user + order history + payment history → SIM swap attack (đổi SIM nhà mạng giả mạo ID) + stalking + phishing target. Pattern mask_* helper lock B80: file crates/shop-common/src/sanitize.rs chứa 3 function: mask_phone(s) giữ last 4 → "***5678", mask_card(s) giữ last 4 → "****-****-****-4242" (PCI DSS yêu cầu), mask_email(s) giữ char đầu + domain → "u***@example.com". Helper pattern: if s.len() <= 4 return "****" defensive nhỏ; format!("***{}", &s[s.len()-4..]) last 4 char. Pattern lock Shop API vĩnh viễn: (a) KHÔNG bao giờ log raw password / password_hash / CVV / PIN / OTP / JWT raw / API key / secret — strict skip; (b) phone / card / national ID mask last 4; (c) email mask local part trừ char đầu; (d) full name mask first name + last name initial "Nguyễn V*** A***"; (e) address mask street + giữ city — "*** Hà Nội"; (f) IP address mask last octet "192.168.1.***"; (g) DOB mask day + month "1990-**-**"; (h) sensitive header Authorization/Cookie/X-API-Key redact "[REDACTED]" trước khi log header map. Enforce: code review checklist + clippy lint custom shop_clippy::raw_pii_in_log grep regex tracing::(info|warn|error|debug)!.*(password|phone|email|card) warn dev; G19 thêm Vector/Fluent Bit redaction layer drop-in defense in depth: stream log qua sidecar regex replace "password":"[^"]+""password":"[REDACTED]" trước khi ship aggregator (nếu dev quên mask trong code thì sidecar catch). Lock B80 + G19: 2 layer defense (app-level mask + infra-level redaction). Compliance: GDPR Article 32 (data protection by design), PCI DSS Requirement 3 (cardholder data protection), HIPAA §164.312 (audit log encryption), Nghị định 13/2023 Điều 7 (bảo vệ dữ liệu cá nhân).
11

Bài Tiếp Theo

— refactor /metrics endpoint B57 với crate metrics + metrics-exporter-prometheus, expose 4 metric type (counter / gauge / histogram / summary), HTTP request metrics middleware track request_count + response_time_histogram + error_rate per route, Prometheus scrape config + Grafana dashboard preview.