Bug 1763757

Summary: rsyslog doesn't read lines from imfile after rotation
Product: Red Hat Enterprise Linux 8 Reporter: Renaud Métrich <rmetrich>
Component: rsyslogAssignee: Jiří Vymazal <jvymazal>
Status: CLOSED ERRATA QA Contact: Dalibor Pospíšil <dapospis>
Severity: high Docs Contact:
Priority: high    
Version: ---CC: bperkins, dapospis, jvymazal, rmeggins
Target Milestone: rcKeywords: Triaged
Target Release: 8.0   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: rsyslog-8.1911.0-1.el8 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-04-28 16:01:06 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1740683    
Bug Blocks:    

Description Renaud Métrich 2019-10-21 14:25:23 UTC
This bug was initially created as a copy of Bug #1763746

I am copying this bug because: 

if also applies to RHEL8. To make the reproducer work, restart rsyslog some times.

Description of problem:

imfile module makes use of a state file /var/lib/rsyslog/imfile-state:<INODE> where <INODE> is the inode of the file being watched, e.g. "/var/opt/rh/rh-nginx18/log/nginx/access.log", e.g.

  # stat -c %i /var/opt/rh/rh-nginx18/log/nginx/access.log
  17625800

  There is now 1 state file: /var/lib/rsyslog/imfile-state:17625800

Upon rotating once, rsyslog doesn't delete the state file corresponding to the inode prior to rotation, e.g.

  # logrotate -f /etc/logrotate.d//etc/logrotate.d/rh-nginx18-nginx
  # stat -c %i /var/opt/rh/rh-nginx18/log/nginx/access.log
  17625781

  There are now 2 state files:
  - /var/lib/rsyslog/imfile-state:17625800
  - /var/lib/rsyslog/imfile-state:17625781

Upon rotating a second time, the "/var/opt/rh/rh-nginx18/log/nginx/access.log" file inode is prior to first rotation is "reused", causing logs to be lost until the offset saved in the /var/lib/rsyslog/imfile-state:<INODE> state file is reached, e.g.

  # logrotate -f /etc/logrotate.d//etc/logrotate.d/rh-nginx18-nginx
  # stat -c %i /var/opt/rh/rh-nginx18/log/nginx/access.log
  17625800


Version-Release number of selected component (if applicable):

rsyslog-8.37.0-9.el8.x86_64

How reproducible:

Always

Steps to Reproduce:
0. Install nginx, start it, make rsyslog watch the log file

  # yum -y install nginx
  # systemctl start nginx

  # cat > /etc/rsyslog.d/nginx.conf << EOF
\$InputFileName /var/log/nginx/access.log
\$InputFileTag nginx_tag
\$InputFileSeverity notice
\$InputFileFacility local6
\$InputFilePersistStateInterval 0
\$InputRunFileMonitor
EOF

  # systemctl restart rsyslog

1. Create some nginx logs with curl

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

2. Check for inode, rotate and check for inode again

  # 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
  XXX
  YYY

3. Create some nginx logs with curl again, after restarting rsyslog

  # systemctl restart rsyslog
  # for i in $(seq 1 100); do curl http://localhost/step3 >/dev/null 2>&1; done

  At this point, it may happen that logs are lost (check for "nginx_tag" in /var/log/messages).
  Otherwise

4. Check for inode, rotate and check for inode again

  # 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
  YYY
  XXX

  If inode XXX is not the one in step 2, create some more logs again and rotate again.

5. Create a new nginx log

  # curl http://localhost/step5 >/dev/null 2>&1
  # tail /var/log/nginx/access.log


Actual results:

The log is in /var/log/nginx/access.log, but never reaches /var/log/messages because offset in state file /var/lib/rsyslog/imfile-state:XXX is high

Expected results:

Log sent to /var/log/messages

Additional info:

I believe backporting ee77f27db0391126f7210dc3f49ab7f01037a700 and friends (the hash part in the state file) would help, but I'm not completely sure yet.

For sure, the issue is due to keeping the state file for old inode which then gets reused, but offset in the state file is not zero.

Comment 9 errata-xmlrpc 2020-04-28 16:01:06 UTC
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:1702