No log shall be lost
Queue based logging system and Unique Request Identifier implementation
Logging is always a crucial part of any complex system. Logs help you identify and fix errors, track system statistics and improve your application. However, if the system grows fast, it’s very easy to end up in a mess of dozens of log channels, log message formats or even different logging systems.
In this article, we will talk about two aspects of logging. In the first part, the Billie logging infrastructure will be explained. In the second part, we will talk about the way to match your logs with the request (and with other logs) — the Request ID.
Logging Infrastructure
Here at Billie, we implemented a custom solution to produce, persist and retrieve logs in a fast and reliable way.
As it can be seen on the chart, all of the services are sending logs to the same queue, where the log messages are being processed by the RabbitMQ consumer. The final destination for the logs is Google Stackdriver — a powerful storage and set of visualization tools for logs (and not only). This approach gives us the following benefits:
- all logs in one place, not like other systems, where logs are written in text files and then being scanned and aggregated;
- one protocol for all services — regardless of the technology, all of the services and applications send logs to the same queue;
- possibility to implement the Request ID, which will be described in the following chapter.
Request ID
… or RID is a way of associating each request with a unique identifier. By doing this and putting this identifier into each log record, we will be able to find all the log entries from all the services and channels which were produced during exactly that request. The RID can be generated at every request or only when the first logging happens. Since we use Monolog for our main app, the only thing we need to do is to write and register a new log processor:
… and an RID Provider:
Why is the getRid() method static? Because of the integration with Sentry bundle, which doesn’t support extra dependency injections.
What about the subrequests to microservices? The RID is sent to the microservices in the headers using the Guzzle EventListener. Then, it’s up to the service to include this identifier in the logs.
What about the CLI? Works out of the box, since we generate RID upon the log, not upon the HTTP request.
Common use cases for the RID:
- Search for all the logs related to the specific request;
- Integrate exception-tracking tools (ex. Sentry) with the RID to provide direct access to the logs;
- Show RID (or it’s beautified version) to the user when hitting the exception so he can communicate it to the support.
Conclusion
Do not undervalue the logging. Sometimes this can be your only friend on the land of terror and 500s.
