9 Ways to Improve Log Formatting in Production

When crafting or aggregating application logs, it's essential to capture sufficient details for a comprehensive event description. Log formatting is the crucial bridge that organizes these details, improving the capacity for efficient log analysis.

A log format will generally encompass the following specifications:

• The structure of log entries, whether structured, semi-structured, or entirely unstructured.
• Its data encoding, which can be in the form of text or binary.
• The specific fields contained within each log entry.
• The chosen method for delimiting individual log records.

Before delving into some log formatting best practices, let's take a closer look at some of the most prevalent log formats you're likely to come across.

Types of log formats

When it comes to formatting application logs, there are three primary approaches:

1. Unstructured logging

Unstructured logs defy predefined formats or structures. Typically generated by APIs that rely solely on printf-style variables or string interpolation for log formatting, unstructured records offer flexibility but can be disorganized.

1687927940843: Starting application on port 3000
Encountered an unexpected error while backing up database
[2023-06-28T04:49:48.113Z]: Device XYZ123 went offline
Disk error reported on Drive C: on 2023-06-28T04:49:48.838Z. Please check disk health and backup data
Service ABCDE stopped unexpectedly. Restarting the service

While such logs are easy to read during development, they quickly become unwieldy in production. At best, you can employ regular expressions to filter messages or extract crucial information, but this approach is error-prone and time-consuming. It's far from ideal when you could be dedicating your time to meaningful analysis of your system-generated data.

2. Semi-structured logging

Semi-structured logs are a step up from unstructured logs. While they maintain some level of structure, they often lack a recognizable format. Certain components or fields within the log entries typically follow a consistent pattern, while others remain unstructured or flexible. For instance, consider the default format when logging in Ruby with Semantic Logger::

2023-06-28 19:09:48.801818 I [969609:60] MyApp -- Starting application on port 3000
2023-06-28 19:09:48.801844 I [969609:60] MyApp -- Device XYZ123 went offline
2023-06-28 19:09:48.801851 E [969609:60 main.rb:13] MyApp -- Service "ABCDE" stopped unexpectedly. Restarting the service

Each entry in this format adheres to a discernible pattern, starting with the event timestamp, log level, process and thread ID, source location (in the case of an error), app name, and finally, the log message. This structure simplifies log filtering and information extraction compared to unstructured logs. Nevertheless, you may still need to craft custom regular expressions (regex) for parsing and extracting the data you require, and even minor changes in the log format can necessitate adjustments in the parsing logic.

3. Structured logging

Structured logging is a contemporary and highly effective approach to log management. With this method, each log entry adheres to a recognizable and consistent format that facilitates easy reading, searching, and analysis by log management tools. Unlike free-form text, structured log entries present well-defined fields and values that capture precise information about the logged event or message. The most widely embraced structured format is JSON:

{
  "host": "fedora",
  "application": "Semantic Logger",
  "timestamp": "2023-06-28T17:20:19.409882Z",
  "level": "info",
  "level_index": 2,
  "pid": 982617,
  "thread": "60",
  "name": "MyApp",
  "message": "Starting application on port 3000"
}

Another prevalent structured format is logfmt which was popularized at Heroku:

host=fedora application="Semantic Logger" timestamp="2023-06-28T17:20:19.409882Z" level=info level_index=2 pid=982617 thread=60 name=MyApp message="Starting application on port 3000"

The primary drawback of structured logging is that you lose some readability which is often crucial in development environments. This issue can usually be mitigated by configuring your chosen framework to produce a more human-readable and colorized output for development purposes while defaulting to a structured output in production.

Log Formatting Best Practices: Impact vs. Difficulty

If you want to improve the usefulness of your logs, the best place to start is by configuring how they are generated or collected and what data is included in each entry. Here are nine essential best practices to help you log more effectively in production.

1. Log using a structured format

The easiest way to generate structured logs is to adopt a framework that provides this ability natively or through a plugin. Most frameworks support this requirement, and many modern libraries even default to it. Here's an example showing the new Slog package in Go's standard library:

package main

import (
    "log/slog"
    "os"
)

func main() {
    logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
    logger.Info("an info message")
}

{"time":"2023-09-14T11:49:17.671587229+02:00","level":"INFO","msg":"an info message"}

Many external services you use can also be configured to produce structured logs. For instance, both PostgreSQL and Nginx support logging in JSON format:

. . .

http {
  log_format custom_json escape=json
  '{'
    '"timestamp":"$time_iso8601",'
    '"pid":"$pid",'
    '"remote_addr":"$remote_addr",'
    '"remote_user":"$remote_user",'
    '"request":"$request",'
    '"status": "$status",'
    '"body_bytes_sent":"$body_bytes_sent",'
    '"request_time_ms":"$request_time",'
    '"http_referrer":"$http_referer",'
    '"http_user_agent":"$http_user_agent"'
  '}';

  access_log /var/log/nginx/access.json custom_json;
}

With the above Nginx access log configuration, you'll go from the following unstructured output:

To the following with clearly defined fields:

In cases where you're unable to configure structured logging directly from the source, you can employ a log shipper to parse and transform the logs for you.

For example, if you need to structure Nginx error logs, which aren't easily configurable, you can use a tool like Vector:

[sources.nginx_error]
type = "file"
include = ["/var/log/nginx/error.log"]
read_from = "end"

# This is where the NGINX error logs are transformed to JSON format:
[transforms.nginx_error_to_json]
type = "remap"
inputs = [ "nginx_error" ]
source = """
structured, err = parse_nginx_log(.message, "error")
if err != null {
        log("Unable to parse Nginx error log: " + err, level: "error")
} else {
        . = merge(., structured)
}
"""

. . .

2. Employ the correct use of log levels

In your log entries, one critical detail that should always be present is the severity or log level of the event being recorded. This provides a quick assessment of the urgency of each entry and simplifies log management by allowing you to filter out irrelevant levels either at the source or during log data processing.

s{"level":"FATAL","time":1643664517737,"msg":"fatal"}
{"level":"ERROR","time":1643664517738,"msg":"error"}
{"level":"WARN","time":1643664517738,"msg":"warn"}
{"level":"INFO","time":1643664517738,"msg":"info"}

Some frameworks use integers to represent log levels, but this can introduce ambiguity because the numeric values vary across different frameworks. For instance, Node.js's Pino uses increments of 10 (10, 20, 30, etc.), Python's logging module employs increments of 10, Log4j uses increments of 100, and Go's Zap uses increments of 1. Here's an example with integer-formatted levels:

{"level":60,"time":1643664517737,"msg":"fatal"}
{"level":50,"time":1643664517738,"msg":"error"}
{"level":40,"time":1643664517738,"msg":"warn"}
{"level":30,"time":1643664517738,"msg":"info"}

To strike a balance between clarity and efficiency, you can include both representations in your logs. This allows you to leverage the readability of string levels and the storage efficiency of integers simultaneously, albeit at the cost of increased verbosity:

{"level":"FATAL","level_index":60,"time":1688003559657,"msg":"fatal"}
{"level":"ERROR","level_index":50,"time":1688003559657,"msg":"error"}
{"level":"WARN","level_index":40,"time":1688003559657,"msg":"warn"}
{"level":"INFO","level_index":30,"time":1688003559657,"msg":"info"}

Learn more about employing log levels correctly in our dedicated guide on the subject.

3. Use a standard timestamp format

Including a timestamp in each log entry is essential for understanding your application's chronological sequence of events. Without timestamps, troubleshooting problems becomes exceedingly challenging because you cannot ascertain the order of log entries. Fortunately, most logging frameworks include timestamps by default, although there are exceptions.

When formatting timestamps, we recommend using either UNIX time or ISO-8601 format (or its stricter counterpart, RFC 3339).

The former is a numeric representation of the number of seconds elapsed since the Unix epoch (January 1, 1970 UTC), while the latter is a human-readable format that provides an unambiguous representation of the date and time (up to nanosecond precision) with optional timezone information.

Examples

• ISO-8601 in UTC: 2023-09-10T12:34:56.123456789Z.
• ISO-8601 with a time zone offset: 2023-09-10T12:34:56+02:00.
• Unix time: 1705123496.

Unix time considerations

• Compact and suitable for systems with limited log storage space.
• Efficient for sorting due to its numeric nature.
• Lacks human readability, making manual log inspection less intuitive.
• Limited precision to seconds and does not store time zone information.

ISO-8601 / RFC 3339 considerations

• Human-readable and unambiguous.
• Supports nanosecond precision.
• Can store time zone information.
• Less compact compared to Unix time.

The choice between these formats primarily hinges on whether you need sub-second precision and human-readability. If either of these features is essential, ISO-8601 format is the recommended choice.

Ensure your timestamps are normalized to location-independent universal time (UTC) to establish a standard reference frame across all your services. If the timestamp's generation location is relevant, offset the time zone accordingly.

4. Include the log source information

Every log entry should contain information about its source or origin. This detail is crucial for understanding where an event or log message was generated. Typically, you can automatically include the source file and line number where the event was logged. Some logging frameworks may incorporate additional details like the server hostname or IP address (which could also be added with a log shipper).

Here's an example of a log entry with source information:

{
  "time": "2023-05-24T19:39:27.005Z",
  "level": "DEBUG",
  "source": {
    "function": "main.main",
    "file": "app/main.go",
    "line": 30
  },
  "msg": "Debug message"
}

In general, include whatever information helps you quickly pinpoint where the log message originated. Usually, providing the source file path and line number will suffice, but you can include additional details at your discretion. In distributed systems, information about the originating host or container can also be valuable for identifying issues on specific nodes.

5. Include the build version or commit hash

Incorporating the build version number or commit hash into your log entries offers several benefits.

Firstly, it associates logs with a specific version of your application, facilitating the replication of events, especially when troubleshooting bugs. With the version or commit hash, you can precisely pinpoint the state of the codebase when the log was generated.

Source information like function names, file locations, or line numbers may change as your codebases evolve. Without version information, trying to correlate logs with updated source code can lead to confusion and time wasted on locating the relevant code.

For example, consider the following log entry:

{
  "time": "2023-05-24T19:39:27.005Z",
  "level": "ERROR",
  "source": {
    "function": "main.main",
    "file": "app/main.go",
    "line": 30
  },
  "msg": "Something unexpected happened"
}

If the code that produced this log was subsequently refactored or relocated, attempting to match this log with the updated code can be perplexing. However, when you have the application version or commit hash, you can precisely identify the project state (with git checkout) and eliminate confusion.

Another relevant detail you might include is the compiler or runtime version used to compile or execute the program. This can also help ensure perfect reproducibility when investigating problems in the code.

{
  "time": "2023-06-29T06:37:38.429463999+02:00",
  "level": "ERROR",
  "source": {
    "function": "main.main",
    "file": "app/main.go",
    "line": 38
  },
  "msg": "an unexpected error",
  "build_info": {
    "go_version": "go1.20.2",
    "commit_hash": "9b0695e1c4732a2ea2c8ac678472c4c3c235101b"
  }
}

By including build version or commit hash information, you can ensure that your logs remain a reliable source of information, even as your codebase evolves.

6. Always include a stack trace when logging errors

In production systems, logging unexpected errors is paramount, and including a stack trace is a critical step to pinpoint the problem's source swiftly. A well-designed logging framework typically includes stack trace details by default when an error is logged. However, some frameworks may require additional configuration or supplementary packages to achieve this.

Here's an example of a stack trace produced by Python's standard logging module coupled with python-json-logger:

{
  "name": "__main__",
  "timestamp": "2023-02-06T09:28:54Z",
  "severity": "ERROR",
  "filename": "example.py",
  "lineno": 26,
  "process": 913135,
  "message": "division by zero",
  "exc_info": "Traceback (most recent call last):\n  File \"/home/betterstack/community/python-logging/example.py\", line 24, in <module>\n    1 / 0\n    ~~^~~\nZeroDivisionError: division by zero"
}

The entire stack trace is included as a string property in this example. Some third-party frameworks such as Structlog, support structured stack traces in JSON format, which is highly preferable:

{
  "event": "Cannot divide one by zero!",
  "level": "error",
  "timestamp": "2023-07-31T07:00:31.526266Z",
  "exception": [
    {
      "exc_type": "ZeroDivisionError",
      "exc_value": "division by zero",
      "syntax_error": null,
      "is_cause": false,
      "frames": [
        {
          "filename": "/home/betterstack/structlog_demo/app.py",
          "lineno": 16,
          "name": "<module>",
          "line": "",
          "locals": {
            "__name__": "__main__",
            "__doc__": "None",
            "__package__": "None",
            "__loader__": "<_frozen_importlib_external.SourceFileLoader object at 0xffffaa2f3410>",
            "__spec__": "None",
            "__annotations__": "{}",
            "__builtins__": "<module 'builtins' (built-in)>",
            "__file__": "/home/betterstack/structlog_demo/app.py",
            "__cached__": "None",
            "structlog": "\"<module 'structlog' from '/home/betterstack/structlog_demo/venv/lib/python3.11/site-\"+32",
            "logger": "'<BoundLoggerLazyProxy(logger=None, wrapper_class=None, processors=None, context_'+55"
          }
        }
      ]
    }
  ]
}

Where possible, prefer a structured stack trace as above, but a large string block is better than nothing.

7. Use standardized contextual fields

Instead of embedding contextual information within log messages, consider using contextual fields to enhance log filtering, grouping, and analysis. Let's say you have the following log lines in your Python program:

logger.info("User '%s' logged in", user)
logger.info("Received '%s' HTTP request to endpoint: %s", request_method, endpoint)
logger.debug("Processing request for endpoint: %s by user: %s", endpoint, user)
logger.debug("Executing query: %s. Execution time: %sms", query, execution_time)

They will produce an output that looks like this:

{"timestamp": "2023-09-12T14:30:45.123456Z", "level": "INFO", "msg": "User 'john_doe' logged in"}
{"timestamp": "2023-09-12T14:30:45.123456Z", "level": "INFO", "msg": "Received 'GET' HTTP request for endpoint: /api/resource"}
{"timestamp": "2023-09-12T14:30:45.123456Z", "level": "DEBUG", "msg": "Processing request for endpoint: /api/resource by user: john_doe"}
{"timestamp": "2023-09-12T14:30:45.123456Z", "level": "DEBUG", "msg": "Executing query: SELECT * FROM resources WHERE id=123. Execution time: 10ms"}

You can translate the string-formatted variables into contextual fields like this:

logger.info("User logged in", extra={"user": user})
logger.info("Received HTTP request", extra={"endpoint": endpoint, "method": request_method})
logger.debug("Processing request", extra={"user": user, "endpoint": endpoint})
logger.debug("Executing query", extra={"query": query, "execution_time_ms": execution_time})

With this approach, the log entries include contextual fields:

{ "timestamp": "2023-09-12T14:30:45.123456Z", "level": "INFO", "msg": "User logged in", "user": "john_doe" }
{ "timestamp": "2023-09-12T14:30:45.123456Z", "level": "INFO", "msg": "Received HTTP request", "method": "GET", "endpoint": "/api/resource" }
{ "timestamp": "2023-09-12T14:30:45.123456Z", "level": "DEBUG", "msg": "Processing request", "user": "john_doe", "endpoint": "/api/resource" }
{ "timestamp": "2023-09-12T14:30:45.123456Z", "level": "DEBUG", "msg": "Executing query", "query": "SELECT * FROM resources WHERE id=123", "execution_time_ms": 10 }

To maintain consistency, establish standards for field names and content types. Enforcing such conventions helps prevent situations where user IDs are logged as user, username, user_id, or userID, ensuring clarity and consistency in your logs. Additionally, consider including units in field names for numeric values (e.g. execution_time_ms or response_size_bytes) to eliminate ambiguity.

8. Include a correlation ID

A single log entry often represents just one event within a larger operation or workflow. For instance, when handling an HTTP request, numerous log entries may be generated at various stages of the request's lifecycle. To better understand and analyze these logs collectively, including a correlation ID that ties together all the log entries related to a specific operation is crucial.

Consider the following log entries produced during the processing of an HTTP request:

{ "timestamp": "2023-09-10T15:30:45.123456Z", "level": "INFO", "message": "received incoming HTTP request", "request": { "method": "GET", "path": "/api/resource", "remote_address": "192.168.1.100" } }
{ "timestamp": "2023-09-10T15:30:45.234567Z", "level": "DEBUG", "message": "processing request", "handler": "ResourceHandler", "user": "john_doe" }
{ "timestamp": "2023-09-10T15:30:45.345678Z", "level": "DEBUG", "message": "query executed", "query": "SELECT * FROM resources WHERE id=123", "execution_time": "10ms" }
{ "timestamp": "2023-09-10T15:30:45.456789Z", "level": "INFO", "message": "HTTP request successfully handled", "response": { "status_code": 200, "content_type": "application/json", "content_length": 543 } }

While the order of events is quite evident in this example, it can be challenging to determine the sequence of events and which logs correspond to a specific request in complex systems with numerous records. To address this issue, include a unique correlation ID that links all log entries associated with a particular operation. Here's the same example with the addition of a correlation ID:

{ "timestamp": "2023-09-10T15:30:45.123456Z", "correlation_id": "2VNr2aTxqvAV0sWI7t0w1oe4mZN", "level": "INFO", "message": "Received incoming HTTP request", "request": { "method": "GET", "path": "/api/resource", "remote_address": "192.168.1.100" } }
{ "timestamp": "2023-09-10T15:30:45.234567Z", "correlation_id": "2VNr2aTxqvAV0sWI7t0w1oe4mZN", "level": "DEBUG", "message": "Processing request", "handler": "ResourceHandler", "user": "john_doe" }
{ "timestamp": "2023-09-10T15:30:45.345678Z", "correlation_id": "2VNr2aTxqvAV0sWI7t0w1oe4mZN", "level": "DEBUG", "message": "Query executed", "query": "SELECT * FROM resources WHERE id=123", "execution_time": "10ms" }
{ "timestamp": "2023-09-10T15:30:45.456789Z", "correlation_id": "2VNr2aTxqvAV0sWI7t0w1oe4mZN" "level": "INFO", "message": "HTTP request successfully handled", "response": { "status_code": 200, "content_type": "application/json", "content_length": 543 } }

Correlation IDs such as the one above can be generated at the edge of your infrastructure, and propagated through the entire request lifecycle so that they are included in each log message so you can easily group and analyze related entries.

9. Send your logs to a log management service

Once you've started generating structured log data, the next step is to aggregate them in a service that provides an easy way to filter, visualize, and set up alert rules so that you are notified when specific log events or patterns occur.

Sounds interesting? Do spin up a free trial of Better Stack to see how easy log analytics can be.

Final thoughts

As you've seen above, log formatting is a complex topic with many facets, but it can be mastered with the right practices and tooling. Implementing these nine best practices is a great starting point to making your systems more observable, enabling you to gain valuable insights, troubleshoot effectively, and enhance overall system reliability.

For more in-depth insights and tutorials on logging practices, feel free to explore our various logging and observability articles.

Thanks for reading, and happy logging!

Article by

Ayooluwa Isaiah

Ayo is the Head of Content at Better Stack. His passion is simplifying and communicating complex technical ideas effectively. His work was featured on several esteemed publications including LWN.net, Digital Ocean, and CSS-Tricks. When he’s not writing or coding, he loves to travel, bike, and play tennis.

This work is licensed under a Creative Commons Attribution-NonCommercial-ShareAlike 4.0 International License.