Structured Logging in a Shell Script with jq

Structured Logging written in ASCII and printed to a shell.

With the rise of DevOps, the focus on observability and analysis continues to grow. The DevOps toolkit has allowed us to part ways (mostly) of slicing and dicing logs with sed and awk . We no longer have to traverse filesystems or tail logs with grep . Instead logs get shipped to an aggregator. From there we can perform queries, analysis, wow our leaders with beautiful dashboards, and yes… build alerts so we can page our teammates in the middle of the night.

Yet *most shell scripts I encounter in the cash grabbing back-alley repositories of Corporate America and neckbeard Open Source projects rarely have structured log messages for me to pass along to the poor schmuck who’s helping troubleshoot my issues. Switching our scripts to structured logging means we can build better tooling that will help reduce the mean time to resolve issues.

Why It’s Not Common Place.

I believe developers do not implement structured logging into their shell scripts is for one reason.

POSIX compliance

POSIX does not require shells to support associative arrays. POSIX does not require a utility to easily parse open standard objects like JSON or… YAML. Ew.

It is that simple.
It is that frustrating.

What Can We Do?

One of the only cross-platform binaries I carry in my toolkit is jq . It allows us to query JSON from the shell. Not only that, but a little lesser known functionality is the ability to build objects with it. Therefore, we can write a simple wrapper function around it to streamline our logging messages.

Here’s How To Get Started.

Step 1.0 Install jq

You can install jq several different ways. The most intuitive though would be to install it via a package manager that you use.

• MacOS: Homebrew
• Windows: Chocolatey
• Linux: Please query your distribution’s package manager.

If you’d rather install the binary without a package manager, that’s cool too. Head over to https://github.com/stedolan/jq/releases and grab the latest release for your operating system. Please do not forget to add it to your user or system path.

Note: I am including Windows here because a lot of the time employers require you to use Windows for developer workstations.

Step 2.0 Create The Function

Go ahead and open your favorite editor so we can create our wrapper function.

Step 2.1 An Empty Object

To get started, let’s create a function called __log that accepts two arguments. The first argument will be the log level. The second argument will be the message we want to output.

__log(){
  log_level="$1"
  message="$2"
}

Once we’ve defined your arguments, we will add jq. Add a call to echo and pass empty curly braces to create an empty JSON object. We pipe this empty object to jq so that an object exists. This must be done so that we have an object that we can append our keys and values to.

Last, we need to add a call to __log so that our function executes.

__log(){
  log_level="$1"
  message="$2"
  echo '{}' | jq
}

Save your file. Head over to your shell and execute your script. If we’ve done everything correctly, we should see output that is similar to below.

Expected Output:

{}

Step 2.2 Add Log Level and Message to the Object

Great, we have an empty object! Now let’s update our function so that we can pass in our log level and message to the object. We will utilize a flag provided by jq called --arg . This allows us to define a key with a variable. We will create the keys log_level and message whose values are equal to the arguments we created earlier that have the same names.

The third argument is a string. This is how we append our two keys and their values to the empty object we created with jq in Step 2.1

To wrap up this section, let’s pass a log level of INFO and a message of Hello, World! to __log .

__log(){
  log_level="$1"
  message="$2"
  echo '{}' | jq \
    --arg log_level "$log_level" \
    --arg message "$message" \
    '.log_level=$log_level|.message=$message'
}
__log "INFO" "Hello, World!"

Note: Appending backslashes to the end of our lines allows us to add line breaks within our shell script. This allows us to shorten the line length which often makes code easier to read.

If you execute your script, you should see output that is similar to below.

{
  "log_level": "INFO",
  "message": "Hello, World."
}

Look at us! Look. At. Us. We have some pretty JSON! We are making progress but we still don’t have a clue when someone executed this script. So let’s create a timestamp function and add that to our object.

Step 2.3 Adding A Timestamp

I really like functions. Instead of just dumping in some ugly call to the date function, we’re going to wrap it in a function as well. We will call that __timestamp .

We will also need to add another --arg to our jq call. We will call it timestamp and its value will be a sub-shell call to our newly created __timestamp function.

We also must update that third argument to append our timestamp to the JSON object.

__timestamp(){
  date "+%Y%m%dT%H%M%S"
}
__log(){
  log_level="$1"
  message="$2"
  echo '{}' | jq \
    --arg timestamp "$(__timestamp)" \
    --arg log_level "$log_level" \
    --arg message "$message" \
    '.timestamp=$timestamp|.log_level=$log_level|.message=$message'
}
__log "INFO" "Hello, World!"

Once you’ve done that, save your file and execute the script again. Given the functions were updated correctly, you should see output that is similar to below. Please note that the timestamps will be different.

Expected Output:

{
  "timestamp": "20210812T190811",
  "log_level": "INFO",
  "message": "Hello, World."
}

Woot! We’re so much closer to having a simple structured logger for our shell scripts. The only issue is that pretty-printed JSON does not make for great logging. In the next step we are going to address a few issues.

Step 3.0 The Finishing Touches

Besides us not wanting to have our JSON pretty-printed, jq also defaults to outputting color. In case we’re running in a shell that does not support color, we are going to disable that behavior as well.

Update the jq function with the flags --monochrome-output , --compact-output , and --raw-output .

__timestamp(){
  date "+%Y%m%dT%H%M%S"
}
__log(){
  log_level="$1"
  message="$2"
  echo '{}' | \
  jq  --monochrome-output \
      --compact-output \
      --raw-output \
      --arg timestamp "$(__timestamp)" \
      --arg log_level "$log_level" \
      --arg message "$message" \
      '.timestamp=$timestamp|.log_level=$log_level|.message=$message'
}
__log "INFO" "Hello, World!"

Once finished, execute your script again. If the updates were done correctly, you should see output similar to the following.

Expected Output:

{"timestamp":"20210812T191730","log_level":"INFO","message":"Hello, World!"}

Conclusion

Beautiful! I just walked you through implementing a simple structured logger for shell scripts. This should work for Bash, ZSH, and many others! Continue to play with this and expand it. Consider implementing this into your day-to-day operations and productivity scripts.

I don’t expect it will take long before someone has issues and passes these beautiful logs over. You’ll be able to parse the logs or throw them into log analysis tools that can extract fields the fields with ease and reduce the time it will take to resolve issues.

Happy Hacking!