Few days back I had an issue where a script was getting timed out, from logs it was successful, it took 2 hours rather than 10 mins as what I thought would be enough time for it to complete. That script was pretty old and was created to work without proper logging, it just outputted log messages to stdout.

Lets say that the script under discussion is ManagementNodeBackup.sh

#!/bin/bash
echo "logging statement 1"
sleep 2
echo "logging statement 2"
sleep 2
echo "logging statement 3"
sleep 2
echo "logging statement 4"

even though here I have wrote it as a bash script this method will work for any scripting language or a compiled binary file too.

Execution of the script may provide output like:

$ bash ManagementNodeBackup.sh 
logging statement 1
logging statement 2
logging statement 3
logging statement 4

After I ran the script with the decorated caused it to output:

time bash -x ManagementNodeBackup.sh 2>&1 | 
while IFS='' read -r line || [[ -n "$line" ]]
do
    echo `date +%s` " $line";
done 2>&1 | tee backup.log

like this:

$ time bash -x ManagementNodeBackup.sh 2>&1 | 
> while IFS='' read -r line || [[ -n "$line" ]]
> do
>     echo `date +%s` " $line";
> done 2>&1 | tee backup.log
1516711319  + echo 'logging statement 1'
1516711319  logging statement 1
1516711319  + sleep 2
1516711321  + echo 'logging statement 2'
1516711321  logging statement 2
1516711321  + sleep 2
1516711323  + echo 'logging statement 3'
1516711323  logging statement 3
1516711323  + sleep 2
1516711325  + echo 'logging statement 4'
1516711325  logging statement 4

real    0m6.016s
user    0m0.011s
sys     0m0.028s

Explanation:

Here I started by redirecting stderr to stdout in command execution like: command 2>&1

Now for, every line which is outputted on stdout we are going to read the line in a small bash program (i.e. while loop) and prepend date to it and print, like:

command 2>&1 |
while IFS='' read -r line || [[ -n "$line" ]]
do
    echo `date +%s` " $line";
done

Other two qualifiers, first command time and last construct | tee are just to add more information and capture the output into log file which can be shipped back from production environment for debugging.