Improve logs: add target, identify running service, identify request

[josecelano]

Relates to: #387

When you run the tracker with info log level you see something like:

Starting:

Loading default configuration file: `./share/default/config/tracker.development.sqlite3.toml` ...
2024-01-12T09:14:39.457741276+00:00 [torrust_tracker::bootstrap::logging][INFO] logging initialized.
2024-01-12T09:14:39.458258441+00:00 [UDP Tracker][INFO] Starting on: udp://0.0.0.0:6969
2024-01-12T09:14:39.458310899+00:00 [UDP Tracker][INFO] Started on: udp://0.0.0.0:6969
2024-01-12T09:14:39.458331488+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled
2024-01-12T09:14:39.458409276+00:00 [HTTP Tracker][INFO] Starting on: http://0.0.0.0:7070
2024-01-12T09:14:39.458425826+00:00 [HTTP Tracker][INFO] Started on: http://0.0.0.0:7070
2024-01-12T09:14:39.458431496+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled
2024-01-12T09:14:39.458516663+00:00 [API][INFO] Starting on http://127.0.0.1:1212
2024-01-12T09:14:39.458519593+00:00 [API][INFO] Started on http://127.0.0.1:1212
2024-01-12T09:14:39.458532263+00:00 [Health Check API][INFO] Starting on: http://127.0.0.1:1313
2024-01-12T09:14:39.458575981+00:00 [Health Check API][INFO] Started on: http://127.0.0.1:1313

Finishing:

2024-01-12T09:14:54.200599386+00:00 [torrust_tracker][INFO] Torrust shutting down..
2024-01-12T09:14:54.200603706+00:00 [torrust_tracker::servers::signals][INFO] Global shutdown signal processed
2024-01-12T09:14:54.200640756+00:00 [torrust_tracker::servers::signals][INFO] Global shutdown signal processed
2024-01-12T09:14:54.200625836+00:00 [torrust_tracker::servers::health_check_api::server][INFO] Stopping Torrust Health Check API server o http://127.0.0.1:1313 ...
2024-01-12T09:14:54.200647715+00:00 [torrust_tracker::servers::signals][INFO] Global shutdown signal processed
2024-01-12T09:14:54.200677215+00:00 [torrust_tracker::servers::signals][INFO] Shutting down UDP server on socket address: udp://0.0.0.0:6969
2024-01-12T09:14:54.200658765+00:00 [torrust_tracker::servers::signals][INFO] Shutting down tracker API server on socket address: 127.0.0.1:1212
2024-01-12T09:14:54.200662015+00:00 [torrust_tracker::bootstrap::jobs::torrent_cleanup][INFO] Stopping torrent cleanup job..
2024-01-12T09:14:54.200686095+00:00 [torrust_tracker::servers::signals][INFO] Sending graceful shutdown signal
!! shuting down in 90 seconds !!
2024-01-12T09:14:54.200703515+00:00 [Health Check API][INFO] Stopped server running on: http://127.0.0.1:1313
2024-01-12T09:14:54.200648515+00:00 [torrust_tracker::servers::signals][INFO] Shutting down HTTP server on socket address: 0.0.0.0:7070
2024-01-12T09:14:54.200717685+00:00 [torrust_tracker::servers::signals][INFO] Sending graceful shutdown signal
!! shuting down in 90 seconds !!
2024-01-12T09:14:54.200771174+00:00 [torrust_tracker][INFO] Torrust successfully shutdown.

I have started replacing the context with the module namespace with a service ID.

• [torrust_tracker::bootstrap::logging]: this is what I call a namespaced context for the log.
• [UDP Tracker], [HTTP Tracker], [Health Check API]: those are permanent service identifiers.

The main advantage is logs are not coupled with implementation details.

I've also added the URL when started services are listening on, for example:

2024-01-12T09:14:39.458310899+00:00 [UDP Tracker][INFO] Started on: udp://0.0.0.0:6969

This is also useful because allows easily identifying running services for developers or other services.

Some services like GitHub Codespaces use the log to auto-discover exposed ports and to automatically port forwarding.

There are still some logs that use the namespaced context like:

2024-01-12T09:14:39.458331488+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled
2024-01-12T09:14:39.458431496+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled
...
2024-01-12T09:14:54.200625836+00:00 [torrust_tracker::servers::health_check_api::server][INFO] Stopping Torrust Health Check API server o http://127.0.0.1:1313 ...
2024-01-12T09:14:54.200677215+00:00 [torrust_tracker::servers::signals][INFO] Shutting down UDP server on socket address: udp://0.0.0.0:6969
2024-01-12T09:14:54.200658765+00:00 [torrust_tracker::servers::signals][INFO] Shutting down tracker API server on socket address: 127.0.0.1:1212
...

It would be convenient to change also those records.

There is also another extra critical improvement. The tracker can run multiple HTTP trackers and multiple UDP trackers. It's very important to identify which one the log line refers to. In some lines, I've added the socket address which, I think, is the best identifier for the service. Since all services are exposed via a socket. For example:

2024-01-12T09:14:39.458258441+00:00 [UDP Tracker][INFO] Starting on: udp://0.0.0.0:6969

However, not all lines identify the service the logs belong to. For example:

2024-01-12T09:14:39.458331488+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled

In this case, we don't know which service has not enabled TLS: the API, one of the HTTP trackers?

We should add, for example, the bind_address somewhere to the log line.

Proposals

Proposal 1

It could be the target:

2024-01-12T09:14:39.458310899+00:00 [UDP Tracker::0.0.0.0:6969][INFO] Started on: udp://0.0.0.0:6969

Proposal 2

It could be in the main body like this:

2024-01-12T09:14:39.458310899+00:00 [UDP Tracker][INFO] 0.0.0.0:6969 - Started on: udp://0.0.0.0:6969

Conclusion

I think I would use the proposal 2. I think the target should be used for things at compilation time and the body for things at runtime. But it's only my first impression.

Maybe we could use an enum for the body to force a certain format.

This could not be a priority since I don't think many people will run multiple trackers at the same time. In fact, I do not know if that's even a useful feature. Why would someone want to run multiple trackers with the same configuration and different ports @WarmBeer?

Tasks

• Replace all namespaced log lines with a target. At least for the info log level.
• Identify the concrete running socket service (potentially by using the bound address).

[mickvandijke]

Relates to: #387

When you run the tracker with info log level you see something like:

Starting:

Loading default configuration file: `./share/default/config/tracker.development.sqlite3.toml` ...
2024-01-12T09:14:39.457741276+00:00 [torrust_tracker::bootstrap::logging][INFO] logging initialized.
2024-01-12T09:14:39.458258441+00:00 [UDP Tracker][INFO] Starting on: udp://0.0.0.0:6969
2024-01-12T09:14:39.458310899+00:00 [UDP Tracker][INFO] Started on: udp://0.0.0.0:6969
2024-01-12T09:14:39.458331488+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled
2024-01-12T09:14:39.458409276+00:00 [HTTP Tracker][INFO] Starting on: http://0.0.0.0:7070
2024-01-12T09:14:39.458425826+00:00 [HTTP Tracker][INFO] Started on: http://0.0.0.0:7070
2024-01-12T09:14:39.458431496+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled
2024-01-12T09:14:39.458516663+00:00 [API][INFO] Starting on http://127.0.0.1:1212
2024-01-12T09:14:39.458519593+00:00 [API][INFO] Started on http://127.0.0.1:1212
2024-01-12T09:14:39.458532263+00:00 [Health Check API][INFO] Starting on: http://127.0.0.1:1313
2024-01-12T09:14:39.458575981+00:00 [Health Check API][INFO] Started on: http://127.0.0.1:1313

Finishing:

2024-01-12T09:14:54.200599386+00:00 [torrust_tracker][INFO] Torrust shutting down..
2024-01-12T09:14:54.200603706+00:00 [torrust_tracker::servers::signals][INFO] Global shutdown signal processed
2024-01-12T09:14:54.200640756+00:00 [torrust_tracker::servers::signals][INFO] Global shutdown signal processed
2024-01-12T09:14:54.200625836+00:00 [torrust_tracker::servers::health_check_api::server][INFO] Stopping Torrust Health Check API server o http://127.0.0.1:1313 ...
2024-01-12T09:14:54.200647715+00:00 [torrust_tracker::servers::signals][INFO] Global shutdown signal processed
2024-01-12T09:14:54.200677215+00:00 [torrust_tracker::servers::signals][INFO] Shutting down UDP server on socket address: udp://0.0.0.0:6969
2024-01-12T09:14:54.200658765+00:00 [torrust_tracker::servers::signals][INFO] Shutting down tracker API server on socket address: 127.0.0.1:1212
2024-01-12T09:14:54.200662015+00:00 [torrust_tracker::bootstrap::jobs::torrent_cleanup][INFO] Stopping torrent cleanup job..
2024-01-12T09:14:54.200686095+00:00 [torrust_tracker::servers::signals][INFO] Sending graceful shutdown signal
!! shuting down in 90 seconds !!
2024-01-12T09:14:54.200703515+00:00 [Health Check API][INFO] Stopped server running on: http://127.0.0.1:1313
2024-01-12T09:14:54.200648515+00:00 [torrust_tracker::servers::signals][INFO] Shutting down HTTP server on socket address: 0.0.0.0:7070
2024-01-12T09:14:54.200717685+00:00 [torrust_tracker::servers::signals][INFO] Sending graceful shutdown signal
!! shuting down in 90 seconds !!
2024-01-12T09:14:54.200771174+00:00 [torrust_tracker][INFO] Torrust successfully shutdown.

I have started replacing the context with the module namespace with a service ID.

* `[torrust_tracker::bootstrap::logging]`: this is what I call a namespaced context for the log.

* `[UDP Tracker]`, `[HTTP Tracker]`, [Health Check API]: those are permanent service identifiers.

The main advantage is logs are not coupled with implementation details.

I've also added the URL when started services are listening on, for example:

2024-01-12T09:14:39.458310899+00:00 [UDP Tracker][INFO] Started on: udp://0.0.0.0:6969

This is also useful because allows easily identifying running services for developers or other services.

Some services like GitHub Codespaces use the log to auto-discover exposed ports and to automatically port forwarding.

There are still some logs that use the namespaced context like:

2024-01-12T09:14:39.458331488+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled
2024-01-12T09:14:39.458431496+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled
...
2024-01-12T09:14:54.200625836+00:00 [torrust_tracker::servers::health_check_api::server][INFO] Stopping Torrust Health Check API server o http://127.0.0.1:1313 ...
2024-01-12T09:14:54.200677215+00:00 [torrust_tracker::servers::signals][INFO] Shutting down UDP server on socket address: udp://0.0.0.0:6969
2024-01-12T09:14:54.200658765+00:00 [torrust_tracker::servers::signals][INFO] Shutting down tracker API server on socket address: 127.0.0.1:1212
...

It would be convenient to change also those records.

There is also another extra critical improvement. The tracker can run multiple HTTP trackers and multiple UDP trackers. It's very important to identify which one the log line refers to. In some lines, I've added the socket address which, I think, is the best identifier for the service. Since all services are exposed via a socket. For example:

2024-01-12T09:14:39.458258441+00:00 [UDP Tracker][INFO] Starting on: udp://0.0.0.0:6969

However, not all lines identify the service the logs belong to. For example:

2024-01-12T09:14:39.458331488+00:00 [torrust_tracker::bootstrap::jobs][INFO] TLS not enabled

In this case, we don't know which service has not enabled TLS: the API, one of the HTTP trackers?

We should add, for example, the bind_address somewhere to the log line.

Proposals

Proposal 1

It could be the target:

2024-01-12T09:14:39.458310899+00:00 [UDP Tracker::0.0.0.0:6969][INFO] Started on: udp://0.0.0.0:6969

Proposal 2

It could be in the main body like this:

2024-01-12T09:14:39.458310899+00:00 [UDP Tracker][INFO] 0.0.0.0:6969 - Started on: udp://0.0.0.0:6969

Conclusion

I think I would use the proposal 2. I think the target should be used for things at compilation time and the body for things at runtime. But it's only my first impression.

Maybe we could use an enum for the body to force a certain format.

This could not be a priority since I don't think many people will run multiple trackers at the same time. In fact, I do not know if that's even a useful feature. Why would someone want to run multiple trackers with the same configuration and different ports @WarmBeer?

Tasks

* [ ]  Replace all namespaced log lines with a target. At least for the `info` log level.

* [ ]  Identify the concrete running socket service (potentially by using the bound address).

I think proposal 2 works as well.

This could not be a priority since I don't think many people will run multiple trackers at the same time. In fact, I do not know if that's even a useful feature. Why would someone want to run multiple trackers with the same configuration and different ports @WarmBeer?

I don't see a reason either why someone would need multiple trackers with the same config.

[josecelano]

@da2ce7 suggested:

• Use a UUID to identify the request (an link the response to the request).
• Use a shorter target for the tracker service:

Instead of:

2024-01-12T09:14:39.458258441+00:00 [UDP Tracker][INFO] Starting on: udp://0.0.0.0:6969
2024-01-12T09:14:39.458310899+00:00 [UDP Tracker][INFO] Started on: udp://0.0.0.0:6969

We could do this:

2024-01-12T09:14:39.458258441+00:00 [UDP::0.0.0.0:6969][INFO] Starting on: udp://0.0.0.0:6969
2024-01-12T09:14:39.458310899+00:00 [UDP::0.0.0.0:6969][INFO] Started on: udp://0.0.0.0:6969
2024-02-08T13:48:26.816333312+00:00 [UDP::0.0.0.0:6969][INFO] "CONNECT REQ TxID -1874681766 RqID 43b09349-82fa-4196-9f8f-f33024d24c15
"
2024-02-08T13:48:26.818308560+00:00 [UDP::0.0.0.0:6969][INFO] "ANNOUNCE REQ TxID 896800714 IH f38a04e46bd9839be59f736742e3893e5f034fcf RqID 75fdf319-b073-4048-ae99-15bf68d610b5"

Request IDs would be included in the responses. Currently, we are not logging responses. This is a proposal:

2024-02-08T13:48:26.816333312+00:00 [UDP::0.0.0.0:6969][INFO] "CONNECT RES TxID -1874681766 RqID 43b09349-82fa-4196-9f8f-f33024d24c15
"
2024-02-08T13:48:26.818308560+00:00 [UDP::0.0.0.0:6969][INFO] "ANNOUNCE RES TxID 896800714 IH f38a04e46bd9839be59f736742e3893e5f034fcf RqID 75fdf319-b073-4048-ae99-15bf68d610b5"

What do you think @da2ce7?

[josecelano]

In the end, I have used a param (server_socket_addr) to identify the running service:

2024-02-19T13:29:02.301023716+00:00 [HTTP TRACKER][INFO] request; server_socket_addr=0.0.0.0:7070 method=GET uri=/scrape?info_hash=%44%3C%76%02%B4%FD%E8%3D%11%54%D6%D9%DA%48%80%84%18%B1%81%B6 request_id=2c4aa57d-dd12-4cb8-95d1-e8193627c106
2024-02-19T13:29:02.301095545+00:00 [HTTP TRACKER][INFO] response; server_socket_addr=0.0.0.0:7070 latency=0 status=200 OK request_id=2c4aa57d-dd12-4cb8-95d1-e8193627c106

Instead of the "target". I think:

• Parsing all HTTP requests from all HTTP trackers is more common than filtering out requests per HTTP tracker.
• And it's also more common to run a single HTTP Tracker.

[josecelano]

Implemented via:

• Refactor UDP Tracker logs #703
• Add logs to HTTP tracker #702
• Add logs to Health Check API #701
• Tracker API: log request and responses #699

Finally, the service identification is not done via the target but with a param (server_socket_addr). For example, for the UDP tracker:

2024-02-19T17:10:05.243973520+00:00 [UDP TRACKER][INFO] request; server_socket_addr=0.0.0.0:6969 action=CONNECT transaction_id=-888840697 request_id=03b92de0-c9f8-4c40-a808-5d706ce770f4
2024-02-19T17:10:05.244016141+00:00 [UDP TRACKER][INFO] response; server_socket_addr=0.0.0.0:6969 transaction_id=-888840697 request_id=03b92de0-c9f8-4c40-a808-5d706ce770f4
2024-02-19T17:10:05.244042841+00:00 [UDP TRACKER][INFO] request; server_socket_addr=0.0.0.0:6969 action=ANNOUNCE transaction_id=-888840697 request_id=2113eb8c-61f4-476b-b3d5-02892f0a2fdb connection_id=-7190270103145546231 info_hash=9c38422213e30bff212b30c360d26f9a02136422
2024-02-19T17:10:05.244052082+00:00 [UDP TRACKER][INFO] response; server_socket_addr=0.0.0.0:6969 transaction_id=-888840697 request_id=2113eb8c-61f4-476b-b3d5-02892f0a2fdb