Bug 974132

Summary: journald duplicate message ID bug causes rsyslog to peg CPU at 100% and spam /var/log/messages until hard disk is full (and breaks journalctl)
Product: [Fedora] Fedora Reporter: Tom London <selinux>
Component: systemdAssignee: systemd-maint
Status: CLOSED CURRENTRELEASE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: urgent Docs Contact:
Priority: urgent    
Version: 19CC: aaron, amit.shah, awilliam, balay, bugs.michael, constantin_, diazbastian, drfudgeboy, harald, ignatenko, johannbg, lionghostshop, lnykryn, madko, mah.darade, malkodan, mathieu-acct, maxx, mikhail.v.gavrilov, msekleta, mteixeira, nonamedotc, notting, plautrba, rdieter, renault, Simon.Gerhards, systemd-maint, theinric, vpavlin, zbyszek
Target Milestone: ---Keywords: Reopened
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: systemd-204-7.fc20 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
: 975011 (view as bug list) Environment:
Last Closed: 2013-12-03 19:11:03 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:    
Bug Blocks: 975011    

Description Tom London 2013-06-13 13:39:50 UTC
Description of problem:
Updated to rsyslog-7.4.0-1.fc20.x86_64 this morning. Since the update, rsyslogd is pegged at 100% CPU and /var/log/messages appears to be "growing without bound":

 2810 root      20   0  530668  15280  14304 S 111.4  0.4  26:13.96 rsyslogd    

(26minutes and increasing)

Here are 10 second stats on /var/log/messages:

-rw-r--r--. 1 root root 792M Jun 13 06:34 /var/log/messages
-rw-r--r--. 1 root root 797M Jun 13 06:34 /var/log/messages
-rw-r--r--. 1 root root 803M Jun 13 06:34 /var/log/messages
-rw-r--r--. 1 root root 809M Jun 13 06:34 /var/log/messages
-rw-r--r--. 1 root root 815M Jun 13 06:35 /var/log/messages
-rw-r--r--. 1 root root 821M Jun 13 06:35 /var/log/messages

Previous version of rsyslog was:

Resolving Dependencies
--> Running transaction check
---> Package rsyslog.x86_64 0:7.3.10-1.fc20 will be updated
---> Package rsyslog.x86_64 0:7.4.0-1.fc20 will be an update
--> Finished Dependency Resolution

/var/log/messages appears now to be sorted with  most recent at the start of the file:

[root@tlondon log]# head messages
Jun  9 08:35:05 tlondon rsyslogd: [origin software="rsyslogd" swVersion="7.3.10" x-pid="430" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Jun  9 08:56:49 tlondon dbus-daemon[434]: dbus[434]: [system] Activating service name='org.fedoraproject.Setroubleshootd' (using servicehelper)
Jun  9 08:56:51 tlondon dbus[434]: [system] Activating service name='org.fedoraproject.Setroubleshootd' (using servicehelper)
Jun  9 08:57:03 tlondon dbus-daemon[434]: dbus[434]: [system] Successfully activated service 'org.fedoraproject.Setroubleshootd'
Jun  9 08:57:03 tlondon dbus[434]: [system] Successfully activated service 'org.fedoraproject.Setroubleshootd'
Jun  9 08:57:11 tlondon setroubleshoot: SELinux is preventing /usr/bin/rsync from setattr access on the sock_file var/lib/libvirt/qemu/capabilities.monitor.sock. For complete SELinux messages. run sealert -l 61735dc9-4f5e-46c5-9384-870d6775c7a9
Jun  9 09:16:04 tlondon systemd-logind[418]: Delay lock is active but inhibitor timeout is reached.
Jun  9 09:16:04 tlondon systemd-logind[418]: System is powering down.
Jun  9 09:16:04 tlondon colord: device removed: xrandr-Lenovo Group Limited
Jun  9 09:16:05 tlondon colord: device removed: xrandr-Hewlett Packard-HP L2208w-CNK80501FQ
[root@tlondon log]# 

(but today is not Jun 9).

Here is the tail:

[root@tlondon log]# tail messages
Mar 27 07:05:49 tlondon gnome-session[916]: WARNING: Could not parse desktop file /home/tbl/.config/autostart/gnome-user-share.desktop or it references a not found TryExec binary
Mar 25 07:19:45 tlondon NetworkManager[514]: <info>   hostname 'tlondon'
Mar 27 07:05:49 tlondon gnome-session[916]: WARNING: could not read /home/tbl/.config/autostart/gnome-user-share.desktop
Mar 25 07:19:45 tlondon NetworkManager[514]: <info>   nameserver '192.168.1.1'
Mar 27 07:05:49 tlondon gnome-session[916]: WARNING: Could not parse desktop file /home/tbl/.config/autostart/imsettings-start.desktop or it references a not found TryExec binary
Mar 25 07:19:45 tlondon NetworkManager[514]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Mar 27 07:05:49 tlondon gnome-session[916]: WARNING: could not read /home/tbl/.config/autostart/imsettings-start.desktop
Mar 25 07:19:45 tlondon dhclient[606]: bound to 192.168.1.88 -- renewal in 40818 seconds.
Mar 27 07:05:49 tlondon gnome-session[916]: WARNING: Could not parse desktop file /home/tbl/.config/autostart/gnome-at-session.desktop or it references a not found TryExec binary
Mar 25 07:19:45 tlondon NetworkManager[514]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Commit) started...
[root@tlondon log]# 


Since typing this message, /var/log/messages has grown to:

[tbl@tlondon ~]$ sudo ls -lh /var/log/messages
-rw-r--r--. 1 root root 939M Jun 13 06:38 /var/log/messages
[tbl@tlondon ~]$ 




Version-Release number of selected component (if applicable):
rsyslog-7.4.0-1.fc20.x86_64

How reproducible:


Steps to Reproduce:
1. 
2.
3.

Actual results:


Expected results:


Additional info:

Comment 1 Tom London 2013-06-13 13:48:33 UTC
Not sure it's helpful, but

[root@tlondon log]# systemctl status rsyslog.service
rsyslog.service - System Logging Service
   Loaded: loaded (/lib/systemd/system/rsyslog.service; enabled)
   Active: active (running) since Thu 2013-06-13 06:10:58 PDT; 36min ago
 Main PID: 2810 (rsyslogd)
   CGroup: name=systemd:/system/rsyslog.service
           └─2810 /sbin/rsyslogd -n

Jun 13 06:10:58 tlondon.localhost.org systemd[1]: Started System Logging Serv...
[root@tlondon log]#

Comment 2 Tomas Heinrich 2013-06-13 17:51:09 UTC
Hello Tom,

thanks for reporting this issue. Unfortunately, this is likely a bug in systemd and not in rsyslog, see this report:
http://lists.freedesktop.org/archives/systemd-devel/2013-June/011261.html

In a nutshell, bogus ids get generated for some message(s) and iterating through them gets stuck in a loop.

You can verify that this is your issue by checking for duplicate messages in the logs / journal. There should be a series of messages that repeats over and over again. Also, if you run journalctl, it should be stuck in a loop and never finish.

A workaround is to erase the (offending) journal files. A proper fix should come with the next systemd release (v205?).

If you can confirm this is really an issue with the journal, please switch the component to systemd.

Comment 3 Tom London 2013-06-13 18:08:38 UTC
Thanks for the quick response.

I had worked around this by downgrading to an earlier version.

I will attempt to follow your hints when I get home tonight.....

Comment 4 Tom London 2013-06-14 02:50:10 UTC
OK. Believe it is as you describe.

If I run 'journalctl --no-pager', it starts spewing at about 15 March and continues to about 27 March. It then "loops back" to 25 March whence it spews till 27 March where it loops back to 25 March, etc.

Reassigning to systemd.

Comment 5 Tom London 2013-06-14 03:02:35 UTC
I've managed to make 'journalctl --no-pager' stop looping and complete by "moving out of the way" the following files in /var/log/journal/6f397d582f6f6691f48a1fa74b338324

[root@tlondon 6f397d582f6f6691f48a1fa74b338324]# ls -l OLD
total 38196
-rw-r-----+ 1 root systemd-journal 16150528 Mar 27 06:16 system~
-rw-r-----+ 1 root systemd-journal 12296192 Mar 28 18:35 system~
-rw-r-----+ 1 root systemd-journal  6856704 Apr  5 06:01 system~
-rw-r-x---+ 1 root systemd-journal  3764224 Mar 25 06:07 user-1000~
[root@tlondon 6f397d582f6f6691f48a1fa74b338324]# 

I'll now attempt the update of rsyslog and see if that produces a finite sized /var/log/messages

Comment 6 Tom London 2013-06-14 03:17:13 UTC
Yeah. After updating to rsyslog-7.4.0-1.fc20.x86_64, rsyslog now completes.

Issue was with corrupted journal files....

Comment 7 Tomas Heinrich 2013-06-14 06:46:40 UTC
Thanks for taking the time to verify this. I expect this will hit more people - I'm already seeing some dupes.

Comment 8 Tomas Heinrich 2013-06-14 06:48:56 UTC
*** Bug 974335 has been marked as a duplicate of this bug. ***

Comment 9 Tomas Heinrich 2013-06-14 06:50:39 UTC
*** Bug 974332 has been marked as a duplicate of this bug. ***

Comment 10 Adam Williamson 2013-06-14 06:51:48 UTC
Even if the bug's in systemd, the effect on rsyslogd is rather catastrophic, and the update should be withdrawn until the systemd issue is fixed. (though the systemd issue renders journalctl kinda useless, which is a major issue in itself).

Comment 11 Adam Williamson 2013-06-14 07:09:06 UTC
I had to move five files on my desktop to finally get journalctl to stop looping, with dates right up to Thursday afternoon:

-rw-r-----+ 1 root systemd-journal  6811648 Apr 10 20:28 system~
-rw-r-----+ 1 root systemd-journal  5545984 Apr 11 09:22 system~
-rw-r-----+ 1 root systemd-journal  5881856 Apr 12 15:17 system~
-rw-r-----+ 1 root systemd-journal 48562176 Jun 13 16:47 system~
-rw-r-----+ 1 root systemd-journal  7389184 Jun 13 16:47 user-1001~

so it seems the bogus IDs have been getting generated all the way up to the present.

Comment 12 James Heather 2013-06-14 08:54:12 UTC
I'm getting this too.

I can also solve it by removing dud files from /var/log/journal. But what is triggering the appearance of these duds? Or, more to the point, how long before this will happen to me again?

Does this qualify as a blocker, by the way? I don't know the exact rules, but something that chews CPU on lots of people's machines is not something we want in F19 final.

Comment 13 Adam Williamson 2013-06-14 08:57:25 UTC
"I can also solve it by removing dud files from /var/log/journal. But what is triggering the appearance of these duds?"

The problem described and linked to in comment #2.

"Or, more to the point, how long before this will happen to me again?"

Probably not very long at all, until we get a systemd build with the fix for the bug from comment #2. I'll bug Lennart about it in the morning.

"Does this qualify as a blocker, by the way? I don't know the exact rules"

It would if the rsyslog update made it out of updates-testing, but I don't expect that to happen; I think the maintainer is going to un-push it until we get a fixed systemd.

Comment 14 Constantin Dunayev 2013-06-14 11:22:19 UTC
*** Bug 974495 has been marked as a duplicate of this bug. ***

Comment 15 Tomas Heinrich 2013-06-14 13:01:18 UTC
*** Bug 974496 has been marked as a duplicate of this bug. ***

Comment 16 Harald Hoyer 2013-06-14 13:23:16 UTC
systemd-204-7.fc20

Comment 17 Satish Balay 2013-06-14 15:55:54 UTC
Not sure how systemd-204-7 is supposed to have  fixed this issue - but if I reinstall rsyslog-7.4.0-1.fc19.x86_64 after systemd-204-7 [even tried systemd-204-8.fc19 from koji] - I still get the spamming of /var/log/messages

Comment 18 Zbigniew Jędrzejewski-Szmek 2013-06-14 15:57:02 UTC
What about systemd-204-8?

Comment 19 Satish Balay 2013-06-14 16:16:20 UTC
systemd-204-8 also didn't help.

I've now deleted /var/log/journal/*/*~ to check bz 956306 - so I guess I can't reproduce this issue anymore
[In retrospect - I should have moved them out - and not deleted them :( ]

Comment 20 Adam Williamson 2013-06-14 17:07:07 UTC
The 204-7 systemd update would prevent the generation of any further duplicate message IDs, but it does nothing to deal with systems which already have some. The 204-8 update tries to do something about this case:

"- fix, which helps to sucessfully browse journals with duplicated seqnums"

Satish's report suggests it doesn't entirely work, but I'll try and take a look and see how it behaves here.

Comment 21 Adam Williamson 2013-06-14 17:08:46 UTC
We need to re-open this *at least* until the fixes are pushed to F19 stable, and check that 204-8 really handles all existing cases as well as is possible.

Comment 22 Adam Williamson 2013-06-14 17:15:26 UTC
The extra patch added in -8 was http://lists.freedesktop.org/archives/systemd-devel/2013-June/011257.html : "journal: remember last direction of search and keep offset cache"

Comment 23 Adam Williamson 2013-06-14 17:39:41 UTC
Unfortunately I did too good a job of cleaning up my log files - I tried to keep enough to reproduce the bug on demand, but evidently I didn't :( Can anyone else who can still reproduce the 'journalctl --no-pager' loop please test if systemd 204-8 results in 'journalctl --no-pager' completing and rsyslog 7.4.0 working *without* any manual cleaning of journal files? Thanks!

Comment 24 Aaron Sowry 2013-06-14 18:11:47 UTC
(In reply to Adam Williamson from comment #23)
> Unfortunately I did too good a job of cleaning up my log files - I tried to
> keep enough to reproduce the bug on demand, but evidently I didn't :( Can
> anyone else who can still reproduce the 'journalctl --no-pager' loop please
> test if systemd 204-8 results in 'journalctl --no-pager' completing and
> rsyslog 7.4.0 working *without* any manual cleaning of journal files? Thanks!

I got rid of my broken log files earlier to try and solve things temporarily; luckily [sic] the newly created ones were also broken.

Confirming that systemd 204-8 from [1] fixes both the journalctl loop (although the log entries are out of order), and makes rsyslogd (rsyslog-7.4.0-1) happy too.

[1] http://koji.fedoraproject.org/koji/buildinfo?buildID=426689

Comment 25 Adam Williamson 2013-06-14 18:17:10 UTC
Well, that's encouraging news, so we now have one report either way (Aaron +1, Satish -1). Anyone else able to chime in?

Comment 26 Mikhail 2013-06-14 18:40:01 UTC
$ rpm -q systemd
systemd-204-8.fc19.i686

this problem still not fixed :(

Comment 27 Adam Williamson 2013-06-14 19:00:18 UTC
Mikhail: when you say 'this problem still not fixed', what do you mean exactly? Did you try deleting /var/log/messages and restarting rsyslog.service? Does 'journalctl --no-pager' loop for you?

Comment 28 Mikhail 2013-06-14 20:27:09 UTC
It means:

1. I update systemd with follow command: "yum install ./systemd-204-8.fc19.i686.rpm ./systemd-libs-204-8.fc19.i686.rpm ./systemd-python-204-8.fc19.i686.rpm ./systemd-sysv-204-8.fc19.i686.rpm ./libgudev1-204-8.fc19.i686.rpm"

2. stop rsyslog with  follow command "systemctl stop rsyslog.service"

3. remove all /var/log/messages files

4. start rsyslog again with follow command "systemctl start rsyslog.service"


And after it I have again 100% CPU usage with thread name "in:imjournal"

Comment 29 Adam Williamson 2013-06-14 20:28:08 UTC
But is your /var/log/messages still being filled up? And does 'journalctl --no-pager' still loop?

Comment 30 Mikhail 2013-06-15 06:02:52 UTC
Now /var/log/messages fills with next messages:

Jun 15 11:58:14 desktop upowerd: (upowerd:1027): UPower-Linux-WARNING **: no voltage values, using 10V as approximation
Jun 15 11:58:17 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:21 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:25 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:29 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:33 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:37 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:41 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:44 desktop upowerd: (upowerd:1027): UPower-Linux-WARNING **: no voltage values, using 10V as approximation
Jun 15 11:58:45 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:49 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:53 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:58:57 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:59:01 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98
Jun 15 11:59:05 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98still
Jun 15 11:59:09 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98


But problem with 100% CPU loading is gone after I doing "# restorecon -Rv /"

Comment 31 Michael Schwendt 2013-06-15 06:49:57 UTC
systemd-204-8.fc19 doesn't fix the rsyslog issue for me.

I've downgraded rsyslog, rebooted, then reapplied the rsyslog test-update, and in /var/log/messages I can observe lots of messages from May 10th onwards being added again. Another "yum downgrade rsyslog" (to rsyslog-7.2.6-1.fc19.x86_64) stops that.

Comment 32 Michael Schwendt 2013-06-15 07:05:59 UTC
More precisely, the spamming stops after some time. A large number of old messages get appended to /var/log/messages, enough to occupy the CPU and make the fans spin up, but when it reaches "today", it stops.

Comment 33 Adam Williamson 2013-06-15 07:16:55 UTC
Right, so actually, it's fixed.

I think this other bug is confusing matters:

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

it causes you to have WAY more messages in your logs than you'd usually expect to, because that AVC will occur about once every three seconds. But as long as neither journalctl nor rsyslog is actually *looping* over a set of messages and never completing, this bug is fixed.

Mikhail, this is what you're seeing too.

Comment 34 Adam Williamson 2013-06-15 07:18:43 UTC
oh, the difference between 7.2.6 and 7.4.0 is expected because they behave fundamentally differently. 7.4.0 essentially turns the default configuration of rsyslog into being a simple ascii backend for journald: it simply outputs every single journal message to /var/log/messages . When it *first* runs, this means it will read all existing journal entries into /var/log/messages - and if you hit the selinux bug you have thousands or hundreds of thousands, hence the initial slowness.

7.2.6 was still acting as an independent system logging daemon.

Comment 35 Mikhail 2013-06-15 07:42:59 UTC
But 'journalctl --no-pager' still loop follow message:

июн 15 12:36:41 desktop setroubleshoot[532]: dbus avc(node=desktop type=AVC msg=audit(1371278201.117:1925): avc:  denied  { read } for  pid=439 comm="accounts-daemon" name="log" dev="sda1" in...:s0 tclass=dir
июн 15 12:36:41 desktop setroubleshoot[532]: AuditRecordReceiver.feed() got node=desktop type=AVC msg=audit(1371278201.117:1925): avc:  denied  { read } for  pid=439 comm="accounts-daemon" na...:s0 tclass=dir
июн 15 12:36:41 desktop setroubleshoot[532]: AuditRecordReceiver.add_record_to_cache(): node=desktop type=AVC msg=audit(1371278201.117:1925): avc:  denied  { read } for  pid=439 comm="account...:s0 tclass=dir
июн 15 12:36:41 desktop setroubleshoot[532]: AuditRecordReceiver.feed() got node=desktop type=SYSCALL msg=audit(1371278201.117:1925): arch=40000003 syscall=292 success=no exit=-13 a0=8 a1=b8e...:s0 key=(null)
июн 15 12:36:41 desktop setroubleshoot[532]: AuditRecordReceiver.add_record_to_cache(): node=desktop type=SYSCALL msg=audit(1371278201.117:1925): arch=40000003 syscall=292 success=no exit=-13...:s0 key=(null)
июн 15 12:36:41 desktop setroubleshoot[532]: AuditRecordReceiver.feed() got node=desktop type=EOE msg=audit(1371278201.117:1925):
июн 15 12:36:41 desktop setroubleshoot[532]: AuditRecordReceiver.add_record_to_cache(): node=desktop type=EOE msg=audit(1371278201.117:1925):
июн 15 12:36:41 desktop setroubleshoot[532]: analyze_avc() avc=scontext=system_u:system_r:accountsd_t:s0 tcontext=system_u:object_r:var_log_t:s0 access=['read'] tclass=dir tpath=/var/log
июн 15 12:36:41 desktop setroubleshoot[532]: lookup_signature: found 1 matches with scores 1.00
июн 15 12:36:41 desktop setroubleshoot[532]: signature found in database
июн 15 12:36:41 desktop setroubleshoot[532]: sending alert to all clients
июн 15 12:36:41 desktop setroubleshoot[532]: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c...7-c73a985c03f5
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() names=['openvpn', 'allow_ftpd_use_nfs', 'catchall', 'wine', 'allow_anon_write', 'allow_execheap', 'allow_
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.openvpn previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.allow_ftpd_use_nfs previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.catchall previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.wine previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.allow_anon_write previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.allow_execheap previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.allow_ftpd_use_cifs previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.catchall_boolean previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.qemu_blk_image previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.restorecon previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.httpd_write_content previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.mozplugger previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.allow_execmod previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.automount_exec_config previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.selinuxpolicy previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.mozplugger_remove previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.cvs_data previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.connect_ports previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.sys_module previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.rsync_data previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.xen_image previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.mmap_zero previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.catchall_labels previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.mounton previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.allow_execstack previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.swapfile previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.sys_resource previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.kernel_modules previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.bind_ports previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.device previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.file previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.samba_share previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.dac_override previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.sshd_root previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.vbetool previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.public_content previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.setenforce previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.disable_ipv6 previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.leaks previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.filesystem_associate previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.httpd_can_sendmail previously imported
июн 15 12:36:41 desktop setroubleshoot[532]: load_plugins() plugins.qemu_file_image previously imported
июн 15 12:36:41 desktop python[532]: [120B blob data]
июн 15 12:36:45 desktop setroubleshoot[532]: dbus avc(node=desktop type=AVC msg=audit(1371278205.117:1926): avc:  denied  { read } for  pid=439 comm="accounts-daemon" name="log" dev="sda1" in...:s0 tclass=dir
июн 15 12:36:45 desktop setroubleshoot[532]: AuditRecordReceiver.feed() got node=desktop type=AVC msg=audit(1371278205.117:1926): avc:  denied  { read } for  pid=439 comm="accounts-daemon" na...:s0 tclass=dir
июн 15 12:36:45 desktop setroubleshoot[532]: AuditRecordReceiver.add_record_to_cache(): node=desktop type=AVC msg=audit(1371278205.117:1926): avc:  denied  { read } for  pid=439 comm="account...:s0 tclass=dir
июн 15 12:36:45 desktop setroubleshoot[532]: AuditRecordReceiver.feed() got node=desktop type=SYSCALL msg=audit(1371278205.117:1926): arch=40000003 syscall=292 success=no exit=-13 a0=8 a1=b8e...:s0 key=(null)
июн 15 12:36:45 desktop setroubleshoot[532]: AuditRecordReceiver.add_record_to_cache(): node=desktop type=SYSCALL msg=audit(1371278205.117:1926): arch=40000003 syscall=292 success=no exit=-13...:s0 key=(null)
июн 15 12:36:45 desktop setroubleshoot[532]: AuditRecordReceiver.feed() got node=desktop type=EOE msg=audit(1371278205.117:1926):
июн 15 12:36:45 desktop setroubleshoot[532]: AuditRecordReceiver.add_record_to_cache(): node=desktop type=EOE msg=audit(1371278205.117:1926):
июн 15 12:36:45 desktop setroubleshoot[532]: analyze_avc() avc=scontext=system_u:system_r:accountsd_t:s0 tcontext=system_u:object_r:var_log_t:s0 access=['read'] tclass=dir tpath=/var/log
июн 15 12:36:45 desktop setroubleshoot[532]: lookup_signature: found 1 matches with scores 1.00
июн 15 12:36:45 desktop setroubleshoot[532]: signature found in database
июн 15 12:36:45 desktop setroubleshoot[532]: sending alert to all clients
июн 15 12:36:45 desktop setroubleshoot[532]: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c...7-c73a985c03f5
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() names=['openvpn', 'allow_ftpd_use_nfs', 'catchall', 'wine', 'allow_anon_write', 'allow_execheap', 'allow_
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.openvpn previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.allow_ftpd_use_nfs previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.catchall previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.wine previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.allow_anon_write previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.allow_execheap previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.allow_ftpd_use_cifs previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.catchall_boolean previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.qemu_blk_image previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.restorecon previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.httpd_write_content previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.mozplugger previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.allow_execmod previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.automount_exec_config previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.selinuxpolicy previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.mozplugger_remove previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.cvs_data previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.connect_ports previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.sys_module previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.rsync_data previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.xen_image previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.mmap_zero previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.catchall_labels previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.mounton previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.allow_execstack previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.swapfile previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.sys_resource previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.kernel_modules previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.bind_ports previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.device previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.file previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.samba_share previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.dac_override previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.sshd_root previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.vbetool previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.public_content previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.setenforce previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.disable_ipv6 previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.leaks previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.filesystem_associate previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.httpd_can_sendmail previously imported
июн 15 12:36:45 desktop setroubleshoot[532]: load_plugins() plugins.qemu_file_image previously imported
июн 15 12:36:45 desktop python[532]: [120B blob data]

Comment 36 Adam Williamson 2013-06-15 07:51:46 UTC
Mikhail: well, I don't see a loop there. The timestamps only go forward, from 12:36:41 to 12:36:45. It'd be a loop if it then went back to 12:36:41, forward to 12:36:45, back to 12:36:41, and so on forever and ever...

Comment 37 Tomas Heinrich 2013-06-15 07:57:54 UTC
(In reply to Michael Schwendt from comment #32)
> More precisely, the spamming stops after some time. A large number of old
> messages get appended to /var/log/messages, enough to occupy the CPU and
> make the fans spin up, but when it reaches "today", it stops.

This is expected.
See https://bugzilla.redhat.com/show_bug.cgi?id=971471#c11

Adam also summed it up here in comment 34.

(In reply to Adam Williamson from comment #34)
> 7.2.6 was still acting as an independent system logging daemon.

To a degree. Some time ago, rsyslog was made to read from a socket provided by journald and not from /dev/log, which journal itself reads from now. This was rather a switch to a more sophisticated interface.

Comment 38 Mikhail 2013-06-15 09:59:02 UTC
Adam Williamson, thanks. Yes seems no more looping, but new messages still added every 4 second it's is normal?

Comment 39 Tomas Heinrich 2013-06-15 12:43:42 UTC
(In reply to Mikhail from comment #38)
> Adam Williamson, thanks. Yes seems no more looping, but new messages still
> added every 4 second it's is normal?

I see that the messages you're receiving look like 

> Jun 15 11:58:17 desktop setroubleshoot: SELinux is preventing /usr/libexec/accounts-daemon from read access on the directory /var/log. For complete SELinux messages. run sealert -l 23b6c865-906d-4a8a-9447-c73a98

These are most likely caused by this bug:
https://bugzilla.redhat.com/show_bug.cgi?id=973849

Comment 40 Tomas Heinrich 2013-06-17 11:42:26 UTC
*** Bug 974969 has been marked as a duplicate of this bug. ***

Comment 41 Haïkel Guémar 2013-06-17 13:12:48 UTC
*** Bug 975019 has been marked as a duplicate of this bug. ***

Comment 42 Tomas Heinrich 2013-06-17 16:28:38 UTC
Here's an rsyslog scratch build for f19. There's a new code that does rate limiting on the messages coming through imjournal, which should mitigate the issue with disks filling up. There are some sane defaults set but they can be configured via /etc/rsyslog.conf. If anybody can still reproduce the issue, it would be good to know if this helps.

http://koji.fedoraproject.org/koji/taskinfo?taskID=5513004

Comment 43 Tomas Heinrich 2013-07-29 10:18:31 UTC
*** Bug 989230 has been marked as a duplicate of this bug. ***

Comment 44 Zbigniew Jędrzejewski-Szmek 2013-12-03 19:11:03 UTC
I'm pretty sure the loop bug is now fixed, because we had a bunch of reports at the time, and they have stopped since those updates. Seems that Mikhail was hitting a different issue above.

Comment 45 Tom London 2013-12-03 19:47:48 UTC
Is there a rawhide fix for this?

Comment 46 Zbigniew Jędrzejewski-Szmek 2013-12-03 19:51:16 UTC
Rawhide has the same systemd version as F20, so yes it should be fixed for rawhide too.

Comment 47 Dan Fruehauf 2014-01-12 11:51:42 UTC
I'm using systemd-208-9.fc20.x86_64 and still suffer from this problem. My rsyslog version is 7.4.2-2.fc20.x86_64.

Still rsyslog is at 100% cpu. Running strace on the rsyslogd doesn't give much, it's just running select().

Should this be a new issue?

Comment 48 Tomas Heinrich 2014-01-12 12:09:06 UTC
(In reply to Dan Fruehauf from comment #47)
> I'm using systemd-208-9.fc20.x86_64 and still suffer from this problem. My
> rsyslog version is 7.4.2-2.fc20.x86_64.

Is it possible that you're hitting bug #1047039 ?

Comment 49 Dan Fruehauf 2014-01-12 12:11:01 UTC
Corret. Looks more like t(In reply to Tomas Heinrich from comment #48)
> (In reply to Dan Fruehauf from comment #47)
> > I'm using systemd-208-9.fc20.x86_64 and still suffer from this problem. My
> > rsyslog version is 7.4.2-2.fc20.x86_64.
> 
> Is it possible that you're hitting bug #1047039 ?

Correct. Looks more like the bug you've mentioned. Thanks!