iTranslated by AI
Introduction to Usable Logging in Web Development
This article is for people who write logs like this:
{
"message": "HogeController.index(). finding hoge...",
"level": "info"
}
{
"message": "HogeService.findListById(). finding hoge...",
"level": "info"
}
{
"message": "HogeRepository.findListById(). finding hoge...",
"level": "info"
}
{
"message": "HogeRepository.findListById(). found Hoge!",
"level": "info"
}
{
"message": "HogeService.findListById(). found Hoge!",
"level": "info"
}
{
"message": "HogeController.index(). found Hoge!",
"level": "info"
}
By the way, when I mention writing info logs for each action, I'm not referring to framework setup or teardown processes. I'm strictly talking about the internal flow of the application.
Starting with Bad Examples
First, let's look at my former logs. For context, the app architecture follows a Controller - Service - Repository (DB access layer) relationship. If you use Rails or Laravel, feel free to replace "Repository" with "ActiveRecord" or "Eloquent."
The sample code is written in TypeScript. Please note that this isn't actual code using a specific framework, but rather a conceptual illustration.
Let's start with the Controller. I used to write info level logs both before and after a process. The reason for this was that if a bug occurred, I wanted to know how far the execution had progressed.
If there was an error, I would write an error level log and pass it back to the framework's error handler. Actually, the framework's error handler was already designed to log errors automatically upon receiving them. The reason I went out of my way to write error logs myself was that I wanted to know the metadata, such as which controller the error occurred in.
class HogeController {
async index(request) {
// Log before the process starts.
logger.info('HogeController.index call!');
// Not strictly TypeScript syntax, just an illustration. Catch if there's an exception.
try {
const hoges = await HogeService.getAllHoge(request.user);
// Log after the process finishes.
logger.info('HogeController.index called!');
return hoges;
// If getAllHoge throws an error
} catch (error) {
// Logged the error indicating which controller.
// Sometimes included userId, sometimes didn't.
logger.error(`Error in HogeContoller.index(). userId: ${request.userId}, error: ${error}`);
// Re-throw the error to let the framework handle it. For Express, this would be next(error).
throw error;
}
}
}
Next is the Service. I wrote logs before and after processing here as well, just like in the Controller. In fact, due to copy-pasting, some log content had become inaccurate over time.
class HogeService {
async getAllHoge(requestUser){
// Log indicating the process is starting.
logger.info('HogeService.getAllHoge. finding hoge... ');
// Throw an exception if some condition check fails.
if(!requestUser.canGetHoge()){
// Log the error where it occurred, just in case.
logger.error('requestUser.canGetHoge() permission error')
throw new Error('Permission Error');
}
const models = await HogeRepository.findAllHoges();
// Log indicating the process was successful.
// Method name changed during refactoring, but forgot to update the log content.
logger.info('HogeService.getHoges found hoge!');
return models;
}
}
I was going to continue with the Repository, but it's just a repetition of the same pattern, so I'll skip it. It's the same cycle of writing info logs before/after processing and logging an error at the spot before throwing it.
Also, I was only recording logs of info level or higher in the logging service.
Realizing one day that my logs were hard to use
One day, a customer told me they couldn't use a certain feature properly. I decided to check the logs using the customer's ID, and when I took a peek at the logging service...
{
"message": "HogeController.findListById(). finding hoge...",
"level": "info"
}
{
"message": "HogeService.findListById(). finding hoge...",
"level": "info"
}
{
"message": "HogeRepository.findListById(). finding hoge...",
"level": "info"
}
{
"message": "HogeRepository.findListById(). found Hoge!",
"level": "info"
}
{
"message": "HogeService.findListById(). found Hoge!",
"level": "info"
}
{
"message": "HogeRepository.findListById(). found Hoge!",
"level": "info"
}
{
"message": "HogeController.index(). found Hoge!",
"level": "info"
}
...snip...
{
"message": "HogeRepository.create(). found Hoge!",
"level": "info"
}
{
"message": "Connection error",
"level": "error"
}
{
"message": "Error in HogeController.index(). userId: 1, error: DB error",
"level": "error"
}
{
"message": "Stack trace here",
"level": "error"
}
What on earth is this!?
There were an excessive amount of retrieval-related logs, anonymous info logs where I couldn't tell who performed the action, and error logs buried deep in the noise. 90% of the data was garbage. And how was I supposed to search by userId again?
I summarized the reasons why I ended up creating unusable logs:
- What I thought were
infologs should have been at thedebuglog level. - Don't record logs for every layer like Controller or Service. Record them as
infologs on a per-action basis. - There should be exactly one
errorlog per error. Attach metadata to make investigation easier. - Always include the
userIdin logs so you can search for the actions a user took right before an error. - Don't embed metadata inside the message string. Record them properly as JSON keys and values to enable searching.
Applying Lessons Learned
First, I customized the logger. I made it so that the object passed as the second argument is handled directly as JSON.
logger.info('message here', {
userId: 1,
requestId: 'gjeaijgeiajke'
})
{
"level": "info",
"message": "message here",
"userId": 1,
"requestId": "gjeaijgeiajke"
}
Next, I'll update the Controller. I changed all info logs to debug and left the error logging to the framework's error handler. However, since logging errors as-is isn't very helpful, I'll add metadata. I'll touch on this later.
class HogeController {
async index(request) {
// Log before the process starts.
logger.debug('HogeController.index call!');
// Not strictly TypeScript syntax, just an illustration. Catch if there's an exception.
try {
const hoges = await HogeService.getAllHoge(request.user);
// Log after the process finishes.
logger.debug('HogeController.index called!');
return hoges;
// If getAllHoge throws an error
} catch (error) {
// No need to wrap in try-catch if just re-throwing, but I wanted to match the structure of the previous section.
// Leave the logging to the framework's error handler.
throw error;
}
}
}
Next, I'll rewrite the Service. I also changed all info logs to debug here. Additionally, I made sure not to write redundant logs when throwing errors. I also modified it to use classes provided by the framework instead of using Error classes directly.
class HogeService {
async getAllHoge(requestUser){
logger.debug('HogeService.getAllHoge. finding hoge... ');
// Throw an exception if some condition check fails.
if(!requestUser.canGetHoge()){
throw ForbiddenError('Access denied.');
}
const models = await HogeRepository.findAllHoges();
// Add an info log when an action is performed.
logger.info('activity log', {
userId: 1,
eventType: 'view.hoge',
timestamp: new Date().toISOString(),
})
logger.debug('HogeService.getHoges found hoge!');
return models;
}
}
Finally, here is the fix for the error handler. In the framework I use, the error handler that catches errors globally is implemented as middleware, and the error content is customizable. I decided to include the following information in the error logs:
- Request URL
- HTTP method
- Request body
- Request query
- Request parameters (part of the URL)
- Request headers
- Request user ID
- Response status code
- Timestamp
export class LoggingExceptionFilter extends BaseExceptionFilter {
catch(exception: Error, request) {
this.logger.error(exception.message, {
path: request.url,
requestMethod: request.method,
requestBody: request.body,
requestQuery: request.query,
requestParam: request.params,
requestHeaders: request.headers,
userId: (request.user as UserEntity | undefined)?.id ?? null,
responseStatus: httpStatus,
timestamp: new Date().toISOString(),
});
}
}
The Reborn Logs
{
"message": "activity log",
"level": "info",
"userId": 1,
"timestamp": "2022-04-20 10:10:10",
"eventType": "view.hoge"
}
{
"message": "activity log",
"level": "info",
"userId": 2,
"timestamp": "2022-04-21 10:10:10",
"eventType": "create.hoge"
}
{
"message": "DB connection error",
"level": "error",
"userId": 2,
"timestamp": "2022-04-22 10:10:10",
"path": "https://example.com/hoge",
"requestMethod": "PUT",
"requestBody": {
"comment": "I think fuga is better than hoge"
},
"requestQuery": "",
"requestParam": "",
"requestHeaders": {
...snip
},
"responseStatus": 500
}
When logs are in JSON format, tools like CloudWatch allow you to search using filters like { $.userId = 1 } to display only that specific user's logs.
You can grasp the approximate location of an error from the response status code and pinpoint the exact issue from the error message. Furthermore, by recording the request body and other metadata, you can understand the context of the situation.
I include an eventType just in case I want to measure certain metrics using log filter functions.
However, I've realized that monitoring tools like CloudWatch aren't particularly well-suited for measuring business metrics, so I don't use this approach much these days.
It's so much easier to use! ₍₍ (ง ˙ω˙)ว ⁾⁾
Bonus
As briefly mentioned in the code earlier, attaching a trace ID to every request from the frontend is very helpful. It comes in handy if you need to output multiple logs for a single request, require trace IDs for future event-driven architectures, or need them for big data analysis.
axios.get('/example.com', {
headers: {'X-REQUEST-ID': nanoId()}
});
You can keep track of it on the backend and append it to your logs. (Don't forget to allow the header in your CORS settings!)
Conclusion
I personally host small "Mokumoku-kai" (quiet coding sessions). I'm thinking about gradually expanding them. I'm casually looking for participants!
Discussion