Structured Logging in Shell Scripting

Published in

Picus Security Engineering

6 min readDec 4, 2023

Any script can be written in various ways. These different ways of coding, such as the maintenance of the code or how easily analyzable the code is, can impact various aspects. Particularly, when examining how a script behaves in error situations, the topic of Structured Logging emerges as an important aspect.

Structured Logging ensures that messages written to standard output or standard error streams in the script follow a specific format. Additionally, it provides a more easily debuggable structure based on Log Levels.

In this blog, I will try to talk about how we can do structured logging in shell scripts, how we can see different logs based on level, and how we cannot see the output of each command in the script.

The three features that need to be implemented are as follows:

Logging Level: Being able to see different log messages on-demand. In this way, specific messages become visible according to the defined Log Levels.
Structured Format: Printing messages with Timestamp and Log Level Values in messages.
Unwanted Outputs of Commands: If you do not redirect the standard output and standard error streams of the command running in any script to the Null device, you will see these logs even when we do not want to debug.

I will proceed step by step by implementing a structured logging structure in a bash script. Here I will use ERROR/WARN/INFO/DEBUG as the Log Levels.

Unwanted Outputs of Commands

Here we have a script as an example below.

#!/bin/bash

set -eo pipefail

echo "Checking Docker Containers"
docker ps
echo "Not Important Log"

If we do not want to see the output of the Docker Client, we can redirect everything to the null device by adding &>/dev/null to the end.

#!/bin/bash
set -eo pipefail
echo "Checking Docker Containers"
docker ps &>/dev/null
echo "Not Important Log"

Here, we can use a wrapper method for each running command and always send the output to the null device.

#!/bin/bash
set -eo pipefail

function wrapper() {
  eval $@ &>/dev/null
}
echo "Checking Docker Containers"
wrapper "docker ps"
wrapper "docker images" 
echo "Not Important Log"

We can create a different solution with a file-based logging structure if we do not want to call each command one by one with the wrapper method.

If we create 2 files and collect all the logs in the file named ALL_LOG_FILE, we can print the logs we want to see in the standard output in the file named STRUCTURED_LOG_FILE.

#!/bin/bash
set -eo pipefail

ALL_LOG_FILE="all-log-file.txt"
STRUCTURED_LOG_FILE="structured-log-file.txt"

function log() {
    local message=$1
    echo "$message"
    echo "$message" >> $STRUCTURED_LOG_FILE
}

function createFile() {
    local file_name=$1
    rm -f $file_name && touch $file_name
}

createFile $ALL_LOG_FILE
createFile $STRUCTURED_LOG_FILE

tail -f $STRUCTURED_LOG_FILE &
exec 1>>$ALL_LOG_FILE 2>>$ALL_LOG_FILE

log "Checking Docker Containers"
docker ps
docker images
echo "Not Important Log"

If we examine the script above, we create 2 log files.

Then, with the tail command, we enable a child process to display the contents of the STRUCTURED_LOG_FILE file on the standard output of the main process. Whenever we print a message to STRUCTURED_LOG_FILE with the method called log, it now appears in the standard output of the main process.

In order not to see the output of Docker Client commands, we redirect whatever is printed to the output of the main process with the exec command to the ALL_LOG_FILE file. Thus, no matter what runs in the script, the ALL_LOG_FILE file will contain them.

Let’s examine the output of the script below.

In Standard Output, we only see the message printed with the log method. Because here we only printed this message in the STRUCTURED_LOG_FILE file content.

We can also see the file content below.

Since we direct all outputs in the script to the ALL_LOG_FILE file with the Exec command, we can see the Docker Client command outputs in the file content below.

Structured Format & Logging Levels

If we only need Debug mode and when we examine the script with Debug mode, we can show whatever is written in ALL_LOG_FILE in Standard Output. We refactor the script as follows.

#!/bin/bash
set -eo pipefail

DEBUG_MODE=${DEBUG_MODE:-false}
ALL_LOG_FILE="all-log-file.txt"
STRUCTURED_LOG_FILE="structured-log-file.txt"

function createFile() {
    local file_name=$1
    rm -f $file_name && touch $file_name
}

function log() {
    local message=$1
    local timestamp=$(date +"%Y-%m-%d %H:%M:%S")
    local log_message="[$timestamp] - $message"

    echo $log_message
    echo $log_message >> $STRUCTURED_LOG_FILE
}

createFile $ALL_LOG_FILE
createFile $STRUCTURED_LOG_FILE

if [[ $DEBUG_MODE == true ]]; then
    tail -f $ALL_LOG_FILE &
else 
    tail -f $STRUCTURED_LOG_FILE &
fi
exec 1>>$ALL_LOG_FILE 2>>$ALL_LOG_FILE


log "Checking Docker Containers"
docker ps
docker images
echo "Not Important Log."

If we set the file in which we perform the tail operation according to the value of an environment variable named DEBUG_MODE, we can see all the content in the ALL_LOG_FILE file at the same time in the Standard Output.

If we set this value to false, it will give the same output as our previous example. Because we are tailing the STRUCTURED_LOG_FILE file.

If we want our script to support more than one Log Level, we can design the Log Levels as an Enum structure and print them according to the LOG_LEVEL environment variable value.

In the example, we implement INFO/WARN/ERROR/DEBUG log levels.

#!/bin/bash

set -eo pipefail

ERROR=1
WARN=2
INFO=3
DEBUG=4

LOG_LEVEL=${LOG_LEVEL:-$INFO}
ALL_LOG_FILE="all-log-file.txt"
STRUCTURED_LOG_FILE="structured-log-file.txt"

function createFile() {
    local file_name=$1
    rm -f $file_name && touch $file_name
}

function log() {
    local log_level_int=$1
    local log_level_str=$2
    local message=${@:3}

    local timestamp=$(date +"%Y-%m-%d %H:%M:%S")


    local log_message="[$timestamp] [$log_level_str] - $message"
    echo $log_message

    if [[ $log_level_int -le $LOG_LEVEL ]]; then
        echo $log_message >> $STRUCTURED_LOG_FILE
    fi
}

function error() {
    log $ERROR "ERROR" $@
}

function warn() {
    log $WARN "WARN" $@
}

function info() {
    log $INFO "INFO" $@
}

function debug() {
    local message=$1
    log $DEBUG "DEBUG" $message
}

if [[ $LOG_LEVEL -lt $ERROR ]]; then
    LOG_LEVEL=$INFO
fi

createFile $ALL_LOG_FILE
createFile $STRUCTURED_LOG_FILE

if [[ $LOG_LEVEL -gt $DEBUG ]]; then
    tail -f $ALL_LOG_FILE &
else
    tail -f $STRUCTURED_LOG_FILE &
fi
exec 1>>$ALL_LOG_FILE 2>>$ALL_LOG_FILE


info "Checking Docker Containers"
docker ps
docker images
echo "Not Important Log"
debug "Debug Log."

If the LOG_LEVEL value is greater than the DEBUG value, we tail the ALL_LOG_FILE file, otherwise we tail the STRUCTURED_LOG_FILE file. By default, we set it as INFO value.

Here, if the info/debug/warn/error methods are less than or equal to the LOG_LEVEL value, we print the messages to the STRUCTURED_LOG_FILE file.

We can see the output below where LOG_LEVEL=3, i.e. INFO, is the default.

We can see the output below where LOG_LEVEL=4, meaning DEBUG.

LOG_LEVEL=5, that is, in the case where we want to see all command outputs, the outputs are as follows.

Conclusion

As a result, In Shell Scripts, it may be desired to see different log messages in happy paths and different log messages in error situations. For this, we can print level-based logs in a certain format. Additionally, if you do not want to see some command outputs, you can implement Structured Logging by doing file-based logging.

Thanks for reading. If you have questions or comments regarding this article, please feel free to leave a comment below.

Would like to get in touch? Reach me out on LinkedIn:

https://www.linkedin.com/in/muhammedsaidkaya/

Structured Logging in Shell Scripting

Unwanted Outputs of Commands

Structured Format & Logging Levels

Conclusion

Written by Muhammed Said Kaya