Ideals for Logging on the Backend

Listen, good logging will save you a ton of time and energy when finding out why something happened. When bad things happen, and you know why, you’re well on your way towards a solution. If you don’t know why, you’re an ocean away, and you don’t even know which ocean.

So I use this checklist to know whether my backend app meets my ideal standards for logging:

1. Every request should have a unique ID

and that ID must be present in every log output made throughout the lifecycle of the request.

Consider the following logs:

{ "request": { "id": 1, "method": "POST", "path": "/users" } }
{ "request": { "id": 1 }, "error": { "message": "Could not create user" } }
{ "request": { "id": 1 }, "response": { "status": 500 } }

The above logs tell a story, where a POST /users request was made to create a new user, and somewhere in the call stack, an error was thrown.

We are able to tell this story about the request, because we can filter the logs by the request’s id e.g. "request.id": 1. This is very useful when looking logs.

2. Logs should be optimized for search.

I initially wrote this as “Logs must be structured e.g. as JSON”, but I realized that optimizing for search is the root reason for this constraint, because there are a ton of logs, and they need to readable by machines first, and humans next.

Structured logging is one way I know to easily achieve this. I have not explored other approaches, so if you have, please let us know in the comments.

3. Logs should have levels

When you have a lot of logs, it becomes important to have a way to quickly view important logs, so every log needs to have a level attached to it.

There are many sets of levels out there, but I’ve found I like: Fatal , Error, Warn, Info, Debug, in order of reduced seriousness.

I use the following criteria to decide which level a log belongs to:

• Fatal: An unhandled exception has occurred, and we need to terminate the application. So this is about errors that the app does not recover from.
• Error: A handled exception has occurred because of an non-user-originating problem, but the app is still either chugging along just fine or attempting to recover from it.
• Warn: A handled exception occurred because of an input given by the user e.g. missing or invalid parameters in a request, accessing deprecated/obsolete endpoints, etc.
• Info: High-level events in the system e.g. the beginning of a request showing its Request Id, URL and HTTP method, the end of a request showing its Request Id and Status code.
• Debug: Low-level events in the system e.g. the beginning and end of every service method, and request to an external system such as a database, queue, 3rd-party API, etc.

Choosing a log-level

Now that you have log levels, you also want a way to determine which levels are used in various deployment environments.

E.g. it is common practice to disable Debug levels by default in production environments, because they occur a lot, and can bloat the log storage really fast.

For maximum efficiency, You want to have a way to enable these Log Levels for a specific user or group of users when debugging an issue in production. Look into adding targetable feature flags to your logging system.

4. Do NOT log personal identifiable information (PII)

Your logs will likely live on and get passed through remote servers you do not control for storage and processing, so logging PII exposes people to risk. So, prefer logging IDs instead of names or email addresses.

I’ve found this is a hard one to enforce technically because a logging framework that automatically redacts PII would be the ideal.

E.g.

logger.Debug(
  "New User",
  new {
    user
  }
);
// should automatically redact the user's name and log:
/*
{
  "message": "New User",
  "user": {
    "id": "user-1",
    "name": "****" // 👈 redacted
  }
}
*/

But can it be done fast and reliably?

I have not explored this in detail, so in the meantime, I tend to rely on code reviews for this.

If you have done such, and are kind enough to, please let me know how in the comments.

5. Support log scope binding

This is something I’ve found extremely useful. If there is some information I want every subsequent log output to have, such as the request’s id, or the current user’s id, I should be able to bind it to the current log’s scope, and every subsequent write to the logs will have that information.

E.g.

logger.bind({ user: { id: "user-1" } });
// Now every log output will have this information.
// so
logger.debug("New Payment");
// will output as:
/*
{
  "message": "New Payment",
  "user": {
    "id": "user-1"
  }
}
*/

And the bound information is available for as long as the logger instance is alive.

You can bind anything. The name of the current service being executed, the calling IP address, anything that helps you make sense of the logs, that does not contravene the other ideals we’ve mentioned.

—

Are there other ideals you follow when logging?

Are there tools you know of, that help you meet these ideals?

Please let us know in the comments.

—

Find comments from readers on other platforms.