From 97233f57aa9595e05bc6d44ad2dd41ae1087e3de Mon Sep 17 00:00:00 2001 From: Jose Celano Date: Mon, 23 Dec 2024 17:55:04 +0000 Subject: [PATCH] fix: missing logs for HTTP requests Some tracing log spans were missing. In adition to that we were using new spans to log requests and responses instead of using the span provided by the TraceLayer. That enables to join all the log events related tho the same requests. This fix is needed to contunie with this issue: https://github.com/torrust/torrust-tracker/issues/1150 Becuase it allos to use a "request-id" header to identify logs. We can write log assertions by mathich lines with the request-id used in the request. For example, it yo make this request: ```console curl -H "x-request-id: YOUR_REQUEST_ID" http://0.0.0.0:1212/api/v1/stats?token=InvalidToken ``` This is the new output (which was missing before this change): ```output 2024-12-23T17:53:06.530704Z INFO request{method=GET uri=/api/v1/stats?token=InvalidToken version=HTTP/1.1}: API: request method=GET uri=/api/v1/stats?token=InvalidToken request_id=YOUR_REQUEST_ID 2024-12-23T17:53:06.530777Z ERROR request{method=GET uri=/api/v1/stats?token=InvalidToken version=HTTP/1.1}: API: response latency_ms=0 status_code=500 Internal Server Error request_id=YOUR_REQUEST_ID 2024-12-23T17:53:06.530785Z ERROR request{method=GET uri=/api/v1/stats?token=InvalidToken version=HTTP/1.1}: API: response failed failure_classification=Status code: 500 Internal Server Error latency=0 ms ``` As you can see. now we have the "request_id=YOUR_REQUEST_ID" field which can be used to identify the test that made the request. --- src/servers/apis/routes.rs | 42 +++++++++++++++--------- src/servers/health_check_api/server.rs | 42 +++++++++++++++--------- src/servers/http/v1/routes.rs | 44 ++++++++++++++++---------- 3 files changed, 82 insertions(+), 46 deletions(-) diff --git a/src/servers/apis/routes.rs b/src/servers/apis/routes.rs index 2ae42260..c021cb21 100644 --- a/src/servers/apis/routes.rs +++ b/src/servers/apis/routes.rs @@ -53,7 +53,7 @@ pub fn router(tracker: Arc, access_tokens: Arc) -> Router .layer( TraceLayer::new_for_http() .make_span_with(DefaultMakeSpan::new().level(Level::INFO)) - .on_request(|request: &Request, _span: &Span| { + .on_request(|request: &Request, span: &Span| { let method = request.method().to_string(); let uri = request.uri().to_string(); let request_id = request @@ -62,30 +62,42 @@ pub fn router(tracker: Arc, access_tokens: Arc) -> Router .map(|v| v.to_str().unwrap_or_default()) .unwrap_or_default(); - tracing::span!( + span.record("request_id", request_id); + + tracing::event!( target: API_LOG_TARGET, - tracing::Level::INFO, "request", method = %method, uri = %uri, request_id = %request_id); + tracing::Level::INFO, %method, %uri, %request_id, "request"); }) - .on_response(|response: &Response, latency: Duration, _span: &Span| { + .on_response(|response: &Response, latency: Duration, span: &Span| { + let latency_ms = latency.as_millis(); let status_code = response.status(); let request_id = response .headers() .get("x-request-id") .map(|v| v.to_str().unwrap_or_default()) .unwrap_or_default(); - let latency_ms = latency.as_millis(); - tracing::span!( - target: API_LOG_TARGET, - tracing::Level::INFO, "response", latency = %latency_ms, status = %status_code, request_id = %request_id); - }) - .on_failure(|failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| { - let latency = Latency::new( - LatencyUnit::Millis, - latency, - ); - tracing::error!(target: API_LOG_TARGET, "response failed classification={failure_classification} latency={latency}"); + span.record("request_id", request_id); + + if status_code.is_server_error() { + tracing::event!( + target: API_LOG_TARGET, + tracing::Level::ERROR, %latency_ms, %status_code, %request_id, "response"); + } else { + tracing::event!( + target: API_LOG_TARGET, + tracing::Level::INFO, %latency_ms, %status_code, %request_id, "response"); + } }) + .on_failure( + |failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| { + let latency = Latency::new(LatencyUnit::Millis, latency); + + tracing::event!( + target: API_LOG_TARGET, + tracing::Level::ERROR, %failure_classification, %latency, "response failed"); + }, + ), ) .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid)) .layer( diff --git a/src/servers/health_check_api/server.rs b/src/servers/health_check_api/server.rs index f8ca65b8..42111f50 100644 --- a/src/servers/health_check_api/server.rs +++ b/src/servers/health_check_api/server.rs @@ -51,7 +51,7 @@ pub fn start( .layer( TraceLayer::new_for_http() .make_span_with(DefaultMakeSpan::new().level(Level::INFO)) - .on_request(|request: &Request, _span: &Span| { + .on_request(|request: &Request, span: &Span| { let method = request.method().to_string(); let uri = request.uri().to_string(); let request_id = request @@ -60,30 +60,42 @@ pub fn start( .map(|v| v.to_str().unwrap_or_default()) .unwrap_or_default(); - tracing::span!( + span.record("request_id", request_id); + + tracing::event!( target: HEALTH_CHECK_API_LOG_TARGET, - tracing::Level::INFO, "request", method = %method, uri = %uri, request_id = %request_id); + tracing::Level::INFO, %method, %uri, %request_id, "request"); }) - .on_response(|response: &Response, latency: Duration, _span: &Span| { + .on_response(|response: &Response, latency: Duration, span: &Span| { + let latency_ms = latency.as_millis(); let status_code = response.status(); let request_id = response .headers() .get("x-request-id") .map(|v| v.to_str().unwrap_or_default()) .unwrap_or_default(); - let latency_ms = latency.as_millis(); - tracing::span!( - target: HEALTH_CHECK_API_LOG_TARGET, - tracing::Level::INFO, "response", latency = %latency_ms, status = %status_code, request_id = %request_id); - }) - .on_failure(|failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| { - let latency = Latency::new( - LatencyUnit::Millis, - latency, - ); - tracing::error!(target: HEALTH_CHECK_API_LOG_TARGET, "response failed classification={failure_classification} latency={latency}"); + span.record("request_id", request_id); + + if status_code.is_server_error() { + tracing::event!( + target: HEALTH_CHECK_API_LOG_TARGET, + tracing::Level::ERROR, %latency_ms, %status_code, %request_id, "response"); + } else { + tracing::event!( + target: HEALTH_CHECK_API_LOG_TARGET, + tracing::Level::INFO, %latency_ms, %status_code, %request_id, "response"); + } }) + .on_failure( + |failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| { + let latency = Latency::new(LatencyUnit::Millis, latency); + + tracing::event!( + target: HEALTH_CHECK_API_LOG_TARGET, + tracing::Level::ERROR, %failure_classification, %latency, "response failed"); + }, + ), ) .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid)); diff --git a/src/servers/http/v1/routes.rs b/src/servers/http/v1/routes.rs index 6eacb1e5..a5d40269 100644 --- a/src/servers/http/v1/routes.rs +++ b/src/servers/http/v1/routes.rs @@ -50,7 +50,7 @@ pub fn router(tracker: Arc, server_socket_addr: SocketAddr) -> Router { .layer( TraceLayer::new_for_http() .make_span_with(DefaultMakeSpan::new().level(Level::INFO)) - .on_request(move |request: &Request, _span: &Span| { + .on_request(move |request: &Request, span: &Span| { let method = request.method().to_string(); let uri = request.uri().to_string(); let request_id = request @@ -59,33 +59,45 @@ pub fn router(tracker: Arc, server_socket_addr: SocketAddr) -> Router { .map(|v| v.to_str().unwrap_or_default()) .unwrap_or_default(); - tracing::span!( + span.record("request_id", request_id); + + tracing::event!( target: HTTP_TRACKER_LOG_TARGET, - tracing::Level::INFO, "request", server_socket_addr= %server_socket_addr, method = %method, uri = %uri, request_id = %request_id); + tracing::Level::INFO, %server_socket_addr, %method, %uri, %request_id, "request"); }) - .on_response(move |response: &Response, latency: Duration, _span: &Span| { + .on_response(move |response: &Response, latency: Duration, span: &Span| { + let latency_ms = latency.as_millis(); let status_code = response.status(); let request_id = response .headers() .get("x-request-id") .map(|v| v.to_str().unwrap_or_default()) .unwrap_or_default(); - let latency_ms = latency.as_millis(); - tracing::span!( - target: HTTP_TRACKER_LOG_TARGET, - tracing::Level::INFO, "response", server_socket_addr= %server_socket_addr, latency = %latency_ms, status = %status_code, request_id = %request_id); - }) - .on_failure(|failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| { - let latency = Latency::new( - LatencyUnit::Millis, - latency, - ); - tracing::error!(target: HTTP_TRACKER_LOG_TARGET, "response failed classification={failure_classification} latency={latency}"); + span.record("request_id", request_id); + + if status_code.is_server_error() { + tracing::event!( + target: HTTP_TRACKER_LOG_TARGET, + tracing::Level::ERROR, %server_socket_addr, %latency_ms, %status_code, %request_id, "response"); + } else { + tracing::event!( + target: HTTP_TRACKER_LOG_TARGET, + tracing::Level::INFO, %server_socket_addr, %latency_ms, %status_code, %request_id, "response"); + } }) + .on_failure( + |failure_classification: ServerErrorsFailureClass, latency: Duration, _span: &Span| { + let latency = Latency::new(LatencyUnit::Millis, latency); + + tracing::event!( + target: HTTP_TRACKER_LOG_TARGET, + tracing::Level::ERROR, %failure_classification, %latency, "response failed"); + }, + ), ) .layer(SetRequestIdLayer::x_request_id(MakeRequestUuid)) - .layer( + .layer( ServiceBuilder::new() // this middleware goes above `TimeoutLayer` because it will receive // errors returned by `TimeoutLayer`