-
Notifications
You must be signed in to change notification settings - Fork 0
Logging
The logging is implemented with the following features in mind to help with debugging:
- Emailing FinBIF about fatal errors
- Monitoring request start & end for all traffic
- Monitoring exact URIs of all traffic
- Monitoring cached outgoing requests
- Monitoring person & system for incoming requests
- Monitoring time spent per incoming/outgoing request
Fatal errors are logged. All other log levels are simply printed to STDOUT.
The log messages aren't equal for incoming and outgoing requests. Here's a comparison table:
| Event | tag | URI | method | time | person | system | body | response status |
|---|---|---|---|---|---|---|---|---|
| Incoming start | [IncomingRequest] START | ✔ | ✔ | ✘ | ✔ | ✔ | ✘ | ✘ |
| Incoming end | [IncomingRequest] END | ✔ | ✔ | ✔ | ✔ | ✔ | ✔ for errors | ✘ |
| Outgoing start | [RestClientS.../] START | ✔ | ✘ | ✘ | ✘ | ✘ | ✘ | ✘ |
| Outgoing end | [RestClientS.../] END | ✔ | ✔ | ✘ | ✘ | ✘ | ✔ | ✔ |
Let's look at an example of getting person information from the token (the token being sensored here naturally):
// Start of an incoming request "A"
[Nest] 1077440 - 10/16/2024, 1:56:22 PM VERBOSE [IncomingRequest] START GET /person/<PERSON TOKEN> [KE.601] [MA.79896]
// Start of an outgoing request "B", triggered by the incoming request
[Nest] 1077440 - 10/16/2024, 1:56:22 PM VERBOSE [RestClientS.../laji-auth] START GET https://login.laji.fi/laji-auth/token/<PERSON TOKEN>
// End of the outgoing request "B"
[Nest] 1077440 - 10/16/2024, 1:56:22 PM VERBOSE [RestClientS.../laji-auth] END GET https://login.laji.fi/laji-auth/token/<PERSON TOKEN> [STATUS 200] [53ms]
// Another request "C" was served from the cache (no start/end). It was triggered by the incoming request.
[Nest] 1077440 - 10/16/2024, 1:56:22 PM DEBUG [RestClientS.../laji-auth] GET (CACHED) https://login.laji.fi/laji-auth/token/<PERSON TOKEN>
// End of the incoming request "A"
[Nest] 1077440 - 10/16/2024, 1:56:22 PM VERBOSE [IncomingRequest] END GET /person/<PERSON TOKEN> [56ms] [MA.79896] [KE.601]
The incoming request has the tag [IncomingRequest]. Request START & END are logged separately, so we can debug what happens in between. Request method & URI are logged. Body is not by default. For incoming errors, the body is logged.
The response status is not logged for the END of request, because the response can't be intercepted properly in NestJS.
Technically, the logging is done with the src/interceptors/logger.interceptor.
We make all request with the RestClientService, so they have the tag looking something like [RestClientS.../laji-auth]. This is short for [RestClientService/laji-auth]. If the request would be done without the RestClientService, then it would use the "context" in Logger(context: string).
Request method & URI are logged. Bodies are not logged, even for errors. This is just to keep the logs less bloated.
Technically, the logging is implemented with a global axios request interceptor in src/main.ts.