Bug 1297253 - After one log rotation, syslog logs won't rotate again and wrong logs are written to
After one log rotation, syslog logs won't rotate again and wrong logs are wri...
Status: CLOSED DUPLICATE of bug 1284173
Product: Fedora
Classification: Fedora
Component: rsyslog (Show other bugs)
23
x86_64 Linux
unspecified Severity medium
: ---
: ---
Assigned To: Tomas Heinrich
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2016-01-10 20:33 EST by Edward Kuns
Modified: 2016-09-20 00:53 EDT (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2016-02-15 10:16:27 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Edward Kuns 2016-01-10 20:33:40 EST
Description of problem:

After a Fedora 21 -> 23 upgrade, the first log rotation worked OK, it seemed, but I quickly realized that /var/log/messages was 0 length and was not getting any new log messages.  The same for /var/log/maillog and /var/log/secure.  Everything found in /etc/logrotate.d/syslog.

I let the system run this way for a week and realized that after more than a week none of the logs rolled.  So I restarted syslog (systemctl restart rsyslog), which sort of fixed the problem.  I expect I'll have to restart syslog every week.

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

rsyslog-8.10.0-1.fc23.x86_64

How reproducible:

I don't know yet.

Steps to Reproduce:
1. Boot
2. Wait for log rotation
3. Check

Actual results:

Logs stay in newly-rotated log file and log rotation never occurs again.

Expected results:

Logs moved to new /var/log/(filename) and old file, renamed, stops growing.

Additional info:

This is possibly similar to this Fedora 22 bug, but may or may not be the same issue.

https://bugzilla.redhat.com/show_bug.cgi?id=1224972

I notice:

# ls /var/run/*syslog*
/var/run/syslogd.pid

that the pid file is syslogd.pid not rsyslogd.pid.

Restarting syslog resulted in messages-20160103 stopped and messages being written to /var/log/messages.  However, it looks like the system tried to copy all logs since the system was booted into /var/log/messages, finally complaining:

Jan 10 19:13:24 hostname rsyslogd-2177: imjournal: begin to drop messages due to rate-limiting

maillog is the same.  The logs actually start with June 5 2099 -- I think my CMOS battery is dying or dead.  Shortly after boot I fixed the time to Jan 2nd.  It looks like when syslog was restarted it tried to copy the entirety of all logs since bootup back into the syslog-managed log files, before hitting the rate limit complaint and going back to normal.
Comment 1 Edward Kuns 2016-01-11 11:03:11 EST
The first night after I restarted syslog to force my logs to rotate, my logs rotated again and now again only messages-20160111 and maillog-20160111 and secure-20160111 and cron-20160111 are being written to and (as before) the files messages and maillog and secure and cron are 0 length.

Comment 3 of bug 1224972 says, "Just change /var/run/syslog.pid to /var/log/rsyslog.pid to fix the problem" but it doesn't say how to DO that.  (Note:  I assume they meant /var/run/rsyslog.pid and not /var/log ... I assume the complaint is the PID file being named syslog instead of rsyslog.)  I don't see anything in /etc/rsyslog.conf or /lib/systemd/system/rsyslog.service or /etc/sysconfig/rsyslog that refers to where the pid file is.

So I forced it by setting this line in /etc/sysconfig/rsyslog:

SYSLOGD_OPTIONS="-i /var/run/rsyslog.pid"

I don't know if this is the right way to do this or not.  I restarted rsyslog and again it tried to copy everything since bootup into the new /var/log/messages.  Just to check I restarted it again and it did so again.

But this did rename the pid file.

Why, when I restart rsyslog, does it try to copy the full logs since bootup into the new log files?
Comment 2 Edward Kuns 2016-01-11 11:11:03 EST
I notice that the other bug has the pid file named rsyslogd ... but the service is named rsyslog not rsyslogd.  If I do this:

kill -HUP $(cat /var/run/rsyslog.pid)

then I don't get all logs since bootup copied (again) to the various syslog-managed logs.

I see these issues here:

1) Log rotation occurs once and never again (without human intervention)
2) Logs after rotation are written to the old renamed file, and the newly created file remains zero length (without human intervention)
3) If I restart rsyslog with systemctl, it tries to copy all logs since booting into the newly created file -- until it hits the rate limit.

I'll let it run overnight and see what happens when log rotation next occurs to see if renaming the PID file to the service name makes any difference at all.
Comment 3 Tomas Heinrich 2016-01-12 11:40:37 EST
(In reply to Edward Kuns from comment #2)

Hello Edward,

> I notice that the other bug has the pid file named rsyslogd ... but the
> service is named rsyslog not rsyslogd.  If I do this:

The PID file is a red herring. It is not used during rotation.

> I see these issues here:
> 
> 1) Log rotation occurs once and never again (without human intervention)
> 2) Logs after rotation are written to the old renamed file, and the newly
> created file remains zero length (without human intervention)

Since f23, the rotation is done through systemctl:
/usr/bin/systemctl kill -s HUP rsyslog.service

The rsyslog.service is missing the correct SELinux label and that causes the rotation not to work properly.

Bug 1284173 is filed for this issue. I think this one should be closed as it's duplicate.

> 3) If I restart rsyslog with systemctl, it tries to copy all logs since
> booting into the newly created file -- until it hits the rate limit.

That shouldn't happen, but there might be changes in your system causing it.

Usually, this happens because of a missing or old "state file" for imjournal.
There should also be an option in /etc/rsyslog.conf preventing this behavior:
$IMJournalIgnorePreviousMessages on
Comment 4 Edward Kuns 2016-01-17 19:14:22 EST
Now that another week has passed, I restarted syslog the correct way (/usr/bin/systemctl kill -s HUP rsyslog.service) and it started the correct way and without copying a few hundred kB to the new logfile.  Thanks for letting me know about that.

I see that bug 1284173 is in the QA state at the moment.  Curiously, the sealert browser doesn't show me the AVC mentioned in that bug.  But I do see that AVC in my logs.

I've installed that test update with 

dnf --enablerepo=updates-testing update  selinux-policy

It'll take a week to hit my next log rolling event.  Assuming this resolves my issue, I'll close this bug as redundant to 1284173.
Comment 5 Edward Kuns 2016-01-25 08:54:32 EST
Well, there's good news and bad news.  With

selinux-policy-3.13.1-158.2.fc23.noarch

installed, my logs rolled as they should last night at 3:33, but now no logs are being written to at all:

# ll -tr /var/log/messages*
-rw-------. 1 root root  11804997 Dec 21 03:44 /var/log/messages-20151221
-rw-------. 1 root root  17995473 Dec 27 03:32 /var/log/messages-20151227
-rw-------. 1 root root 127968599 Jan 10 19:13 /var/log/messages-20160103
-rw-------. 1 root root   2059616 Jan 11 09:56 /var/log/messages-20160111
-rw-------. 1 root root    615865 Jan 17 03:28 /var/log/messages-20160117.gz
-rw-------. 1 root root    582428 Jan 25 03:33 /var/log/messages-20160125.gz
-rw-------. 1 root root         0 Jan 25 03:33 /var/log/messages

The same is true for the other logs maintained by syslogd.  To try to kickstart syslogd into logging, I tried running:

/usr/bin/systemctl kill -s HUP rsyslog.service

Once I ran that, logs started accumulating again.  I'm not sure precisely what to investigate to figure out why logs didn't go anywhere after log rolling.  

Also, this is really a new bug.  Should I resolve this one as redundant as discussed (since logs did roll when they were supposed to) and open a new one?
Comment 6 Edward Kuns 2016-01-31 16:29:12 EST
One week later, my logs rolled last night (I'm not sure why sometimes it's Sunday AM and sometimes it's Monday AM) and just like last time, nothing went to the new logs until I kicked syslogd to restart it.  So something is still wrong.
Comment 7 Tomas Heinrich 2016-02-01 11:39:05 EST
(In reply to Edward Kuns from comment #5)
> Well, there's good news and bad news.  With
> 
> selinux-policy-3.13.1-158.2.fc23.noarch

I think you need selinux-policy-3.13.1-158.3.fc23.noarch. It's still in testing AFAIK.

> installed, my logs rolled as they should last night at 3:33, but now no logs
> are being written to at all:

The renaming and file creation are done by logrotate. If rsyslog didn't reopen the file(s), it most likely hasn't been HUPed.

> The same is true for the other logs maintained by syslogd.  To try to
> kickstart syslogd into logging, I tried running:
> 
> /usr/bin/systemctl kill -s HUP rsyslog.service
> 
> Once I ran that, logs started accumulating again.

If the manual HUP helped, this really looks like the SELinux issue.

> Also, this is really a new bug.  Should I resolve this one as redundant as
> discussed (since logs did roll when they were supposed to) and open a new
> one?

Let's try whether the new package version works. Maybe there are some other permissions that are still missing.
Comment 8 Edward Kuns 2016-02-09 10:03:23 EST
I've applied selinux-policy-targeted-3.13.1-158.4.fc23.noarch from updates (the previous one I applied, .2, was from testing).  So far, a manual HUP via systemctl has always helped.  At first, rotation occurred once and not again.  With the .2 update, rotation happened but nothing went to the new log.  With the .4 update I'll have to wait until rotation occurs again.  I'll report back success/failure.  Thanks.
Comment 9 Edward Kuns 2016-02-15 10:16:27 EST
My logs rolled yesterday and everything was working properly this time around.  Looks like the latest policy fixed it fully.  Thanks for keeping on top of this and letting me know about the other defects.

Resolving as a duplicate.

*** This bug has been marked as a duplicate of bug 1284173 ***

Note You need to log in before you can comment on or make changes to this bug.