Overhaul logging #485

josecelano · 2024-02-12T13:36:34Z

Overhaul logging.

Improve tracker stats importer logs.
Improve tracker API logs.
- Enable default logging for Axum API requests.
- Link requests and responses with an ID.
- Add target API to the log lines.

New format using a "target" ("TrackerStats Importer") and more info like the time spent and tracker URL. ```2024-02-12T13:32:50.123422513+00:00 [Tracker Stats Importer][INFO] Importing 2 torrents statistics from tracker udp://localhost:6969 ... 2024-02-12T13:32:50.123461943+00:00 [Tracker Stats Importer][INFO] Importing torrent torrust#1 ... 2024-02-12T13:32:50.242154360+00:00 [Tracker Stats Importer][INFO] Importing torrent torrust#2 ... 2024-02-12T13:32:50.243383523+00:00 [Tracker Stats Importer][INFO] Statistics import completed in 119.92ms ```

- tower-http = { version = "0", features = ["compression-full", "cors", "trace"] } - trace = "0.1.7" - tracing = "0.1.40" They will be use to add logs to HTTP API requests.

This change enables the default logging for HTTP requests to the API: ``` 2024-02-12T14:15:15.546548923+00:00 [tower_http::trace::make_span][INFO] request; method=GET uri=/v1/about version=HTTP/1.1 2024-02-12T14:15:15.546840151+00:00 [tower_http::trace::on_response][INFO] finished processing request latency=0 ms status=200 2024-02-12T14:15:34.754336133+00:00 [tower_http::trace::make_span][INFO] request; method=GET uri=/v1/about/license version=HTTP/1.1 2024-02-12T14:15:34.754544571+00:00 [tower_http::trace::on_response][INFO] finished processing request latency=0 ms status=200 ```

Add new features to `tower-http` crate to propagate the request ID to the response. If the request does not have an ID it sets a newly generated UUID. ``` $ curl -i localhost:3001/v1/about/license HTTP/1.1 200 OK content-type: text/html; charset=utf-8 content-length: 1262 x-request-id: cea0efcd-84e0-4f59-96b3-625ca4154396 date: Mon, 12 Feb 2024 16:58:05 GMT ``` ``` $ curl -i -H "x-request-id: a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3" localhost:3001/v1/about/license HTTP/1.1 200 OK content-type: text/html; charset=utf-8 content-length: 1262 x-request-id: a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3 date: Mon, 12 Feb 2024 16:59:31 GMT ``` This commit onlu adds the needed features.

It propagates the request ID to the response. If the request does not have an ID it sets a newly generated UUID. Without providing ID: ``` $ curl -i localhost:3001/v1/about/license HTTP/1.1 200 OK content-type: text/html; charset=utf-8 content-length: 1262 x-request-id: cea0efcd-84e0-4f59-96b3-625ca4154396 date: Mon, 12 Feb 2024 16:58:05 GMT ``` Providing ID: ``` $ curl -i -H "x-request-id: a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3" localhost:3001/v1/about/license HTTP/1.1 200 OK content-type: text/html; charset=utf-8 content-length: 1262 x-request-id: a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3 date: Mon, 12 Feb 2024 16:59:31 GMT ``` The response contains the provided ID in the request.

``` 2024-02-12T18:20:13.114426999+00:00 [API][INFO] finished processing request; latency=0 status=200 OK request_id=a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3 ``:Wq

``` 2024-02-12T18:24:13.404193511+00:00 [API][INFO] request; method=GET uri=/v1/about/license request_id=a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3 2024-02-12T18:24:13.404380120+00:00 [API][INFO] response; latency=0 status=200 OK request_id=a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3 ``` Add - request id - uri - method

josecelano · 2024-02-12T18:40:20Z

It's almost finished but it does not work when the request ID is not provided by the client:

No request ID from the client (it should set one with SetRequestIdLayer middleware:

curl -i localhost:3001/v1/about/license

2024-02-12T18:34:30.331362304+00:00 [API][INFO] request; method=GET uri=/v1/about/license request_id=
2024-02-12T18:34:30.331575353+00:00 [API][INFO] response; latency=0 status=200 OK request_id=

Request ID provided by the client:

curl -i -H "x-request-id: a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3" localhost:3001/v1/about/license

2024-02-12T18:35:06.346733541+00:00 [API][INFO] request; method=GET uri=/v1/about/license request_id=a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3
2024-02-12T18:35:06.346932750+00:00 [API][INFO] response; latency=0 status=200 OK request_id=a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3

Maybe it's something related to the middleware order.

@da2ce7 if I can't finally fix this problem the solution only uses official middlewares from the tower-http crate.

josecelano · 2024-02-12T18:46:43Z

It's almost finished but it does not work when the request ID is not provided by the client:

No request ID from the client (it should set one with SetRequestIdLayer middleware:
curl -i localhost:3001/v1/about/license

2024-02-12T18:34:30.331362304+00:00 [API][INFO] request; method=GET uri=/v1/about/license request_id=
2024-02-12T18:34:30.331575353+00:00 [API][INFO] response; latency=0 status=200 OK request_id=
Request ID provided by the client:
curl -i -H "x-request-id: a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3" localhost:3001/v1/about/license

2024-02-12T18:35:06.346733541+00:00 [API][INFO] request; method=GET uri=/v1/about/license request_id=a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3
2024-02-12T18:35:06.346932750+00:00 [API][INFO] response; latency=0 status=200 OK request_id=a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3
Maybe it's something related to the middleware order.

@da2ce7 if I can't finally fix this problem the solution only uses official middlewares from the tower-http crate.

It seems I only needed to duplicate the layers. See https://docs.rs/axum/latest/axum/middleware/index.html#ordering

When the client does not provide a request ID it generates one and it's also inclueded in the logs. This commtis fixes the missing request id in the logs for this case. Output without this patch: ``` curl -i localhost:3001/v1/about/license 2024-02-12T18:34:30.331362304+00:00 [API][INFO] request; method=GET uri=/v1/about/license request_id= 2024-02-12T18:34:30.331575353+00:00 [API][INFO] response; latency=0 status=200 OK request_id= ```

Issues introduced in this PR: torrust#484

josecelano · 2024-02-12T21:47:18Z

ACK 1e96237

josecelano requested a review from da2ce7 February 12, 2024 13:36

josecelano had a problem deploying to coverage February 12, 2024 13:36 — with GitHub Actions Failure

josecelano added this to the v3.0.0 milestone Feb 12, 2024

josecelano linked an issue Feb 12, 2024 that may be closed by this pull request

Overhaul logging #468

Closed

josecelano self-assigned this Feb 12, 2024

josecelano added Enhancement / Feature Request Something New - System Admin - Enjoyable to Install and Setup our Software labels Feb 12, 2024

chore: [torrust#468] add cargo dependencies for tracing

c1e01f8

- tower-http = { version = "0", features = ["compression-full", "cors", "trace"] } - trace = "0.1.7" - tracing = "0.1.40" They will be use to add logs to HTTP API requests.

josecelano had a problem deploying to coverage February 12, 2024 14:23 — with GitHub Actions Failure

josecelano added 3 commits February 12, 2024 16:34

josecelano force-pushed the 468-overhaul-logging branch from eb85fb9 to db6a62f Compare February 12, 2024 17:05

josecelano had a problem deploying to coverage February 12, 2024 17:05 — with GitHub Actions Failure

feat: [torrust#468] add request id to response log

91f818e

``` 2024-02-12T18:20:13.114426999+00:00 [API][INFO] finished processing request; latency=0 status=200 OK request_id=a5030c7a-5302-49d4-8e66-f0f0ab0e3ce3 ``:Wq

josecelano had a problem deploying to coverage February 12, 2024 18:21 — with GitHub Actions Failure

josecelano had a problem deploying to coverage February 12, 2024 18:25 — with GitHub Actions Failure

josecelano marked this pull request as ready for review February 12, 2024 18:25

josecelano marked this pull request as draft February 12, 2024 18:34

josecelano had a problem deploying to coverage February 12, 2024 18:46 — with GitHub Actions Failure

josecelano marked this pull request as ready for review February 12, 2024 18:46

josecelano mentioned this pull request Feb 12, 2024

Overhaul logging torrust/torrust-tracker#687

Closed

6 tasks

josecelano added 2 commits February 12, 2024 21:42

ci: fix missing tools in coverage workflow

1e96237

Issues introduced in this PR: torrust#484

josecelano force-pushed the 468-overhaul-logging branch from bbbb9ca to 1e96237 Compare February 12, 2024 21:46

josecelano requested a review from a team as a code owner February 12, 2024 21:46

josecelano had a problem deploying to coverage February 12, 2024 21:46 — with GitHub Actions Failure

josecelano merged commit c9d9ff3 into torrust:develop Feb 12, 2024
12 of 13 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Overhaul logging #485

Overhaul logging #485

josecelano commented Feb 12, 2024 •

edited

Loading

josecelano commented Feb 12, 2024 •

edited

Loading

josecelano commented Feb 12, 2024

josecelano commented Feb 12, 2024

Overhaul logging #485

Overhaul logging #485

Conversation

josecelano commented Feb 12, 2024 • edited Loading

josecelano commented Feb 12, 2024 • edited Loading

josecelano commented Feb 12, 2024

josecelano commented Feb 12, 2024

josecelano commented Feb 12, 2024 •

edited

Loading

josecelano commented Feb 12, 2024 •

edited

Loading