To boldly log: debug Docker apps effectively using logs options, tail and grep

When developing applications based on Docker, being able to find specific information in the logs and save this data to file can speed up the troubleshooting and debugging process. Here are some tips on using log options, tail and grep to find what you are looking for in docker containers’ log data.

Displaying all logs
Target and follow specific containers
Slice and search logs using tail and grep
Logs by time
Combining commands
Writing logs to file

My posts on getting started with Docker- Top 10 Docker commands you can’t live without- The ups and downs of docker-compose — how to run multi-container applications

Displaying all logs

When spinning up a Docker container, such as with docker-compose up, it will automatically show the logs. If you run them in the background, such as with docker-compose up -d, or from a different terminal then you can display logs using:

docker logs [OPTIONS] CONTAINER
docker-compose logs (all containers)

However, this will give you a large output of information.

Target and follow specific containers

Using docker-compose you can specify which container logs you want to show using:

docker-compose logs [options] [SERVICE...]

When debugging specific applications, a useful option is to follow log output. This means you can start a container, test a feature and see what is sent to the logs as you use it.

--follow , -f

An alternative is to test your application, then search the logs for specific information to show you how well it worked (or not!!!). There are two commands based on Unix commands that you can use for this.

Slice and search logs using tail and grep

The tail command outputs the last n number of lines from the end of a file. For example:

tail -n5 docker-compose.yml                                                                =>
        NAME: "rabbit"
      tty: true
      volumes:
        - ./rabbitmq.conf:/etc/rabbitmq.conf:ro
        - ./definitions.json:/etc/rabbitmq/definitions.json:ro

To see the most recent output in the docker logs, you can either use this directly on a log file or use docker’s --tail option.

--tail number of lines to show from the end of the logs

docker-compose logs --tail 5 rabbit =>Attaching to docker_rabbit_1 rabbit_1 | completed with 3 plugins. rabbit_1 | 2018-03-03 14:02:01.377 [info] <0.5.0> Server startup complete; 3 plugins started. rabbit_1 | * rabbitmq_management rabbit_1 | * rabbitmq_web_dispatch rabbit_1 | * rabbitmq_management_agent

Another Bash command you can use with the logs is grep to return lines containing a specified string. For example:

docker-compose logs | grep error

…will show you all the errors logged by a docker containers. Very useful for seeing what you need to focus your development on.

docker-compose logs | grep error
=>
rabbit_1  | 2018-03-03 16:40:41.938 [error] <0.192.0> CRASH REPORT Process <0.192.0> with 0 neighbours exited with reason: {error,<<"Please create virtual host \"/my_vhost\" prior to importing definitions.">>} in application_master:init/4 line 134
...

Logs by time

If you know which time period you want to focus on, for example a time when you know there was an issue you can tell docker to show timestamps using

--timestamps , -t

docker-compose logs -t => Attaching to docker_rabbit_1 rabbit_1 | 2018-03-03T14:01:58.109383986Z 2018-03-03 14:01:58.099 [info] <0.33.0> Application lager started on node rabbit@71bfa4cd9dc2 ...

Pick a specific time period --since and --until options (only for docker logs, not docker-compose logs):

--sinceShow logs since timestamp (e.g. 2013-01-02T13:23:37) or relative (e.g. 42m for 42 minutes)
--untilShow logs before a timestamp (e.g. 2013-01-02T13:23:37) or relative (e.g. 42m for 42 minutes)

For example, if I wanted to see the logs close to the warning message in the earlier example I would execute:

docker logs -t --since 2018-03-03T16:52:45.000996884Z --until 2018-03-03T16:52:45.001996884Z docker_rabbit_1
=>
2018-03-03T16:52:45.000996884Z 2018-03-03 16:52:45.000 [warning] <0.417.0> Message store "61NHVEJY8W4BPTRU4AS08KK9D/msg_store_persistent": rebuilding indices from scratch
2018-03-03T16:52:45.001801685Z 2018-03-03 16:52:45.001 [info] <0.410.0> Started message store of type persistent for vhost '/my_vhost'

Combining commands

You can combine these options and commands to target very specific areas of the logs with the information you need. In the below example we combine the -t timestamps option with --tail for the last 10 lines of the logs for container docker_rabbit_1, then search these for lines containing info to just see lines that were logged at info level.

docker logs -t --tail 10 docker_rabbit_1 | grep info                         =>
2018-03-03T16:52:45.029907263Z 2018-03-03 16:52:45.020 [info] <0.33.0> Application rabbitmq_web_dispatch started on node rabbit@d5d541f785f4
2018-03-03T16:52:45.042007695Z 2018-03-03 16:52:45.041 [info] <0.517.0> Management plugin started. Port: 15672
2018-03-03T16:52:45.042222660Z 2018-03-03 16:52:45.041 [info] <0.623.0> Statistics database started.
2018-03-03T16:52:45.043026767Z 2018-03-03 16:52:45.042 [info] <0.33.0> Application rabbitmq_management started on node rabbit@d5d541f785f4
2018-03-03T16:52:45.361845369Z 2018-03-03 16:52:45.361 [info] <0.5.0> Server startup complete; 3 plugins started.

Writing logs to file

Now that you have mastery over docker logs commands and how to find exactly what you want, use this to send the data to a log file. Using Bash, or alternative shell such as Zsh, the >> command followed by the file name outputs and saves the data to that file.

docker logs -t --tail 10 docker_rabbit_1 | grep info >> my_log_file.txt

You might want to use this to create log files for specific log data. For example, when debugging you could create ones for warnings or errors.

docker logs -t docker_rabbit_1 | grep warning >> logs_warnings.txt

Now the contents of my logs_warnings.txt file contains:

2018-03-03T16:52:45.000996884Z 2018-03-03 16:52:45.000 [warning] <0.417.0> Message store "61NHVEJY8W4BPTRU4AS08KK9D/msg_store_persistent": rebuilding indices from scratch
2018-03-03T16:52:51.036989298Z 2018-03-03 16:52:51.036 [warning] <0.654.0> HTTP access denied: user 'guest' - invalid credentials

This means you can use all other applications and commands you use with text files and apply them to this log data.

Why not try some of your own custom log commands and saving the output to your own log file?

Development and debugging of your docker apps can be made easier with targeted log data. For example, you could search for specific types of errors within a time period, which you could then save to an error logs file.

Happy development and debugging!