Timestamps in container logs

^{August 10, 2018}

It is essential to know when the application generates a specific log message. Timestamps help us to order the events. And they help us to build a correlation between systems.

That is why logging libraries write timestamps with the log messages. When you write log messages to systems, like journald or Splunk, every event has a timestamp. These applications parse timestamp from the message or generate from the system time. When you write logs to the plain text files, you lose the information about at what time application created these messages. This is why you tell loggers to identify every line with the timestamp.

Let's look at the example. A tiny python snippet that generates a new log message, when the response does not have a 200 status.

import logging

logging.basicConfig(format="%(asctime)s - %(levelname)s - %(message)s")


def handle_request(request):
    if request.statusCode != 200:
       logging.warning('not OK response')

    # handle request

If we handle response without an OK status, we should see a message like in the example below.

2018-08-09 21:53:42,792 - WARNING - not OK response

What can this logging message tell us? That around 2018-08-09 21:53:42,792 we had one response, that did not have a 200 status code. It is not an exact time of the response. Possible that function handles the response a second later after actual response. Possible that the network was too slow, and the whole request took 10 seconds to complete.

Another important detail, when we write a log message, we do not inject the timestamp. The logger does it for us. It depends on the load of the system where this code is getting executed. The timestamp can be few nano- or micro- seconds off from the actual message.

Logger libraries are very similar in how they work. Below we will look into how the Python logging module emits the log messages.

If we look at the source code of the logging module, we could find where the timestamp is getting generated.

def __init__(self, name, level, pathname, lineno,
             msg, args, exc_info, func=None, sinfo=None, **kwargs):
    """
    Initialize a logging record with interesting information.
    """
    ct = time.time()
    self.name = name
    self.msg = msg

Based on the format, logger prints the timestamp in the human-readable form.

Another important detail of all logging libraries. They all flush the stream after emitting the message. Python logging module is not an exception.

msg = self.format(record)
stream = self.stream
stream.write(msg)
stream.write(self.terminator)
self.flush()

The flush call is very important for the logging libraries. By default, Operation Systems create buffered standard output and error streams. Based on the attached reader, the behavior could be different. Without flushing, your messages could be stuck in the buffer till the buffer is full or system closes the stream. I recommend to look at the stdio and fflush man pages to learn more.

Let's summarize what we have learned so far:

Timestamps are essential in the logs. They give an order and help to correlate events.
Timestamps might not represent an exact moment of time when application code writes the log message.
Logging libraries are avoiding to keep the records in buffers. All messages should be available for the readers almost instantly.

It is time to look how docker handles the container logs. In the example below we use Docker, but other container runtimes, like CRI-O, have similar implementations.

Let's generate the docker container logs. For that, we can run a docker run command.

$ docker run --name python_example python:3 python -c 'import logging; logging.basicConfig(format="%(asctime)s - %(levelname)s - %(message)s"); logging.warning("not OK response");'
2018-08-10 17:59:54,582 - WARNING - not OK response

It is a short-lived container, but we have not removed it after execution. So we can look at the logs.

$ docker logs python_example
2018-08-10 18:00:56,086 - WARNING - not OK response

We can use an --timestamp option with the docker logs command.

$ docker logs --timestamps python_example
2018-08-10T18:00:56.086989400Z 2018-08-10 18:00:56,086 - WARNING - not OK response

As you can see every message in docker logs also has a timestamp. If we round the timestamp generated by Docker, we can see that it differs by one millisecond (2018-08-10T18:00:56.086989400Z ~= 2018-08-10T18:00:56.087).

Docker generates this timestamp with the Copier.

if msg.PLogMetaData == nil {
    msg.Timestamp = time.Now().UTC()
} else {
    msg.Timestamp = partialTS
}

Docker attaches the Copier to the container standard output and error pipes.

copier := logger.NewCopier(map[string]io.Reader{"stdout": container.StdoutPipe(), "stderr": container.StderrPipe()}, l)
container.LogCopier = copier
copier.Run()
container.LogDriver = l

The Copier reads the streams and forwards messages to loggers.

Let's summarize what we learned about Docker logger system.

Docker generates another timestamp for every log message.
There could be a slight delay between when an application writes the message and docker timestamp. This delay depends on the how busy is your system.
We have not talked about that. But it is essential to know. If the Copier with the Logger isn't able to keep up with the number of logs, that might block standard output of the container. And that can result in the performance degradation of your application. You will not see spikes in the CPU usage, but peaks in IO wait.
None of the timestamps represent an actual moment of time when the event happened.
Logger drivers use the timestamp generated by the Docker.

Our suggestion. Avoid generating timestamps with the logging libraries. Docker always attaches timestamps to the logs. That will help you to reduce disk space for storing the logs. And if you use logging systems where you pay for the amount of injected data (like AWS CloudWatch or Splunk), that will help you to reduce the cost.

About Outcold Solutions