Bash: how to filter tee output in realtime for ssh command?

Question

My goal is to make a timestamped log of the commands used in my ssh sessions.

Tee works in realtime as long as the output is not filtered. When I tail -F test.log, the following command appends output in realtime:

#!/bin/bash
ssh "$@" | tee -a test.log

However, when I try to modify tee's output by methods suggested in this question, the output is no longer in realtime. For example:

#!/bin/bash
ssh "$@" | tee >(grep -e '.*\@.*\:.*\$.*' --color=never >> test.log)

Strangely, if I substitute the "yes" command instead of the ssh command, the output is filtered properly in realtime.

Realtime processing is important because my script needs to append a current timestamp to each line and remove as much output as possible. Here is my script so far:

#!/bin/bash
logfile=~/test.log
desc="sshlog ${@}"
tab="\t"
format_line() {
    while IFS= read -r line; do
        echo "$(date +"%Y-%m-%d %H:%M:%S %z")${tab}${desc}${tab}${line}"
    done
}
echo "[START]" | format_line >> $logfile
ssh "$@" | tee >(grep -e '.*\@.*\:.*\$.*' --color=never | format_line >> $logfile)
echo "[END]" | format_line >> $logfile

How can I fix this, and why is the ssh command acting differently with tee than the yes command?

Answer 1

The problem is most likely that grep is buffering its output — selecting large chunks of input, filtering them, and outputting the result — so it handles the output of yes smoothly (because yes quickly generates a lot of input for it to filter and output), whereas your ssh command probably doesn't generate as much output as quickly.

Many versions of grep offer a mechanism to tweak this buffering. Since you're on Linux, you're likely using GNU Grep, which offers a --line-buffered flag for this purpose (see the "Other Options" section of the GNU Grep Manual), so that the output is buffered just one line at a time:

ssh "$@" | tee >(grep -e '.*\@.*\:.*\$.*' --color=never --line-buffered >> test.log)