Improving logs in bash scripts

Using redirection and file descriptors to split logs by verbosity in your bash scripts

Published April 16th, 2020 by Kumbirai Tanekha

Who knew that you could reasonably split logs in bash scripts without sacrificing the UX?

I certainly didn’t! At least not until I made an attempt to implement it. The first hurdle was overcoming the urge to just move everything from bash script to some programming language. We all know that bash reigns supreme on multiple fronts including, and most importantly, “convenience!” And that’s precisely why codebases are littered with it.

Let’s start by jumping right to the end. The ambitious goal I set out to achieve was a separation of log content by severity so that readers would not have to be forced to wade through mounds of irrelevant information. That means that, if you’re running a suite of integration tests, the main output should contain an overview of the steps that took place and the results. The rest of the output could be stored in different buckets so you can look at it by category as and when you please. Separating logs is a relatively easy task to accomplish in most programming languages. I wondered if it could be achieved in bash.

And indeed it could.

The image above gets to the heart of the matter. Both logs show an identical run of release tests. The logs on the left are extremely noisy; this is when the bash scripts allow everything in their path to log. Those on the right are concise, only outputting curated informational logs. The difference is astonishing when you consider that the left image logged ~400 lines compared to ~30 for the right on the same run.

How did we get here, you ask ? In a phrase, “file descriptors”.

A crash course on file descriptors in bash

Let’s begin.

A file descriptor is a number that uniquely identifies an open file, plus an associated byte offset and access restrictions (read/write etc.)

The first order of business is to get ahold of a file descriptor. It turns you get three for free.

  • 0: /dev/stdin
  • 1: /dev/stdout
  • 2: /dev/stderr

You can redirect these so that, for example, stdout can go to a file:

exec 1>log

Now, anything written to the stdout file descriptor within the current shell (and all sub-shells) goes to the file log.

Here’s an excerpt where this functionality is described, straight from man bash:

exec [-cl] [-a name] [command [arguments]]

...

If command is not specified, any redirections take effect in the current shell and the return status is 0.

How do we write to them, you say ?

That’s relatively straightforward: [command] [from-file-descriptor]>&[to-file-descriptor]. It’s the > operator, but with an ampersand suffix, so that [to-file-descriptor] is parsed as a file descriptor. The contents to write have to come from somewhere, by default that place is /dev/stdout. It’s quite common to see [from-file-descriptor] omitted; it defaults to /dev/stdout. That’s really all there is to writing.

Here are two equivalent ways of writing from /dev/stdout to /dev/stderr.

command 1>&2
command >&2

What about reading ?

<& allows you to read from a file descriptor so that you can use cat:

cat <&3

Alternatively, read allows you to read from a file descriptor line by line:

read -u 3 && printf '%s' "${REPLY}"

You’ll notice that, if you try to read from a file descriptor after the first read, you won’t get anything back. That’s because the byte offset has moved all the way to the end of the file while you were reading. To move the byte offset to an arbitrary location you’ll need to make calls to the syscall lseek. I’ll talk about it more in a moment.

How do I create my own ?

Well, you can create simple file descriptors in the following ways:

exec 7<log // read-only
exec 8>log // write-only (resets file)
exec 9>>log // append-only
exec 10<>log // read-write

This creates four separate file descriptors to a file named log.

Why descriptors and not just files ?

When you have to carry out many reads and writes, a file descriptor is useful because it gives you a pointer to an open file, which avoids reopening a file each time you want to carry out operations. It allows you to have fine grain control of where you read/wrote by maintaining the byte offset, meaning you can carry on from where you left off, which could be anywhere in the file.

It’s worth exploring this byte offset a little bit. It’s unfortunate that there’s no built-in way to select an arbitrary offset in bash, but we have other options. It turns out:

  1. Child processes inherit the file descriptors of the parent.
  2. The byte offset of a file descriptor can be modified using the lseek syscall

Let’s define a bash function called lseek. It takes two arguments (file descriptor and byte offset, in that order) and calls the lseek syscall to set the byte offset of a file descriptor. It does this by calling to Python. As best as I can tell, there’s no built-in in Bash for making syscalls (sigh! I feel like this is cheating a bit).

lseek() {
  python -c "
    import os
    os.lseek($1, $2, 0)
  ";
}

Using lseek, defined above, we can now read a file as many times as we like, as follows:

exec 4<log # create file descriptor for reading

cat <&4 # file contents in output
cat <&4 # no output
lseek 4 0 # reset byte offset
cat <&4 # file contents in output
lseek 4 0 # reset byte offset
cat <&4 # file contents in output

I made sure to add an example of manipulating the byte offset for completeness; this won’t be used for splitting the log files.

Splitting log files

It’s time to put our new found knowledge of file descriptors to use!

When a process starts, it receives three file descriptors.

  1. /dev/stdin to read from
  2. /dev/stdout to write to
  3. /dev/stderr to write to — loosely meant for errors

We want to split log contents into 2 categories.

  1. Informational. The curated stuff. You decide what goes here. This is also the only thing that gets shown to the world. The rest they have to dig into.
  2. Debug. By default it should gather /dev/stdout and /dev/stdout. We can also add the (1) to it if we’d like.

(2) is what you normally get on your terminal unless you redirect /dev/stdout and /dev/stderr. One way to reduce the noise is to send it all down the pit of /dev/null exec > /dev/null 2>&1. But, that’s hardly a productive thing to do in this case.

With all the above in mind, let’s set things up for each of the categories.

  1. Informational. Create a file named info-log.txt. Any informational logs should be written here. This is the only change we make to the UX of a typical writer of bash scripts. Content written to this file will be persisted to disk and simultaneously output to the terminal. 
    # Reset the log file
printf '' > info-log.txt

# Tail the info logfile as a background process so the contents of the
# info logfile are output to stdout.
tail -f info-log.txt &

# Set an EXIT trap to ensure your background process is
# cleaned-up when the script exits
trap "pkill -P $$" EXIT
  2. Debug. Create a file named debug-log.txt. Append everything from /dev/stdout and /dev/stderr to this file. 
    # Reset the log file
printf '' > debug-log.txt

# Redirect both stdout and stderr to write to the debug logfile
exec 1>>debug-log.txt 2>>debug-log.txt

    It’s worth noting that we create the file descriptor for the debug logfile in append mode. This is important because it means we always write to the end of the file. If this file happens to be opened and being written to from elsewhere, then our writes will always be at the end of the file.

That’s pretty much it.

Now let’s put it all together and see it in action. Below is an example of a verbose command.

#!/usr/bin/env bash

# Reset the log files
printf '' > info-log.txt > debug-log.txt

# Tail the info logfile as a background process so the contents of the
# info logfile are output to stdout.
tail -f info-log.txt &

# Set an EXIT trap to ensure your background process is
# cleaned-up when the script exits
trap "pkill -P $$" EXIT

# Redirect both stdout and stderr to write to the debug logfile
exec 1>>debug-log.txt 2>>debug-log.txt

# Write to both info and debug
echo "Making an HTTP request to Google" | tee -a info-log.txt

# Write to info only. Remember to always append
echo "Sorry, this might take some time." >> info-log.txt

# This command is only present to indicate failure or success.
# If it fails the program will exit, if it succeeds it will just keep going.
# I only want to see its output when there is a failure.
curl -v -f https://google.com

# Written to both info and debug
echo " ✅ " | tee -a info-log.txt

Save the script above to ./example.sh and run chmod +x ./example.sh to make it executable.

Run it!

Then cat the contents of info-log.txt and debug-log.txt. The image below captures the outputs you might see.

There we go, separate logs! The debug log keeps all the verbose stuff that’s useful for debugging. The info log provides a curated picture.

Now go out there and start splitting logs 🌳.