Prepending a timestamp to each line of output from a command

Firstly, if you are expecting these timestamps to actually represent an event, bear in mind that since many programs perform line buffering (some more aggressively than others), it is important to think of this as close to the time that the original line would have been printed rather than a timestamp of an action taking place.

You may also want to check that your command doesn’t already have an inbuilt feature dedicated to doing this. As an example, ping -D exists in some ping versions, and prints the time since the Unix epoch before each line. If your command does not contain its own method, however, there are a few methods and tools that can be employed, amongst others:

POSIX shell

Bear in mind that since many shells store their strings internally as cstrings, if the input contains the null character (), it may cause the line to end prematurely.

command | while IFS= read -r line; do printf '[%s] %sn' "$(date '+%Y-%m-%d %H:%M:%S')" "$line"; done

GNU awk

command | gawk '{ print strftime("[%Y-%m-%d %H:%M:%S]"), $0 }'

Perl

command | perl -pe 'use POSIX strftime; print strftime "[%Y-%m-%d %H:%M:%S] ", localtime'

Python

command | python -c 'import sys,time;sys.stdout.write("".join(( " ".join((time.strftime("[%Y-%m-%d %H:%M:%S]", time.localtime()), line)) for line in sys.stdin )))'

Ruby

command | ruby -pe 'print Time.now.strftime("[%Y-%m-%d %H:%M:%S] ")'

You can do this with date and xargs:

... | xargs -L 1 echo `date +'[%Y-%m-%d %H:%M:%S]'` $1

Explanation:

xargs -L 1 tells xargs to run the proceeding command for every 1 line of input, and it passes in the first line as it does so. echo `date +'[%Y-%m-%d %H:%M:%S]'` $1 basically echoes the date with the input argument at the end of it

Ryan’s post does provide an interesting idea, however, it fails in several regards. While testing with tail -f /var/log/syslog | xargs -L 1 echo $(date +'[%Y-%m-%d %H:%M:%S]') $1 , I noticed that timestamp stays the same even if stdout comes later with difference in seconds apart. Consider this output:

[2016-07-14 01:44:25] Jul 14 01:44:32 eagle dhclient[16091]: DHCPREQUEST of 192.168.0.78 on wlan7 to 255.255.255.255 port 67 (xid=0x411b8c21)
[2016-07-14 01:44:25] Jul 14 01:44:34 eagle avahi-daemon[740]: Joining mDNS multicast group on interface wlan7.IPv6 with address fe80::d253:49ff:fe3d:53fd.
[2016-07-14 01:44:25] Jul 14 01:44:34 eagle avahi-daemon[740]: New relevant interface wlan7.IPv6 for mDNS.

My proposed solution is similar, however provides proper time-stamping and uses somewhat more portable printf rather than echo

| xargs -L 1 bash  -c 'printf "[%s] %sn" "$(date +%Y-%m-%d %H:%M:%S )" "$*" ' bash

Why bash -c '...' bash ? Because due to -c option, first argument gets assigned to $0 and won’t show up in the output. Consult your shell’s manual page for the proper description of -c

Testing this solution with tail -f /var/log/syslog and (as you probably could guess) disconnecting and reconnecting to my wifi, has shown the proper time-stamping provided by both date and syslog messages

Bash could be replaced by any bourne-like shell, could be done with either ksh or dash , at least those that have -c option.

Potential issues:

The solution requires having xargs ,which is available on POSIX compliant systems, so most Unix-like systems should be covered. Obviously won’t work if your system is non-POSIX compliant or doesn’t have GNU findutils

For a line-by-line delta measurement, try gnomon.

It is a command line utility, a bit like moreutils’s ts, to prepend timestamp information to the standard output of another command. Useful for long-running processes where you’d like a historical record of what’s taking so long.

Piping anything to gnomon will prepend a timestamp to each line, indicating how long that line was the last line in the buffer–that is, how long it took the next line to appear. By default, gnomon will display the seconds elapsed between each line, but that is configurable.

Most of answers suggest to use date, but it’s slow enough. If your bash version is greater than 4.2.0 it’s better to use printf instead, it’s a bash builtin.
If you need to support legacy bash versions you can create log function depends on bash version:

TIMESTAMP_FORMAT='%Y-%m-%dT%H:%M:%S'
# Bash version in numbers like 4003046, where 4 is major version, 003 is minor, 046 is subminor.
printf -v BV '%d%03d%03d' ${BASH_VERSINFO[0]} ${BASH_VERSINFO[1]} ${BASH_VERSINFO[2]}
if ((BV > 4002000)); then
log() {
    ## Fast (builtin) but sec is min sample for most implementations
    printf "%(${TIMESTAMP_FORMAT})T %5d %sn" '-1' $$ "$*"  # %b convert escapes, %s print as is
}
else
log() {
    ## Slow (subshell, date) but support nanoseconds and legacy bash versions
    echo "$(date +"${TIMESTAMP_FORMAT}") $$ $*"
}
fi

See speed differences:

user@host:~$time for i in {1..10000}; do printf "%(${TIMESTAMP_FORMAT})T %sn" '-1' "Some text" >/dev/null; done

real    0m0.410s
user    0m0.272s
sys     0m0.096s
user@host:~$time for i in {1..10000}; do echo "$(date +"${TIMESTAMP_FORMAT}") Some text" >/dev/null; done

real    0m27.377s
user    0m1.404s
sys     0m5.432s

UPD: instead of $(date +"${TIMESTAMP_FORMAT}") it’s better to use $(exec date +"${TIMESTAMP_FORMAT}") or even $(exec -c date +"${TIMESTAMP_FORMAT}") too speedup execution.

UPD2: bash 5 provides EPOCHREALTIME variable for microseconds granularity, you can use it by this command (about 30% slower than seconds only):
printf "%(${TIMESTAMP_FORMAT})T.%s %5d %sn" ${EPOCHREALTIME/./ } $$ "$*"

I would have preferred to comment above but I can’t, reputationally. Anyway, the Perl sample above can be unbuffered as follows:

command | perl -pe 'use POSIX strftime; 
                    $|=1; 
                    select((select(STDERR), $| = 1)[0]);
                    print strftime "[%Y-%m-%d %H:%M:%S] ", localtime'

The first ‘$|’ unbuffers STDOUT. The second one sets stderr as the current default output channel and unbuffers it. Since select returns the original setting of $|, by wrapping the select inside a select, we also reset $| to its default, STDOUT.

And yes, you can cut ‘n paste as is. I multi-lined it for legibility.

And if you really want to get precise (and you have Time::Hires installed):

command | perl -pe 'use POSIX strftime; use Time::HiRes gettimeofday;
                    $|=1; 
                    select((select(STDERR), $| = 1)[0]);
                    ($s,$ms)=gettimeofday();
                    $ms=substr(q(000000) . $ms,-6);
                    print strftime "[%Y-%m-%d %H:%M:%S.$ms]", localtime($s)'

Shameless plug for something I just wrote to solve this exact problem: ets, written in Go.

You can find a lot of usage examples on the project page.

The notable difference from existing answers and similar offerings is that ets is designed to run your command for you, in a pty (pseudo tty) — that is to say, simulating your command running natively in a tty. Compared to piping command output into e.g. ts, this makes timestamping mostly transparent, and solves a bunch of issues of piping:

• Some programs aggressively buffer when writing to a pipe, so you see no output and then a whole bunch of output (yeah, you can stdbuf them, you can even wrap stdbuf and ts in an alias/function, but wouldn’t it be better if things work out of the box);
• Some programs disable color and/or interactivity when writing to a pipe;
• Exit status is gone unless you turned on pipefail; etc.

Commands can be directly exec’ed, meaning you can simply prepend ets to your existing command line, or they can be shell commands (as shown in the gif above). Of course, if you want to pipe output in, ets can do that too.

ets supports the same timestamp modes as moreutils ts: absolute time mode, elapsed time mode, and incremental time mode. It uses saner defaults (e.g. monotonic clock is always used for elapsed/incremental timestamps) and has additional support for custom time zones. There’s a detailed comparison here.

Again, https://github.com/zmwangx/ets. Give it a spin, report bugs, etc.

If you are working in bash, put this near the start of your script

exec &> >( ts '%Y-%m-%d.%H%M.%.S ' )  # prepend a timestamp to all output

Or, for extra credit, output to log file via:

script_name=foobar
log_file=$( printf "/tmp/${script_name}-%(%Y-%m-%d)T.%(%H%M%S)T.log" -1 )
echo "note: redirecting output to [${log_file}]"
exec &> >( ts '%Y-%m-%d %H:%M:%.S ' > ${log_file} )

to output to both console and log file:

script_name=foobar
log_file=$( printf "/tmp/${script_name}-%(%Y-%m-%d)T.%(%H%M%S)T.log" -1 )
exec &> >( ts '%Y-%m-%d %H:%M:%.S ' | tee ${log_file} )

The main advantages of doing this are to separate the logging from everything else, not cluttering the body of the script by piping to tee or similar on every command, and not having to write custom logging functions and sticking to plain old echo and printf.

The ts program is found in the moreutils package, which should be readily available under any reasonably sane administration regime. 🙂

This is a small tool implemented in C:

/*
 * Redirect stdin to stdout, prepending a millisecond-precision
 * Unix timestamp to each line.
 */
#include <stdio.h>
#include <sys/time.h>

int main(int argc, char *argv[]) {
   char *line = NULL;
   size_t linecap = 0;
   ssize_t linelen;
   struct timeval tv;

   while ((linelen = getline(&line, &linecap, stdin)) > 0) {
      gettimeofday(&tv, NULL);
      fprintf(stdout, "%lu ", tv.tv_sec*1000 + tv.tv_usec/1000);
      fwrite(line, linelen, 1, stdout);
   }
}

Paste the above code into a .c file. I call mine tsms.c. Then

gcc -o tsms tsms.c

and then

command | tsms

and you can be a big boy too.

Prefix output

{
  echo foo
  sleep 1
  echo bar >&2
} 
   > >(sed "s/^/$(date '+%Y-%m-%d %H:%M:%S') [INF] /") 
  2> >(sed "s/^/$(date '+%Y-%m-%d %H:%M:%S') [ERR] /" >&2)

Prefix output and redirect to a log file

Redirect script to test.log file:

{
  echo foo
  sleep 1
  echo bar >&2
} 
   > test.log 
  2>&1 
   > >(sed "s/^/$(date '+%Y-%m-%d %H:%M:%S') [INF] /") 
  2> >(sed "s/^/$(date '+%Y-%m-%d %H:%M:%S') [ERR] /" >&2)

Most of these answers suck for measuring performance. AWK can’t show milliseconds. Ruby and Python are slow af. Also all of them show the absolute time when you’d really want relative times.

I figured someone would probably have written a decent solution in Rust, and they have!

rtts

You can pipe into it:

-% cargo build --release 2>&1 | rtss
 274.1ms  274.1ms |    Compiling libc v0.2.40
   1.50s    1.22s |    Compiling memchr v2.0.1
   2.28s  780.8ms |    Compiling rtss v0.5.0 (file:///home/freaky/code/rtss)
   5.18s    2.90s |     Finished release [optimized] target(s) in 5.17 secs
   5.18s    exit code: 0

Or wrap a command:

-% rtss sh -c "echo foo; echo bar; sleep 1; echo moo >&2; sleep 1; echo baz; exit 64"
   1.7ms    1.7ms | foo
   1.7ms          | bar
   1.00s    1.00s # moo
   2.03s    2.03s | baz
   2.03s    exit code: 64
zsh: exit 64    rtss sh -c

-% rtss sh -c "echo foo; echo bar; sleep 1; echo moo >&2; sleep 1; echo baz; exit 64" 2>/dev/null
   1.9ms    1.9ms | foo
   1.9ms          | bar
   2.05s    2.04s | baz
   2.05s    exit code: 64
zsh: exit 64    rtss sh -c  2> /dev/null

It also shows you the time taken for each line (the second column) which is quite helpful.

It also works for both stderr and stdout.

Unfortunately they haven’t set up CI to build binaries, but installing Rust programs is easy if you already have Rust installed:

cargo install rtss