Skip to content

Commit

Permalink
fix: missing logs for HTTP requests
Browse files Browse the repository at this point in the history 
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:

#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.
  • Loading branch information
@josecelano
josecelano committed Dec 23, 2024
1 parent 0f40030 commit 97233f5
Show file tree
Hide file tree
Showing 3 changed files with 82 additions and 46 deletions.
42 changes: 27 additions & 15 deletions src/servers/apis/routes.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,7 @@ pub fn router(tracker: Arc<Tracker>, access_tokens: Arc<AccessTokens>) -> Router
.layer(
TraceLayer::new_for_http()
.make_span_with(DefaultMakeSpan::new().level(Level::INFO))
.on_request(|request: &Request<axum::body::Body>, _span: &Span| {
.on_request(|request: &Request<axum::body::Body>, span: &Span| {
let method = request.method().to_string();
let uri = request.uri().to_string();
let request_id = request
Expand All @@ -62,30 +62,42 @@ pub fn router(tracker: Arc<Tracker>, access_tokens: Arc<AccessTokens>) -> 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(
Expand Down
42 changes: 27 additions & 15 deletions src/servers/health_check_api/server.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -51,7 +51,7 @@ pub fn start(
.layer(
TraceLayer::new_for_http()
.make_span_with(DefaultMakeSpan::new().level(Level::INFO))
.on_request(|request: &Request<axum::body::Body>, _span: &Span| {
.on_request(|request: &Request<axum::body::Body>, span: &Span| {
let method = request.method().to_string();
let uri = request.uri().to_string();
let request_id = request
Expand All @@ -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));

Expand Down
44 changes: 28 additions & 16 deletions src/servers/http/v1/routes.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -50,7 +50,7 @@ pub fn router(tracker: Arc<Tracker>, server_socket_addr: SocketAddr) -> Router {
.layer(
TraceLayer::new_for_http()
.make_span_with(DefaultMakeSpan::new().level(Level::INFO))
.on_request(move |request: &Request<axum::body::Body>, _span: &Span| {
.on_request(move |request: &Request<axum::body::Body>, span: &Span| {
let method = request.method().to_string();
let uri = request.uri().to_string();
let request_id = request
Expand All @@ -59,33 +59,45 @@ pub fn router(tracker: Arc<Tracker>, 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`
Expand Down

0 comments on commit 97233f5

Please sign in to comment.