How to capture ordered STDOUT/STDERR and add timestamp/prefixes?

Question

I have explored almost all available similar questions, to no avail.

Let me describe the problem in detail:

I run some unattended scripts and these can produce standard output and standard error lines, I want to capture them in their precise order as displayed by a terminal emulator and then add a prefix like "STDERR: " and "STDOUT: " to them.

I have tried using pipes and even epoll-based approach on them, to no avail. I think solution is in pty usage, although I am no master at that. I have also peeked into the source code of Gnome's VTE, but that has not been much productive.

Ideally I would use Go instead of Bash to accomplish this, but I have not been able to. Seems like pipes automatically forbid keeping a correct lines order because of buffering.

Has somebody been able to do something similar? Or it is just impossible? I think that if a terminal emulator can do it, then it's not - maybe by creating a small C program handling the PTY(s) differently?

Ideally I would use asynchronous input to read these 2 streams (STDOUT and STDERR) and then re-print them second my needs, but order of input is crucial!

NOTE: I am aware of stderred but it does not work for me with Bash scripts and cannot be easily edited to add a prefix (since it basically wraps plenty of syscalls).

Update: added below two gists

• Example program that generates mixed stdout/stderr
• Expected output from program above

(sub-second random delays can be added in the sample script I provided for a proof of consistent results)

Update: solution to this question would also solve this other question, as @Gilles pointed out. However I have come to the conclusion that it's not possible to do what asked here and there. When using 2>&1 both streams are correctly merged at the pty/pipe level, but to use the streams separately and in correct order one should indeed use the approach of stderred that involves syscall hooking and can be seen as dirty in many ways.

I will be eager to update this question if somebody can disprove the above.

Answer 1

You might use coprocesses. Simple wrapper that feeds both outputs of a given command to two sed instances (one for stderr the other for stdout), which do the tagging.

#!/bin/bash
exec 3>&1
coproc SEDo ( sed "s/^/STDOUT: /" >&3 )
exec 4>&2-
coproc SEDe ( sed "s/^/STDERR: /" >&4 )
eval $@ 2>&${SEDe[1]} 1>&${SEDo[1]}
eval exec "${SEDo[1]}>&-"
eval exec "${SEDe[1]}>&-"

Note several things:

1. It is a magic incantation for many people (including me) - for a reason (see the linked answer below).

2. There is no guarantee it won't occasionally swap couple of lines - it all depends on scheduling of the coprocesses. Actually, it is almost guaranteed that at some point in time it will. That said, if keeping the order strictly the same, you have to process the data from both stderr and stdin in the same process, otherwise the kernel scheduler can (and will) make a mess of it.

   If I understand the problem correctly, it means that you would need to instruct the shell to redirect both streams to one process (which can be done AFAIK). The trouble starts when that process starts deciding what to act upon first - it would have to poll both data sources and at some point get into state where it would be processing one stream and data arrive to both streams before it finishes. And that is exactly where it breaks down. It also means, that wrapping the output syscalls like stderred is probably the only way to achieve your desired outcome (and even then you might have a problem once something becomes multithreaded on a multiprocessor system).

As far as coprocesses be sure to read Stéphane's excellent answer in How do you use the command coproc in Bash? for in depth insight.

Answer 2

Method #1. Using file descriptors and awk

What about something like this using the solutions from this SO Q&A titled: Is there a Unix utility to prepend timestamps to lines of text? and this SO Q&A titled: pipe STDOUT and STDERR to two different processes in shell script?.

The approach

Step 1, we create 2 functions in Bash that will perform the timestamp message when called:

$ msgOut () {  awk '{ print strftime("STDOUT: %Y-%m-%d %H:%M:%S"), $0; fflush(); }'; }
$ msgErr () {  awk '{ print strftime("STDERR: %Y-%m-%d %H:%M:%S"), $0; fflush(); }'; }

Step 2 you'd use the above functions like so to get the desired messaging:

$ { { { ...command/script... } 2>&3; } 2>&3 | msgErr; } 3>&1 1>&2 | msgOut

Example

Here I've concocted an example that will write a to STDOUT, sleeps for 10 seconds, and then writes output to STDERR. When we put this command sequence into our construct above we get messaging as you specified.

$ { { echo a; sleep 10; echo >&2 b; } 2>&3 | \
    msgErr; } 3>&1 1>&2 | msgOut
STDERR: 2014-09-26 09:22:12 a
STDOUT: 2014-09-26 09:22:22 b

Method #2. Using annotate-output

There's a tool called annotate-output that's part of the devscripts package that will do what you want. It's only restriction is that it must run the scripts for you.

Example

If we put our above example command sequence into a script called mycmds.bash like so:

$ cat mycmds.bash 
#!/bin/bash

echo a
sleep 10
echo >&2 b

We can then run it like this:

$ annotate-output ./mycmds.bash 
09:48:00 I: Started ./mycmds.bash
09:48:00 O: a
09:48:10 E: b
09:48:10 I: Finished with exitcode 0

The output's format can be controlled for the timestamp portion but not beyond that. But it's similar output to what you're looking for, so it may fit the bill.

Answer 3

Seeing as your scripts essentially split their output into two separate pipes, it becomes physically impossible for even just one program attached to these pipes to make 100% sure no lines are swapped - it would have to perform alternating non-blocking reads on these pipes, and at some point it would have to decide which pipe to read from next. That said, I suspect even terminal emulators can't be trusted to perfectly preserve the order of lines.