How to write a script's output to both a rotating log file and to stdout?

Question

we run our microservices inside containers as K8s pods. To make sure that our app gets any signals sent to the container (in particular the SIGTERM on pod eviction), we usually use exec at the very end of our start script, so that the start script bash process (which has PID 1) effectively "turns into" the process that is our app. So our start scripts usually end with

exec <ourCommand>

For convenience, we want it's log output (both stdout and stderr) to be visible in the output of kubectl logs, but for post mortem analysis, we also want the output to end up in a file (yes, the file ends up somewhere where it survives a pod restart :-)). To avoid letting the file grow too much, it should be rotated. For the log rotation, we had made good experience with Apache's rotatelogs tool. It's "-e" option will "echo logs through to stdout" - giving us the logged output both in the file(s) and on stdout. The obvious approach was to pipe the scripts output, like this:

exec <ourCommand> | rotatelogs -e -n 10 stdout.log 10M

This seemed to work fine, but we then noticed that this effectively prevent the exec from behaving as expected and the start script would remain the root process, e.g., pstree -p would show this structure:

start.sh(1)-+-<ourCommand>(17)
        `-rotatelogs(18)

So our signal handling was broken, the app would not get the SIGTERM and not exit gracefully, instead the pod would be killed after the terminationGracePeriod was up.

After a lot of trial and error we had arrived at this solution using process substitution: exec <ourCommand> &> >( rotatelogs -e -n 10 stdout.log 10M)

The result was the desired process structure and again working signal handling, pstree -p would now show this structure:

<ourCommand>(1)---start.sh(17)---rotatelogs(18)

However, we then repeatedly noticed situations where a pod would crash, but sometimes there was no error message visible in kubectl logs (but it was visible in the log file, but no one looked there, expecting it to have the same content as kubectl logs, so "why bother"). Funny enough, this happened much more often in production environments (EKS and AKS clusters), and not so reliably when trying to reproduce the issue in a local environment (minikube).

Our best guess was that rotatelogs would not always flush its output buffer, so in particular the last line output by the script (which usually was the helpful error message...) might end up missing. Since rotatelogs didn't offer a setting that would force-flush every line, the idea was now to use this approach (let's call it "double process substitution"):

exec <ourCommand> &> >(tee >(rotatelogs -n 10 stdout.log 10M ))

The idea is to let tee to the "stream splitting", and since it does not have the flushing problem that rotatelogs' -e has, this worked fine - the "famous last words" of a crashing app would show up reliably in the log file and in kubectl logs.

Then someone had the glorious idea to add timestamps to all log lines by filtering through ts:

exec <ourCommand> &> >(ts | tee >(rotatelogs -n 10 stdout.log 10M ))

This again led to the "famous last words" often not showing up in kubectl logs. The process structure now looks like this:

<ourCommand>(1)---start.sh(17)-+-tee(19)---start.sh(20)---rotatelogs(21)
                               `-ts(18)

Yes, we did try "triple process substitution" :-D, but that didn't fix it. Only removing ts would.

Can anyone with more in-depth understanding of bash try to explain what is happening here (and ideally come up with a solution)?

THX

P

Answer 1

ts expects to receive a full line before adding timestamp and printing it. So if "last words" of your process do not end with \n - they can be lost.

How to fix it? Write your own ts, it could be something like this:

#!/bin/perl
$foundLF = 1;

while($ch=getc) {
    if ($foundLF == 1) {
        $datestring = gmtime();
        print "$datestring ";
        $foundLF = 0;
    }

    print $ch;

    $foundLF = 1 if (ord($ch) == 10);
}

The ts is already written in perl and you can use it for reference.

And you can even get rid of tee and rotatelog if you include that functionality into your own version of ts. It is very easy to do in perl.