Skip to content

Commit

Permalink
Merge #1153: Fix missing logs for HTTP requests
Browse files Browse the repository at this point in the history 
97233f5 fix: missing logs for HTTP requests (Jose Celano)

Pull request description:

  Relates to:
    - #1150
    - #1152

  Some log lines (tracing spans) were missing. In addition to that, we were using new spans to log requests and responses instead of using the span provided by the `TraceLayer`. That enables you to join all the log events related to the same request.

  This fix is needed to continue with this issue: #1150

  Because it allows the use of a "request-id" header to identify logs.

  We can write log assertions by matching lines with the `request-id` used in the request.

  For example, if you 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 and write a log assertion for that concrete expected line.

ACKs for top commit:
  josecelano:
    ACK 97233f5

Tree-SHA512: 075a3cdeafa735d4a263c942b34594049adc9d42ed5e8a1bef043ffea394bfdae7cf109928f1311d4589f40804c72ebe71c66d6ec5380f5ce472ba9ba5304ad5
  • Loading branch information
@josecelano
josecelano committed Dec 23, 2024
2 parents 0f40030 + 97233f5 commit 64039e5
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 64039e5

Please sign in to comment.