Log redirection happens to rotated log instead of new log getting created

Question

Objective

So I have written a script that logs and rotates logs if it reaches certain size. I wish to capture all the errors and output by other commands also instead of the ones that I deliberately echo into the log.

The way I have achieved this is by redirecting STDIN and STDOUT to tee in a process substitution and have written a small function that makes use of savelog to rotate logs.

#!/bin/bash

LOGFILE="/var/log/ps.log"
exec > >(tee "$LOGFILE") 2>&1

LOGPATH="/var/log"
MAX_LOGFILE_SIZE=5
rotateLog() {
        currentsize=$(du -k $LOGFILE | cut -f1)
        if [ $currentsize -ge $MAX_LOGFILE_SIZE ]; then
                savelog -dn $LOGFILE &>/dev/null
        fi
}

while :; do
    echo "A computer program can easily produce gibberish - especially if it has been provided with garbage beforehand. This program does something a little different. It takes a block of text as input and works out the proportion of characters within the text according to a chosen order. For example, an order of 2 means the program looks at pairs of letters, an order of 3 means triplets of letters and so on. The software can regurgitate random text that is controlled by the proportion of characters. The results can be quite surprising."

    rotateLog

    sleep 5
done

Problem

The problem is that even after the log ps.log gets rotated to ps.log.20180829131658, all the logs are still written to ps.log.20180829131658 and following error is thrown:

du: cannot access '/var/log/ps.log': No such file or directory ./ps.sh: line 12: [: -ge: unary operator expected

Leading to no further rotation of logs!!!

Assumption

I was assuming that once ps.log gets rotated to ps.log.20180829131658, a new log file ps.log will get created. But that definitely isn't the case since exec is executed only once (Can anyone please explain what exactly happens here?) i.e., at the beginning of the script.

Observation

What also I have observed that a new file descriptor is created for >(tee "$LOGFILE") that points to /var/log/p.log which gets reassigned to p.log.20180829131658! This is what clearly resulting in logs still being written to p.log.20180829131658. Can anyone please explain this behaviour?

root@b537ccc2c1ab:/var/log# ls -lrt
-rw-r--r-- 1 root root   7248 Aug 29 13:16 ps.log

root@b537ccc2c1ab:/var/log# ls -lrt /proc/*/fd
/proc/8979/fd:
total 0
l-wx------ 1 root root 64 Aug 29 13:16 3 -> /var/log/ps.log
lrwx------ 1 root root 64 Aug 29 13:16 2 -> /dev/pts/17
lrwx------ 1 root root 64 Aug 29 13:16 1 -> /dev/pts/17
lr-x------ 1 root root 64 Aug 29 13:16 0 -> pipe:[3889791]


root@b537ccc2c1ab:/var/log# ls -lrt
-rw-r--r-- 1 root root  11098 Aug 29 13:17 ps.log.20180829131658

root@b537ccc2c1ab:/var/log# ls -lrt /proc/*/fd
/proc/8979/fd:
total 0
l-wx------ 1 root root 64 Aug 29 13:16 3 -> /var/log/ps.log.20180829131658
lrwx------ 1 root root 64 Aug 29 13:16 2 -> /dev/pts/17
lrwx------ 1 root root 64 Aug 29 13:16 1 -> /dev/pts/17
lr-x------ 1 root root 64 Aug 29 13:16 0 -> pipe:[3889791]

How can achieve my objective with this logging and log rotation scheme? In particular how can my script write to newer log files besides log rotation while capturing errors and outputs of all other commands in my script alongside?

Answer 1

Once a process opens a file, you can you all sorts of things to that file such as renaming it, truncating it, even deleting it but the process will still have that file opened. A common mistake is when a logfile has used up all diskspace, one deletes the file in an attempt to free up space. However the process writing to the logfile has it still opened, so the space is not freed. Only when the process closes the file will the blocks allocated to the file be freed. (The workaround here is to truncate the file, i.e. > logfile.)

In your case you've renamed the file, but the process writing to it does not know or care about that.

The logcheck utility has an option copytruncate for such situations: it copies the logfile to the rotated name, and then truncates the original. You can do the same thing:

rotateLog() {
    currentsize=$(du -k $LOGFILE | cut -f1)
    if [ $currentsize -ge $MAX_LOGFILE_SIZE ]; then
            ROTATEDLOG=$LOGFILE.$(date +%Y%m%d%H%M%S)
            cp -p $LOGFILE $ROTATEDLOG && true > $LOGFILE
    fi
}

A better alternative would be to modify the process to understand e.g. the signal SIGHUP to close and reopen the logfile. See the shell trap command for handling this.

Answer 2

Based on an alternative solution suggested by @wurtel, I got it working like so,

#!/bin/bash

LOGFILE="/root/logr/simple.log"

function sighuphandler() {
    exec > >(tee "$LOGFILE") 2>&1
}

trap sighuphandler SIGHUP

LOGPATH="/root/logr"
MAX_LOGFILE_SIZE=5
rotateLog() {
    currentsize=$(du -k $LOGFILE | cut -f1)
    if [ $currentsize -ge $MAX_LOGFILE_SIZE ]; then
            savelog -dn $LOGFILE &>/dev/null
            kill -s SIGHUP $$
    fi
}

sighuphandler
while :; do
    echo "[`date "+%Y-%m-%d %H:%M:%S"`] [INFO] - A computer program can easily produce gibberish - especially if it has been provided with garbage beforehand. This program does something a little different. It takes a block of text as input and works out the proportion of characters within the text according to a chosen order. For example, an order of 2 means the program looks at pairs of letters, an order of 3 means triplets of letters and so on. The software can regurgitate random text that is controlled by the proportion of characters. The results can be quite surprising."

    ls +

    rotateLog

    sleep 5
done