Bug 1763746

An alternate reproducer is to have logrotate use the "copytruncate" option for the log file.
In such case, because the inode never changes, logs are lost upon rotation (rsyslog doesn't detect the file content changed at all).

Reproducer:

1. Create many logs (1000)

  # for i in $(seq 1 1000); do curl http://localhost/step1 >/dev/null 2>&1; done

2. Rotate

  # stat -c %i /var/opt/rh/rh-nginx18/log/nginx/access.log; logrotate -f /etc/logrotate.d/rh-nginx18-nginx; stat -c %i /var/opt/rh/rh-nginx18/log/nginx/access.log
  <INODE>
  <INODE>

  (Same inodes above due to using "copytruncate")

3. Create some logs

  # curl http://localhost/step3 >/dev/null 2>&1

--> isn't read my imfile due to offset being large (rsyslog didn't detect the rotation at all).

I think this bz is related to https://bugzilla.redhat.com/show_bug.cgi?id=1739558 - note that description says "rsyslog underperforming compared to fluentd" - that is misleading - it is really that rsyslog is dropping logs due to cri-o/kubelet log rotation.

Also - have you tried to use the reopenontruncate setting: https://www.rsyslog.com/doc/v8-stable/configuration/modules/imfile.html#reopenontruncate ?  Or have tried to use a later version of rsyslog to see if that fixes the problem?

My comment #2 is misleading, this is another scenario of when the issue happens, but for other reasons (not using "reopnontruncate").

In the description logrotate doesn't truncate the log file, it creates a new inode.
The issue is with the older state files which do not get deleted, causing the issue when some inode was already used for the log file some time ago (typically I see this reuse after one or 2 rotations).

All this has been fixed upstream by the proposed fix + some recent fixes.

I'm proposing the following workaround, which consists in deleting rsyslog state files that will be used for the current logs after rotation:

/etc/logrotate.d/rh-nginx18-nginx:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
/var/opt/rh/rh-nginx18/log/nginx/*log {
    create 0644 nginx nginx
    daily
    rotate 10
    missingok
    notifempty
    compress
    sharedscripts
    postrotate
        for inode in $(stat -c %i $1); do
            /bin/rm /var/lib/rsyslog/imfile-state:$inode 2>/dev/null || true
        done
        /bin/kill -USR1 `cat /var/opt/rh/rh-nginx18/run/nginx/nginx.pid 2>/dev/null` 2>/dev/null || true
    endscript
}
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

The modification is in "postrotate", the first 3 lines.

In theory, this should work well because at the "postrotate" step here, the new logs have been created by logrotate (through "create" statement) but nginx doesn't use them yet since it didn't receive the USR1 signal, hence rsyslog is still processing the older file.

I'm still waiting for my customer to confirm it works, I will then create a KCS with this.

(In reply to Renaud Métrich from comment #5)
> My comment #2 is misleading, this is another scenario of when the issue
> happens, but for other reasons (not using "reopnontruncate").
> 
> In the description logrotate doesn't truncate the log file, it creates a new
> inode.
> The issue is with the older state files which do not get deleted, causing
> the issue when some inode was already used for the log file some time ago
> (typically I see this reuse after one or 2 rotations).
> 
> All this has been fixed upstream by the proposed fix + some recent fixes.

So if we rebase rsyslog in rhel 8.2 to the latest upstream, we can solve this issue for rhel8?

> 
> I'm proposing the following workaround, which consists in deleting rsyslog
> state files that will be used for the current logs after rotation:
> 
> /etc/logrotate.d/rh-nginx18-nginx:
> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<
> --------
> /var/opt/rh/rh-nginx18/log/nginx/*log {
>     create 0644 nginx nginx
>     daily
>     rotate 10
>     missingok
>     notifempty
>     compress
>     sharedscripts
>     postrotate
>         for inode in $(stat -c %i $1); do
>             /bin/rm /var/lib/rsyslog/imfile-state:$inode 2>/dev/null || true
>         done
>         /bin/kill -USR1 `cat /var/opt/rh/rh-nginx18/run/nginx/nginx.pid
> 2>/dev/null` 2>/dev/null || true
>     endscript
> }
> -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<
> --------
> 
> The modification is in "postrotate", the first 3 lines.
> 
> In theory, this should work well because at the "postrotate" step here, the
> new logs have been created by logrotate (through "create" statement) but
> nginx doesn't use them yet since it didn't receive the USR1 signal, hence
> rsyslog is still processing the older file.
> 
> I'm still waiting for my customer to confirm it works, I will then create a
> KCS with this.

Ok, but note that if the customer is using imfile with startmsg.regex or endmsg.regex, there is a chance that the log will end with a partial line, which will be saved in the imfile-state:$inode file.  The timing has to be just right, but if you restart rsyslog, it will lose the copy of the partial line in memory, and will not be able to reconstruct the partial line from the information saved in the imfile-state:$inode file.

(In reply to Rich Megginson from comment #6)
> So if we rebase rsyslog in rhel 8.2 to the latest upstream, we can solve
> this issue for rhel8?
> 

It looks like it works with very latest from Upstream (tried with 8.1911.0.master and didn't reproduce).

> > 
> > I'm proposing the following workaround, which consists in deleting rsyslog
> > state files that will be used for the current logs after rotation:
> > 
> > /etc/logrotate.d/rh-nginx18-nginx:
> > -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<
> > --------
> > /var/opt/rh/rh-nginx18/log/nginx/*log {
> >     create 0644 nginx nginx
> >     daily
> >     rotate 10
> >     missingok
> >     notifempty
> >     compress
> >     sharedscripts
> >     postrotate
> >         for inode in $(stat -c %i $1); do
> >             /bin/rm /var/lib/rsyslog/imfile-state:$inode 2>/dev/null || true
> >         done
> >         /bin/kill -USR1 `cat /var/opt/rh/rh-nginx18/run/nginx/nginx.pid
> > 2>/dev/null` 2>/dev/null || true
> >     endscript
> > }
> > -------- 8< ---------------- 8< ---------------- 8< ---------------- 8<
> > --------
> > 
> > The modification is in "postrotate", the first 3 lines.
> > 
> > In theory, this should work well because at the "postrotate" step here, the
> > new logs have been created by logrotate (through "create" statement) but
> > nginx doesn't use them yet since it didn't receive the USR1 signal, hence
> > rsyslog is still processing the older file.
> > 
> > I'm still waiting for my customer to confirm it works, I will then create a
> > KCS with this.
> 
> Ok, but note that if the customer is using imfile with startmsg.regex or
> endmsg.regex, there is a chance that the log will end with a partial line,
> which will be saved in the imfile-state:$inode file.  The timing has to be
> just right, but if you restart rsyslog, it will lose the copy of the partial
> line in memory, and will not be able to reconstruct the partial line from
> the information saved in the imfile-state:$inode file.

I understand it's not optimal.

*** Bug 1762035 has been marked as a duplicate of this bug. ***

Note that workaround in Comment #5 may not be sufficient. It has been reported that this creates an AVC (logrotate is not authorized to delete the old state files).
Unfortunately I didn't find the time to confirm myself.

I can confirm some additional SELinux rules are needed to be able to use the workaround:

logrotate_rsyslog_state_files.te:
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
module logrotate_rsyslog_state_files 1.0;

require {
	type syslogd_var_lib_t;
	type logrotate_t;
	class file { getattr unlink };
	class dir { remove_name write };
}

#============= logrotate_t ==============
allow logrotate_t syslogd_var_lib_t:dir { remove_name write };
allow logrotate_t syslogd_var_lib_t:file { getattr unlink };
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

Compile and install the module:

-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------
# yum -y install selinux-policy-devel
# make -f /usr/share/selinux/devel/Makefile logrotate_rsyslog_state_files.pp
# semodule -i logrotate_rsyslog_state_files.pp
-------- 8< ---------------- 8< ---------------- 8< ---------------- 8< --------

adding relevant upstream PRs

*** Bug 1772672 has been marked as a duplicate of this bug. ***

What is taking so long?

The bug is now verified. It just waits for a release of rhel-7.8.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2020:1000