Bug 1284173 - logrotate not working for rsyslog
Summary: logrotate not working for rsyslog
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: selinux-policy
Version: 23
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: ---
Assignee: Lukas Vrabec
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1297253 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-11-21 13:28 UTC by Stefan Becker
Modified: 2016-02-15 15:16 UTC (History)
13 users (show)

Fixed In Version: selinux-policy-3.13.1-158.4.fc23.noarch
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-01-22 02:21:50 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Stefan Becker 2015-11-21 13:28:48 UTC
Description of problem:

/etc/logrotate.d/syslog shows

      postrotate
        /usr/bin/systemctl kill -s HUP rsyslog.service >/dev/null 2>&1 || true

but for some reason this command doesn't work from logrotate., i.e. rsyslog keeps on writing to the old logfile.

When I copy and paste the command to a root shell and execute, rsyslog takes the new logfile into use like it should,


Version-Release number of selected component (if applicable):
logrotate-3.9.1-2.fc23.x86_64
rsyslog-8.10.0-1.fc23.x86_64

How reproducible:
I have now encountered this already on 2 consecutive Monday mornings, i.e. after the weekly logrotate run.

Steps to Reproduce:
1. wait for the weekly logrotate run
2. check /var/log/messages
3.

Actual results:
rsyslog keeps on writing to the old logfile

Expected results:
rsyslog should write to the new /var/log/message


Additional info:
Maybe logrotate doesn't have the permissions to run "systemctl"?

Comment 1 Terje Røsten 2015-12-06 15:21:24 UTC
Does it help to do this change?

- /usr/bin/systemctl kill -s HUP rsyslog.service >/dev/null 2>&1 || true
+ /bin/kill -HUP $(cat /var/run/syslogd.pid 2> /dev/null) 2> /dev/null || true

Comment 2 Toby Ovod-Everett 2015-12-06 16:14:04 UTC
I can report that I am seeing the exact same behavior.  I'm running Fedora 23 Server.  I first noticed the issue because fail2ban stops working, and I was investigating the sudden spike it failed login attempts.

I found the following messages (there's one of these for every time logrotate runs) related to the inability of logrotate to run systemctl:

messages-20151130:Dec  6 03:34:01 vin audit: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  denied  { stop } for auid=n/a uid=0 gid=0 path="/usr/lib/systemd/system/rsyslog.service" cmdline="/usr/bin/systemctl kill -s HUP rsyslog.service" scontext=system_u:system_r:logrotate_t:s0-s0:c0.c1023 tcontext=system_u:object_r:systemd_unit_file_t:s0 tclass=service#012 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'

Obviously, I'm running with SELinux in Enforcing mode.  I'm not very good at reading SELinux messages, but it occurs to me that there are two possibilities for how SELinux restricts logrotate.  It could be blocking access to systemctl, but it could also be blocking sending the HUP signal (through any channel) to rsyslogd.  If it's the latter, then the suggested change won't help.

Comment 3 Tomas Heinrich 2015-12-07 12:23:53 UTC
Thanks for checking the AVCs. I wonder why I didn't catch this; probably also ran it from a root shell.

I think amending the SELinux policy would be the proper solution -> switching the component.

Comment 4 Miroslav Grepl 2015-12-07 12:58:05 UTC
The problem is we miss a default labeling for /usr/lib/systemd/system/rsyslog.service together with appropriate rules.

Comment 5 Tomas Heinrich 2015-12-07 17:49:46 UTC
Btw, the only releases affected are f23, f24.

Comment 6 Lukas Vrabec 2016-01-12 17:05:27 UTC
commit e4637c2bbfffa5ec05b80248e94fd127661ad4bc
Author: Lukas Vrabec <lvrabec>
Date:   Tue Jan 12 18:01:28 2016 +0100

    Allow logrotate to systemctl rsyslog service. BZ(1284173)

Comment 7 Fedora Update System 2016-01-14 13:15:59 UTC
selinux-policy-3.13.1-158.2.fc23 has been submitted as an update to Fedora 23. https://bodhi.fedoraproject.org/updates/FEDORA-2016-7cb7ac5cb9

Comment 8 Fedora Update System 2016-01-15 18:53:58 UTC
selinux-policy-3.13.1-158.2.fc23 has been pushed to the Fedora 23 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2016-7cb7ac5cb9

Comment 9 Stefan Becker 2016-01-18 03:13:20 UTC
Still doesn't work for me after updating to selinux-policy-targeted-3.13.1-158.2.fc23.noarch

type=USER_AVC msg=audit(1453080721.624:377): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  denied  { stop } for auid=n/a uid=0 gid=0 path="/usr/lib/systemd/system/rsyslog.service" cmdline="/usr/bin/systemctl kill -s HUP rsyslog.service" scontext=system_u:system_r:logrotate_t:s0-s0:c0.c1023 tcontext=system_u:object_r:systemd_unit_file_t:s0 tclass=service  exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'

# date --date=
Mon Jan 18 03:32:01 EET 2016
# ls -lht /var/log/messages*
-rw-r--r--. 1 root root    0 Jan 18 03:32 /var/log/messages
-rw-r--r--. 1 root root 3.2K Jan 17 22:09 /var/log/messages-20160118
...
# lsof /var/log/messages*
COMMAND   PID USER   FD   TYPE DEVICE SIZE/OFF   NODE NAME
rsyslogd 1037 root   65w   REG  253,1     3232 136085 /var/log/messages-20160118

Comment 10 Lukas Vrabec 2016-01-18 12:03:17 UTC
commit 7cc997acdfb2337b8cb46d30b2306be6d6999217
Author: Lukas Vrabec <lvrabec>
Date:   Mon Jan 18 13:01:19 2016 +0100

    Fix SELinux context for rsyslog unit file. BZ(1284173)


Fixed now, sorry for that.

Comment 11 Toby Ovod-Everett 2016-01-18 15:42:19 UTC
Now that syslog rolled log files this morning, I can confirm Stefan Becker's results.  

I have selinux-policy-3.13.1-158.2.fc23.noarch and selinux-policy-targeted-3.13.1-158.2.fc23.noarch installed, I even rebooted after the install, and this morning when syslog rolled the log files this morning the renamed one remained in use.

Lukas - when you say "Fixed now", does that mean it will be fixed in the next release of selinux-policy or that you have somehow released a new version of selinux-policy-3.13.1-158.2.fc23.noarch that we need to deploy?

Comment 12 Lukas Vrabec 2016-01-19 09:54:02 UTC
Toby, 
Fixes are in this version: http://koji.fedoraproject.org/koji/buildinfo?buildID=712094

Comment 13 Fedora Update System 2016-01-22 02:20:58 UTC
selinux-policy-3.13.1-158.2.fc23 has been pushed to the Fedora 23 stable repository. If problems still persist, please make note of it in this bug report.

Comment 14 Tomas Heinrich 2016-02-10 12:56:41 UTC
This bug was closed automatically by an update to selinux-policy-3.13.1-158.2.fc23, which didn't actually fix the issue, right?
Can somebody confirm this is fixed with the latest stable update?

There's .4 in the updates and .3 has been skipped, so the 'fixed in' field is probably wrong. Lukas, am I right?

Comment 15 Toby Ovod-Everett 2016-02-10 14:24:27 UTC
Unfortunately, my logs went through logrotate automatically at 3:22:03 on Feb 7.  At 6:58:53 on Feb 7, I ran dnf update and selinux-policy updated to .4.  At 7:00:40, I manually HUPed rsyslogd to get syslogd using the new messages file.

I'm not sure how to manually trigger logrotate in such a manner that the SELinux context would be sufficiently accurate to serve as a good test, so I'm waiting until Feb 14 to see logrotate run normally and I'll check to see if it properly rotates.  I always know when it doesn't rotate, because fail2ban stops working!

Log output:

messages-20160207:Feb  7 03:22:03 vin audit: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='avc:  denied  { stop } for auid=n/a uid=0 gid=0 path="/usr/lib/systemd/system/rsyslog.service" cmdline="/usr/bin/systemctl kill -s HUP rsyslog.service" scontext=system_u:system_r:logrotate_t:s0-s0:c0.c1023 tcontext=system_u:object_r:systemd_unit_file_t:s0 tclass=service#012 exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'

dnf.rpm.log:Feb 07 06:58:53 INFO Upgraded: selinux-policy-3.13.1-158.4.fc23.noarch

messages-20160207:Feb  7 07:00:40 vin rsyslogd: [origin software="rsyslogd" swVersion="8.10.0" x-pid="701" x-info="http://www.rsyslog.com"] rsyslogd was HUPed

Comment 16 Stefan Becker 2016-02-15 03:02:36 UTC
selinux-policy-3.13.1-158.4.fc23.noarch solves the problem for me. logrotate just went through the weekly cycle and rsyslog got huped:

-rw-r--r--. 1 root root 6.6K Feb 15 03:21 /var/log/messages-20160215
-rw-r--r--. 1 root root    0 Feb 15 03:21 /var/log/messages

Feb 15 03:21:01 XXXX rsyslogd: [origin software="rsyslogd" swVersion="8.10.0" x-pid="1052" x-info="http://www.rsyslog.com"] rsyslogd was HUPed

The next message should go to /var/log/messages.

Comment 17 Toby Ovod-Everett 2016-02-15 14:32:56 UTC
I can confirm as well that selinux-policy-3.13.1-158.4.fc23.noarch solves the problem for me:

vin:root 5:30am /var/log# tail -n 1 messages-20160214
Feb 14 03:47:02 vin rsyslogd: [origin software="rsyslogd" swVersion="8.10.0" x-pid="674" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
vin:root 5:30am /var/log# head -n 1 messages
Feb 14 03:48:02 vin audit: <message redacted>

Comment 18 Edward Kuns 2016-02-15 15:16:27 UTC
*** Bug 1297253 has been marked as a duplicate of this bug. ***


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