Diff for "BashFAQ/107"

How do I add a timestamp to every line of a stream?

Adding timestamps to a stream is a challenge, because there aren't any standard tools to do it. You either have to install something specifically for it (e.g. ts from moreutils, or multilog from daemontools), or write a filter in some programming language. Ideally, you do not want to fork a date(1) command for every line of input that you're logging, because it's too slow. You want to use builtins. Older versions of bash cannot do this. You need at least Bash 4.2 for the printf %(...)T option. Otherwise, you could write something in Perl, Python, Tcl, etc. to read lines and write them out with timestamps.

Here's a simple timestamper using Bash 4.2, with 1 second resolution:

# Bash 4.2 or later
stamper() {
  while read -r; do
    printf '%(%Y-%m-%d %H:%M:%S)T %s\n' -1 "$REPLY"
  done
}

You could also use %(%s)T on systems that support %s in strftime(3), for Unix epoch timestamps. Sadly, this is not portable.

One external tool designed specifically for this purpose is ts from the moreutils package. Its default format is poorly chosen (human readable month names, in Mmm DD YYYY format), but you can specify a format. It supports microsecond resolution.

stamper() {
    ts "%Y-%m-%d %H:%M:%S.%.S"
}

Another choice is multilog, with nanosecond resolution:

stamper() {
  multilog t e 2>&1
}

The e option of multilog tells it to write each line to stderr, instead of to a file in an automatically rotated directory. multilog writes timestamps in TAI64N format, which is similar in nature to Unix epoch format. Use a conversion tool (e.g. tai64nlocal) to make them human-readable.

Here's an example using Tcl, with microsecond resolution:

#!/usr/bin/env tclsh
while {[gets stdin line] >= 0} {
    set now [clock microseconds]
    set frac [expr {$now % 1000000}]
    set now [expr {$now / 1000000}]
    puts "[clock format $now -format {%Y-%m-%d %H:%M:%S}].$frac $line"
}

That works best as a separate, standalone script. Embedding it in a bash function is also possible, albeit ugly:

stamper() {
  tclsh <(cat <<\EOF
    while {[gets stdin line] >= 0} {
      set now [clock microseconds]
      set frac [expr {$now % 1000000}]
      set now [expr {$now / 1000000}]
      puts "[clock format $now -format {%Y-%m-%d %H:%M:%S}].$frac $line"
    }
EOF
  )
}

For perl fans, here's one with 1 second resolution:

stamper() {
    perl -p -e '$|=1; @l=localtime; printf "%04d-%02d-%02d %02d:%02d:%02d ",
        1900+$l[5], $l[4], $l[3], $l[2], $l[1], $l[0]'
}

Pick one of these, or write another one (or a better one) in your preferred language. Let's call whichever one you chose stamper. For the purposes of this section, let's say we're not completely insane, so we don't care about separation of stdout and stderr. We just want it all in one file, in order, with stdout and stderr mixed together.

Now, it's somewhat easy to run a script so that its output and stderr go to the screen normally, while timestamped lines go to a logfile:

./myscript 2>&1 | tee >(stamper >logfile)

Putting this same thing inside a script is slightly more involved:

#!/bin/bash
exec > >(tee >(stamper >logfile)) 2>&1

while sleep 0.2s; do
    echo "TPS report $RANDOM"
done

And of course, buffering issues may exist, if the parts of the script that write to stamper use stdout buffering. Take that into consideration.

I don't care how slow it is! I want to call date(1) a thousand times a second! My PC doubles as my space-heater!

This is inefficient and horrible.

stamper() {
  while read -r; do
    printf '%s %s\n' "$(date +'%Y-%m-%d %H:%M:%S')" "$REPLY"
  done
}

Don't use this. It's stupid. You were warned.