Hide Forgot
Ok, this one is truly bizarre. I have this script that, amongst other things, forces an auditd rotate. I'm running SELinux with the "unconfined" module disabled and users locked down. The script works fine when run with sudo (which sets my role and type to unconfined, from staff), and (here's the weird part) it runs fine from cron IFF dontaudit is set to off. If dontaudit is on (my normal state) the rotate command, apparently, gets completely ignored. Here's the script: - ----------------------- #!/bin/bash export PATH='/bin:/usr/bin:/sbin:/usr/sbin:/usr/local/bin:/usr/local/sbin' echo -e "\n\n********************************************* Rotating Audit Logs\n\n" /sbin/service auditd rotate ## 2>&1 | grep -v '^ *Rotating logs: .*OK '; /sbin/service auditd restart ## 2>&1 | grep -v '^ *Restarting auditd .via systemctl.: .*OK ' # Delete old logs ls -rt /var/log/audit/* | head -n -10 | xargs rm echo -e "\n\n********************************************* Special Modules\n\n" semodule -l | grep '^my' | grep -Pv '^mysql\s' echo -e "\n\n********************************************* AVCs\n\n" grep -P '(AVC|SELINUX)' /var/log/audit/audit.log.1 | ausearch -i - -------------- Here's a log between two successful cron runs; dontaudit was turned off sometime in the middle here, but that seemed to still be OK: http://users.digitalkingdom.org/~rlpowell/media/public/audit.log.1.txt And here's the log after that, in which the script was run every minute but the rotate command was totally ignored:http://users.digitalkingdom.org/~rlpowell/media/public/audit.log.txt I'm totally mystified. -Robin
Oh yeah: note that this is *not* the log file secretly respecting the max_log_file parameter, because that's set to 5 and: -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 633067415 Sep 10 04:04 audit.log.9 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 140102879 Sep 12 04:04 audit.log.8 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 66728930 Sep 13 04:04 audit.log.7 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 766666684 Oct 2 10:09 audit.log.6 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 60768 Oct 2 10:09 audit.log.5 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 1709913 Oct 2 10:19 audit.log.4 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 126963 Oct 2 10:20 audit.log.3 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 761251 Oct 2 10:21 audit.log.2 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 440416 Oct 2 10:23 audit.log.1 -rw-------. 1 system_u:object_r:auditd_log_t:s0 root root 396468 Oct 2 10:45 audit.log -Robin
From IRC #selinux: 02-19:47 < rlpowell> < grift> dontaudit doesnt have any affect on policy enforcement < grift> so it doesnt make sense that someting would without dontaudit rules but not with dontaudit rules -- Ofcourse it doesn't make sense; that was rather my point. 02-19:47 < rlpowell> 02-10:57 < SwifT> perhaps the auditd init script checks the audit log, sees no new entries (since dontaudit is turned on) and thus doesn't do anything? -- No; I'm auditing constantly, you can see that in the second example. 02-19:47 < rlpowell> Every exec of anything causes an audit. Further: 02-10:58 < grift> i was just about to ask whether it does work in permissive mode 02-10:58 < grift> e.g. whether this is really a selinux issue 02-10:58 < grift> audit is very protective of its log files It's entirely possible that this isn't an selinux issue, which is why I posted it to audit rather than selinux. :) Hmmm.... Running it for longer, it looks like it's just random: sometimes it works, and sometimes it doesn't. It seems to work somewhat more often in permissive mode, but only somewhat. About one time in four, is my current guess. So yeah, probably not SELinux. Here's what happened when I left the cron running once a minute for a long time (the times indicating which ones worked). Looks like it was closer to 2 out of 3 for this time period, but I've got other hosts where this cron has failed 5 or more days in a row, so something weird and complicated is going on. -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 50610 Oct 2 20:09 audit.log.29 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 33979 Oct 2 20:10 audit.log.28 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 32339 Oct 2 20:11 audit.log.27 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 35828 Oct 2 20:12 audit.log.26 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 30360 Oct 2 20:13 audit.log.25 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 282341 Oct 2 20:14 audit.log.24 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 145053 Oct 2 20:15 audit.log.23 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 30716 Oct 2 20:16 audit.log.22 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 74572 Oct 2 20:19 audit.log.21 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 49311 Oct 2 20:20 audit.log.20 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 40788 Oct 2 20:21 audit.log.19 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 42249 Oct 2 20:22 audit.log.18 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 50752 Oct 2 20:23 audit.log.17 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 76343 Oct 2 20:25 audit.log.16 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 48310 Oct 2 20:26 audit.log.15 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 47426 Oct 2 20:27 audit.log.14 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 67739 Oct 2 20:29 audit.log.13 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 95536 Oct 2 20:31 audit.log.12 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 26072 Oct 2 20:32 audit.log.11 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 65923 Oct 2 20:34 audit.log.10 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 34016 Oct 2 20:35 audit.log.9 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 161292 Oct 2 20:36 audit.log.8 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 31072 Oct 2 20:37 audit.log.7 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 39826 Oct 2 20:38 audit.log.6 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 63944 Oct 2 20:40 audit.log.5 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 45203 Oct 2 20:41 audit.log.4 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 66025 Oct 2 20:43 audit.log.3 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 31815 Oct 2 20:44 audit.log.2 -r--------. 1 system_u:object_r:auditd_log_t:s0 root root 76274 Oct 2 20:45 audit.log.1 -rw-------. 1 system_u:object_r:auditd_log_t:s0 root root 59237 Oct 2 20:47 audit.log -Robin
Two, comments that are probably unrelated to the problem...why do you issue a restart after a rotate? You shouldn't have to do that. And why do you do: grep -P '(AVC|SELINUX)' /var/log/audit/audit.log.1 | ausearch -i instead of ausearch -if /var/log/audit/audit.log.1 -m AVC -m SELINUX_ERR -m USER_AVC -m USER_SELINUX_ERR -i Using ausearch without the grep will provide more complete records. Regarding the problem...what's in syslog related to this issue? The audit daemon records some information in syslog about what its doing.
(In reply to comment #3) > Two, comments that are probably unrelated to the problem...why do you issue a > restart after a rotate? You shouldn't have to do that. Paranoia? > And why do you do: > grep -P '(AVC|SELINUX)' /var/log/audit/audit.log.1 | ausearch -i > instead of > ausearch -if /var/log/audit/audit.log.1 -m AVC -m SELINUX_ERR -m USER_AVC -m > USER_SELINUX_ERR -i Because (1) I don't really get ausearch (2) I couldn't find a list of possible types anywhere to select from. If that's a complete list, I'll use that instead. > Using ausearch without the grep will provide more complete records. > > Regarding the problem...what's in syslog related to this issue? The audit > daemon records some information in syslog about what its doing. Here's what's in syslog for a failed overnight run; as far as I can tell it didn't see the rotate at all: Oct 2 04:04:02 vrici auditd[3282]: The audit daemon is exiting. Oct 2 04:04:02 vrici kernel: [98008.135309] audit_printk_skb: 57 callbacks suppressed Oct 2 04:04:02 vrici kernel: [98008.139129] type=1305 audit(1317553442.222:6362): audit_pid=0 old=3282 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1 Oct 2 04:04:02 vrici kernel: [98008.884920] type=1300 audit(1317553442.970:6363): arch=c000003e syscall=59 success=yes exit=0 a0=1da0880 a1=1d9ced0 a2=1da0cf0 a3=8 items=3 ppid=6264 pid=6270 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="rm" exe="/bin/rm" subj=system_u:system_r:initrc_t:s0 key="64bit_execs" Oct 2 04:04:03 vrici kernel: [98008.909942] type=1309 audit(1317553442.970:6363): argc=3 a0="rm" a1="-f" a2="/var/run/auditd.pid" Oct 2 04:04:03 vrici kernel: [98008.916981] type=1307 audit(1317553442.970:6363): cwd="/" Oct 2 04:04:03 vrici kernel: [98008.921286] type=1302 audit(1317553442.970:6363): item=0 name="/bin/rm" inode=268623 dev=fc:02 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:bin_t:s0 Oct 2 04:04:03 vrici kernel: [98008.939219] type=1302 audit(1317553442.970:6363): item=1 name=(null) inode=276820 dev=fc:02 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:ld_so_t:s0 Oct 2 04:04:03 vrici kernel: [98008.950681] type=1302 audit(1317553442.970:6363): item=2 name=(null) inode=276820 dev=fc:02 mode=0100755 ouid=0 ogid=0 rdev=00:00 obj=system_u:object_r:ld_so_t:s0 Oct 2 04:04:03 vrici kernel: [98008.972258] type=1300 audit(1317553443.056:6364): arch=c000003e syscall=59 success=yes exit=0 a0=1d4af60 a1=1d8a230 a2=1da0cf0 a3=8 items=3 ppid=6264 pid=6271 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="rm" exe="/bin/rm" subj=system_u:system_r:initrc_t:s0 key="64bit_execs" Oct 2 04:04:03 vrici kernel: [98008.996603] type=1309 audit(1317553443.056:6364): argc=3 a0="rm" a1="-f" a2="/var/lock/subsys/auditd" Oct 2 04:04:03 vrici kernel: [98009.004691] type=1307 audit(1317553443.056:6364): cwd="/" Oct 2 04:04:03 vrici auditd[6290]: Started dispatcher: /sbin/audispd pid: 6292 Oct 2 04:04:03 vrici audispd: audispd initialized with q_depth=120 and 1 active plugins Oct 2 04:04:03 vrici auditd[6290]: Init complete, auditd 2.1.2 listening for events (startup state enable) -Robin
This actually hasn't happened in the last 4 nights or so; it's rotating fine. I don't know what that means. I *did* drop the restart call, so perhaps the restart was somehow getting in before the rotate call was completed? -Robin
I am closing this bug report. I don't know of any reason why there would be problems rotating. No one else is reporting something similar. So, maybe it was a race of some kind where rotating was not finished when the restart was issued.