Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Closed
2 tasks
Tracked by #687
josecelano opened this issue Jan 12, 2024 · 4 comments
Closed
2 tasks
Tracked by #687

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

josecelano opened this issue Jan 12, 2024 · 4 comments
Labels
- Admin - Enjoyable to Install and Setup our Software Code Cleanup / Refactoring Tidying and Making Neat Easy Good for Newcomers Enhancement / Feature Request Something New
Milestone
v3.0.0

Comments

@josecelano
Copy link
Member

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).
@josecelano josecelano added Enhancement / Feature Request Something New Code Cleanup / Refactoring Tidying and Making Neat - Admin - Enjoyable to Install and Setup our Software Easy Good for Newcomers labels Jan 12, 2024
@josecelano josecelano changed the title Add target and identify service in logs Add target and identify running service in logs Jan 12, 2024
@mickvandijke
Copy link
Member

mickvandijke commented Jan 12, 2024 •
edited
Loading

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.

@cgbosse cgbosse added this to the v3.0.0 milestone Jan 16, 2024
This was referenced Feb 7, 2024
Closed
Closed
@josecelano josecelano changed the title Add target and identify running service in logs Improve logs: add target, identify running service, identify request Feb 8, 2024
@josecelano
Copy link
Member Author

@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
Copy link
Member Author

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
Copy link
Member Author

Implemented via:

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
- Admin - Enjoyable to Install and Setup our Software Code Cleanup / Refactoring Tidying and Making Neat Easy Good for Newcomers Enhancement / Feature Request Something New
Projects
Torrust Solution
Status: Done
Milestone
v3.0.0
Development

No branches or pull requests
3 participants
@josecelano @mickvandijke @cgbosse