How to add timestamp to STDERR redirection

问题:

In bash/ksh can we add timestamp to STDERR redirection?

E.g. myscript.sh 2> error.log

I want to get a timestamp written on the log too.

回答1:

If you're talking about an up-to-date timestamp on each line, that's something you'd probably want to do in your actual script (but see below for a nifty solution if you have no power to change it). If you just want a marker date on its own line before your script starts writing, I'd use:

( date 1>&2 ; myscript.sh ) 2>error.log

What you need is a trick to pipe stderr through another program that can add timestamps to each line. You could do this with a C program but there's a far more devious way using just bash.

First, create a script which will add the timestamp to each line (called predate.sh):

#!/bin/bash
while read line ; do
    echo "$(date): ${line}"
done

For example:

( echo a ; sleep 5 ; echo b ; sleep 2 ; echo c ) | ./predate.sh

produces:

Fri Oct  2 12:31:39 WAST 2009: a
Fri Oct  2 12:31:44 WAST 2009: b
Fri Oct  2 12:31:46 WAST 2009: c

Then you need another trick that can swap stdout and stderr, this little monstrosity here:

( myscript.sh 3>&1 1>&2- 2>&3- )

Then it's simple to combine the two tricks by timestamping stdout and redirecting it to your file:

( myscript.sh 3>&1 1>&2- 2>&3- ) | ./predate.sh >error.log

The following transcript shows this in action:

pax> cat predate.sh
    #!/bin/bash
    while read line ; do
        echo "$(date): ${line}"
    done
pax> cat tstdate.sh
    #!/bin/bash
    echo a to stderr then wait five seconds 1>&2
    sleep 5
    echo b to stderr then wait two seconds 1>&2
    sleep 2
    echo c to stderr 1>&2
    echo d to stdout
pax> ( ( ./tstdate.sh ) 3>&1 1>&2- 2>&3- ) | ./predate.sh >error.log
    d to stdout
pax> cat error.log
    Fri Oct  2 12:49:40 WAST 2009: a to stderr then wait five seconds
    Fri Oct  2 12:49:45 WAST 2009: b to stderr then wait two seconds
    Fri Oct  2 12:49:47 WAST 2009: c to stderr

As already mentioned, predate.sh will prefix each line with a timestamp and the tstdate.sh is simply a test program to write to stdout and stderr with specific time gaps.

When you run the command, you actually get "d to stdout" written to stderr (but that's your TTY device or whatever else stdout may have been when you started). The timestamped stderr lines are written to your desired file.

回答2:

The devscripts package in Debian/Ubuntu contains a script called annotate-output which does that (for both stdout and stderr).

$ annotate-output make
21:41:21 I: Started make
21:41:21 O: gcc -Wall program.c
21:43:18 E: program.c: Couldn't compile, and took me ages to find out
21:43:19 E: collect2: ld returned 1 exit status
21:43:19 E: make: *** [all] Error 1
21:43:19 I: Finished with exitcode 2

回答3:

Here's a version that uses a while read loop like pax's, but doesn't require extra file descriptors or a separate script (although you could use one). It uses process substitution:

myscript.sh 2> >( while read line; do echo "$(date): ${line}"; done > error.log )

Using pax's predate.sh:

myscript.sh 2> >( predate.sh > error.log )

回答4:

The program ts from the moreutils package pipes standard input to standard output, and prefixes each line with a timestamp.

To prefix stdout lines: command | ts
To prefix both stdout and stderr: command 2>&1 | ts

回答5:

I like those portable shell scripts but a little disturbed that they fork/exec date(1) for every line. Here is a quick perl one-liner to do the same more efficiently:

perl -p -MPOSIX -e 'BEGIN {$!=1} $_ = strftime("%T ", localtime) . $_'

To use it, just feed this command input through its stdin:

(echo hi; sleep 1; echo lo) | perl -p -MPOSIX -e 'BEGIN {$|=1} $_ = strftime("%T ", localtime) . $_'

回答6:

Rather than writing a script to pipe to, I prefer to write the logger as a function inside the script, and then send the entirety of the process into it with brackets, like so:

 # Vars    
 logfile=/path/to/scriptoutput.log

 # Defined functions
 teelogger(){
   log=$1
   while read line ; do
     print "$(date +"%x %T") :: $line" | tee -a $log
   done
 }


# Start process
{

echo 'well'
sleep 3
echo 'hi'
sleep 3
echo 'there'
sleep 3
echo 'sailor'

}  |  teelogger $logfile

回答7:

If you want to redirect back to stdout I found you have to do this:

myscript.sh >> >( while read line; do echo "$(date): ${line}"; done )

Not sure why I need the > in front of the (, so <(, but thats what works.

回答8:

I was too lazy for all current solutions... So I figured out new one (works for stdout could be adjusted for stderr as well):

echo "output" | xargs -L1 -I{} bash -c "echo \$(date +'%x %T') '{}'" | tee error.log

would save to file and print something like that: 11/3/16 16:07:52 output

Details:

-L1 means "for each new line"

-I{} means "replace {} by input"

bash -c is used to update $(date) each time for new call

%x %T formats timestamp to minimal form.

It should work like a charm if stdout and stderr doesn't have quotes (" or `). If it has (or could have) it's better to use:

echo "output" | awk '{cmd="(date +'%H:%M:%S')"; cmd | getline d; print d,$0; close(cmd)} | tee error.log'

(Took from my answer in another topic: https://stackoverflow.com/a/41138870/868947)

回答9:

#!/bin/bash

DEBUG=1

LOG=$HOME/script_${0##*/}_$(date +%Y.%m.%d-%H.%M.%S-%N).log
ERROR=$HOME/error.log

exec 2> $ERROR
exec 1> >(tee -ai $LOG)

if [ $DEBUG = 0 ] ; then
    exec 4> >(xargs -i echo -e "[ debug ] {}")
else
    exec 4> /dev/null
fi

# test
echo " debug sth " >&4
echo " log sth normal "
type -f this_is_error
echo " errot sth ..." >&2
echo " finish ..." >&2>&4
# close descriptor 4
exec 4>&-

回答10:

This thing: nohup myscript.sh 2> >( while read line; do echo "$(date): ${line}"; done > mystd.err ) < /dev/null &

Works as such but when I log out and log back in to the server, it does not work. that is mystd.err stop getting populated with stderr stream even though my process (myscript.sh here) still runs.

Does someone know how to get back the lost stderr in the mystd.err file back?

回答11:

Thought I would add my 2 cents worth..

#!/bin/sh

timestamp(){
  name=$(printf "$1%*s" `expr 15 - ${#1}`)
  awk "{ print strftime(\"%b %d %H:%M:%S\"), \"- $name -\", $$, \"- INFO -\", \$0; fflush() }";
}

echo "hi" | timestamp "process name" >> /tmp/proccess.log

printf "$1%*s" `expr 15 - ${#1}`
Spaces the name out so it looks nice, where 15 is the max space issued, increase if desired

outputs >> Date - Process name - Process ID - INFO - Message

Jun 27 13:57:20 - process name     - 18866 - INFO - hi

回答12:

How about timestamping the remaining output, redirecting all to stdout?

This answer combines some techniques from above, as well as from unix stackexchange here and here. bash >= 4.2 is assumed, but other advanced shells may work. For < 4.2, replace printf with a (slower) call to date.

: ${TIMESTAMP_FORMAT:="%F %T"} # override via environment
_loglines() { 
    while IFS= read -r _line ; do 
      printf "%(${TIMESTAMP_FORMAT})T#%s\n" '-1' "$_line";
    done;
}
exec 7<&2 6<&1
exec &> >( _loglines )
# Logit

To restore stdout/stderr:

exec 1>&6 2>&7

You can then use tee to send the timestamps to stdout and a logfile.

_tmpfile=$(mktemp)
exec &> >( _loglines | tee $_tmpfile )

Not a bad idea to have cleanup code if the process exited without error:

trap "_cleanup \$?" 0 SIGHUP SIGINT SIGABRT SIGBUS SIGQUIT SIGTRAP SIGUSR1 SIGUSR2 SIGTERM
_cleanup() { 
    exec >&6 2>&7
    [[ "$1" != 0 ]] && cat "$_logtemp"
    rm -f "$_logtemp"
    exit "${1:-0}"
}

回答13:

Redirections are taken in order. Try this:

Given a script -

$: cat tst
echo a
sleep 2
echo 1 >&2
echo b
sleep 2
echo 2 >&2
echo c
sleep 2
echo 3 >&2
echo d

I get the following

$: ./tst 2>&1 1>stdout | sed 's/^/echo $(date +%Y%m%dT%H%M%S) /; e'
20180925T084008 1
20180925T084010 2
20180925T084012 3

And as much as I dislike awk, it does avoid the redundant subcalls to date.

$: ./tst 2>&1 1>stdout | awk "{ print strftime(\"%Y%m%dT%H%M%S \") \$0; fflush() }"; >stderr

$: cat stderr
20180925T084414 1
20180925T084416 2
20180925T084418 3

$: cat stdout
a
b
c
d