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.

Solution 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.

Solution 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.

Comments

[slm]

Is this not what you want? stackoverflow.com/questions/21564/…

[peterph]

@slm probably not, since OP needs to prepend different strings to different streams.

[peterph]

Can you share why the order is so important? Maybe there could be some other way around your problem...

[Deim0s]

@peterph it's a prerequisite, if I can't have consistent output I'd rather send it to /dev/null than read it and get confused by it :) 2>&1 preserves order for example, but doesn't allow the kind of customization that I ask in this question

[peterph]

See also groups.google.com/forum/#!topic/comp.unix.shell/zpAjBAO0pIo

[peterph]

Depends on what exactly is the problem you are trying to solve. In many cases it is enough to know that the error description is in the +/-X lines from the output it refers to. It can also be an indication that the thing you are running needs fixing in the way it uses the two output streams. IOW take a step back and re-check validity/correctness of the prerequisite.

[Deim0s]

@slm close enough, except for the differentiation of stdout/stderr :(

[Deim0s]

@peterph all the software/scripts I use do (correctly) output information/debug messages on stdout and errors on stderr. The prerequisite is IMO valid because what I want to achieve is decorated output (think about: compilation results, deployment results etc). The prefix would help to decorate with colour, timestamp, etc

[peterph]

Let us continue this discussion in chat.

[Gilles 'SO- stop being evil']

This is fundamentally the same question as Show only stderr on screen but write both stdout and stderr to file, and it's a hard problem (no one produced any correct answer last time round).

[Deim0s]

@Gilles it's not the same question, but both of them do indeed try to tackle the same underlying technical limitation. I think it's not possible, I will update question to reflect this situation.

[Don Hatch]

You say "I think that if a terminal emulator can do it, then it's not [impossible]". I don't think that follows. A terminal emulator receiving merged stdout and stderr isn't any different from a file or pipe receiving the merged stdout and stderr via 2>&1, for the purposes of this question-- in all those cases, the program's fds 1 and 2 refer to the same underlying thing (kernel resource), and that's when interleaving order is guaranteed to stay correct. As soon as the fds are redirected to different underlying things, the ordering is lost, in all of these cases.

[Deim0s]

@DonHatch but the terminal emulator knows which is which when rendering them. Perhaps I could look at how podman does this, similarly.

[Don Hatch]

@Deim0s What makes you say a terminal emulator knows which is which when rendering them? I don't believe it does.

[Deim0s]

Thanks @peterph for your answer, however I am looking specifically for ways to preserve the order. Note: I think your interpreter should be bash because of the process substitution you use (I get ./test1.sh: 3: ./test1.sh: Syntax error: "(" unexpected by copy/pasting your script)

[peterph]

Very likely so, I ran it in bash with /bin/sh (not sure why I had it there).

[peterph]

I've updated the question a bit, regarding where the stream mix-up could happen.

[Deim0s]

Thanks @peterph, however I have not given up on alternatives to total-syscall-wrapping and I'd like to explore how this is done in VTE library and in general with ptys. Perhaps nobody has tried those routes or found already that syscall wrapping is the only way; the reason behind it is still interesting to me (remember: on a terminal emulator looks good...)

[peterph]

What you see on terminal is basically what you get with 2>&1 - see ls -al /proc/$$/fd. thr two streams end in the same sink.

[peterph]

unfortunately this also doesn't solve the problem of possibly swapping some lines.

[Deim0s]

exactly. I think the answer to this question of mine is "not possible". Event with stderred you cannot easily determine boundaries of lines (trying so would be hackish). I wanted to see if somebody could help me with this problem but apparently everybody wants to give up the single constraint (order) that is the basis for the question

[Charles Duffy]

eval $@ is quite buggy. Use "$@" if you want to run your arguments as an exact command line -- adding a layer of eval interpretation throws in a bunch of hard-to-predict (and potentially malicious, if you're passing filenames or other content you don't control as arguments) behaviors, and failing to quote even moreso (splits names with spaces into multiple words, expands globs even if they were previously quoted to be literal, etc).

[Charles Duffy]

Also, in modern-enough-to-have-coprocesses bash, you don't need eval to close file descriptors named in a variable. exec {SEDo[1]}>&- will work as-is (yes, the lack of a $ before the { was deliberate).

[Olivier Dulac]

+1 for using @StephaneChazelas's answer (and pointing to it for further reading) :). And for the warnings about potential side effects.

[Austin Hanson]

Method 1's step 2 requires another { at the front to work properly.