Description of problem: rsyslog with default configuration consumes 100% CPU when started without any output in /var/log/* produced. Version-Release number of selected component (if applicable): rsyslog-7.4.2-2.fc20.x86_64 How reproducible: ALWAYS Steps to Reproduce: 1. sudo systemctl start syslog 2. watch cpu load Actual results: 100% CPU load without any obvious reason Expected results: peaceful, low rotating fun and smooth desktop Additional info: This made me realize that I don't actually need it thanks to journal.
(In reply to Michal Minar from comment #0) > Description of problem: > rsyslog with default configuration consumes 100% CPU when started without > any output in /var/log/* produced. How did this happen? After a package upgrade? Fresh f20 install? Upgrade from f18/f19? > Steps to Reproduce: > 1. sudo systemctl start syslog > 2. watch cpu load Can you get a strace? Perhaps even the output from a debug mode (/sbin/rsyslogd -dn). Can you try do delete /var/lib/rsyslog/imjournal.state and restart the daemon to see whether this solves it?
I'm seeing this on a fresh f20 install. I didn't see it straight away but I noticed it after doing "yum install @kde-desktop". Attaching strace to the running rsyslogd just showed: # strace -p 19541 Process 19541 attached select(1, NULL, NULL, NULL, {86346, 498588} Running in debug mode produced a couple of lines of: Dec 30 12:22:00 zion rsyslogd: log message from journal doesn't have MESSAGE Dec 30 12:22:01 zion rsyslogd: log message from journal doesn't have MESSAGE but nothing else. Removing /var/lib/rsyslog/imjournal.state and restarting the daemon resulted in a lot of journal messages appearing in /var/log/messages but then nothing else. CPU continues to be used at 100%.
Got the same bug here: F19 to F20 otherwise uneventful fedup. Attaching a brief debug mode output here. systemctl stopped rsyslog.service, deleted /var/lib/imjournal.state, systemctl started rsyslog.service: rsyslogd still pegged 1 core at 100%. I only have the "base" rsyslog.x86_64 package installed.
Created attachment 843494 [details] rsyslog debug output from command line run
Thank you both for the information. Looking at the code, this might even be a bug / change in journald. Could you please try to delete (backup) /var/log/journal/* and see if that helped? If that doesn't help, an interim workaround is to edit /etc/rsyslog.conf to use the imuxsock module instead of imjournal. I.e. commenting out $ModLoad imjournal $OmitLocalLogging on $IMJournalStateFile imjournal.state
*** Bug 1047643 has been marked as a duplicate of this bug. ***
That should have been "delete /var/log/journal/* or /run/log/journal/*, whichever is in use". Also, when rsyslog is in a busy-loop, what does journalctl report?
Created attachment 844370 [details] output of journalctl after rsyslog start Deleting /var/log/journal/* did indeed help. I haven't been able to reproduce the problem afterwards (restarting journal, rsylogd, rebooting). And unfortunately I didn't make a backup. Attached is the output of journalctl when rsylog got into busy-loop. SELinux is in permissive mode.
Deleting /var/log/journal/* and rebooting worked for me too. journalctl didn't show anything unusual when rsyslog started and was busy-looping prior to that, just the usual daemon start-up message.
I had the issue again, but this time I noticed that my / partition was increased suddenly by almost 10GB. It turned out that /var/log/messages and the files in /var/log/journal/ were too large. I deleted the message file and the contents of /var/log/journal/, but this time I also uninstalled rsyslog. It does not make much sense having two log systems anyway. http://0pointer.de/blog/projects/journalctl.html So far, so good.
(In reply to Paulo Roma Cavalcanti from comment #10) > I had the issue again, but this time I noticed that my / partition > was increased suddenly by almost 10GB. It turned out that /var/log/messages > and the files in /var/log/journal/ were too large. If those locations grow in size considerably, it might suggest some process has run amok or there might be a bug in systemd/journal and rsyslog gets hit. > It does not make much sense having two log systems anyway. journal can't do everything rsyslog does and vice versa. The messages from comment#2 look malformed. Not sure if the MESSAGE field is mandatory in journal. If somebody can still reproduce this behavior and is willing to test, can you compile and run the example from the page sd_journal_next(3) man page to see what's actually coming out of journal? Maybe journalctl has a way of limiting the output. Switching to systemd; either there's a flood of malformed messages or the api needs to be used in a way I'm not aware of.
Not sure if this is the same bug? Output from "top H": PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 713 root 20 0 815920 17560 14908 R 99.9 0.1 539:38.57 in:imjournal (gdb) info threads Id Target Id Frame 4 Thread 0x7fa07a8bc700 (LWP 713) "in:imjournal" 0x00007fa08a61f795 in generic_array_get (f=f@entry=0x7fa08c958cd0, first=3737832, i=74, ret=ret@entry=0x7fa07a8bbb50, offset=offset@entry=0x7fa07a8bbb58) at ../src/journal/journal-file.c:1423 3 Thread 0x7fa07a0bb700 (LWP 714) "in:imklog" 0x00007fa08bea687d in read () at ../sysdeps/unix/syscall-template.S:81 2 Thread 0x7fa0798ba700 (LWP 715) "rs:main Q:Reg" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185 * 1 Thread 0x7fa08c4b2780 (LWP 650) "rsyslogd" 0x00007fa08af8f7b3 in select () at ../sysdeps/unix/syscall-template.S:81 (gdb) thread 4 [Switching to thread 4 (Thread 0x7fa07a8bc700 (LWP 713))] #0 0x00007fa08a61f795 in generic_array_get (f=f@entry=0x7fa08c958cd0, first=3737832, i=74, ret=ret@entry=0x7fa07a8bbb50, offset=offset@entry=0x7fa07a8bbb58) at ../src/journal/journal-file.c:1423 1423 ci = hashmap_get(f->chain_cache, &first); (gdb) bt #0 0x00007fa08a61f795 in generic_array_get (f=f@entry=0x7fa08c958cd0, first=3737832, i=74, ret=ret@entry=0x7fa07a8bbb50, offset=offset@entry=0x7fa07a8bbb58) at ../src/journal/journal-file.c:1423 #1 0x00007fa08a61fc7a in journal_file_next_entry (f=f@entry=0x7fa08c958cd0, o=<optimized out>, p=<optimized out>, direction=direction@entry=DIRECTION_DOWN, ret=ret@entry=0x7fa07a8bbb50, offset=offset@entry=0x7fa07a8bbb58) at ../src/journal/journal-file.c:1991 #2 0x00007fa08a618f1b in next_with_matches (j=j@entry=0x7fa08c9583b0, f=f@entry=0x7fa08c958cd0, direction=direction@entry=DIRECTION_DOWN, ret=ret@entry=0x7fa07a8bbb50, offset=offset@entry=0x7fa07a8bbb58) at ../src/journal/sd-journal.c:814 #3 0x00007fa08a61a76d in next_beyond_location (offset=<synthetic pointer>, ret=0x7fa07a8bbb40, direction=DIRECTION_DOWN, f=0x7fa08c958cd0, j=0x7fa08c9583b0) at ../src/journal/sd-journal.c:873 #4 real_journal_next (j=0x7fa08c9583b0, direction=direction@entry=DIRECTION_DOWN) at ../src/journal/sd-journal.c:895 #5 0x00007fa08a61b3aa in sd_journal_next (j=<optimized out>) at ../src/journal/sd-journal.c:931 #6 0x00007fa08a8343a0 in runInput (pThrd=<optimized out>) at imjournal.c:533 #7 0x00007fa08c53eb00 in thrdStarter (arg=0x7fa08c966f50) at ../threads.c:212 #8 0x00007fa08be9ff33 in start_thread (arg=0x7fa07a8bc700) at pthread_create.c:309 #9 0x00007fa08af97ead in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
Thanks for another another data point. It's likely the same bug. I have a theory of what's happening but can't reproduce this myself. It would be great if somebody who hit this bug can try to run a minimalistic code that uses the journal api, such as the one from the sd_journal_next(3) man page and provide the output / describe the behavior.
Can someone experiencing this attach (or post somewhere) the contents of /var/log/journal/ ?
Hi Zbigniew, [alex@alex-ultrabook ~]$ ls -lh /var/log/journal/df93f6ef563440308214bf8c81ff44fe/ total 906M -rw-r-----+ 1 root systemd-journal 23M Jul 11 2013 system~ -rw-r-----+ 1 root systemd-journal 105M Sep 2 20:37 system~ -rw-r-----+ 1 root systemd-journal 31M Sep 12 20:23 system~ -rw-r-----+ 1 root systemd-journal 85M Oct 31 09:09 system~ -rw-r-----+ 1 root systemd-journal 52M Nov 22 08:15 system~ -rw-r-----+ 1 root systemd-journal 78M Dec 4 18:46 system~ -rw-r-----+ 1 root systemd-journal 19M Dec 8 16:15 system~ -rw-r-----+ 1 root systemd-journal 56M Dec 23 22:51 system~ -rw-r-----+ 1 root systemd-journal 32M Dec 31 09:24 system~ -rw-r-----+ 1 root systemd-journal 8.0M Dec 31 09:34 system~ -rw-r-----+ 1 root systemd-journal 8.0M Dec 31 12:06 system~ -rw-r-----+ 1 root systemd-journal 16M Jan 1 12:59 system~ -rw-r-----+ 1 root systemd-journal 16M Jan 2 09:09 system~ -rw-r-----+ 1 root systemd-journal 40M Jan 9 10:31 system~ -rw-r-----+ 1 root systemd-journal 16M Jan 10 10:46 system~ -rw-r-----+ 1 root systemd-journal 88M Jul 11 2013 system -rw-r-----+ 1 root systemd-journal 110M Aug 4 23:49 system -rw-r-----+ 1 root systemd-journal 40M Jan 15 09:32 system.journal -rw-r-----+ 1 root systemd-journal 4.4M Sep 2 20:38 user-1000~ -rw-r-----+ 1 root systemd-journal 5.5M Dec 8 16:16 user-1000~ -rw-r-----+ 1 root systemd-journal 8.0M Dec 23 22:51 user-1000~ -rw-r-----+ 1 root systemd-journal 8.0M Dec 31 09:35 user-1000~ -rw-r-----+ 1 root systemd-journal 8.0M Dec 31 12:06 user-1000~ -rw-r-----+ 1 root systemd-journal 8.0M Jan 1 13:02 user-1000~ -rw-r-----+ 1 root systemd-journal 8.0M Jan 9 10:54 user-1000~ -rw-r-----+ 1 root systemd-journal 8.0M Jan 10 10:46 user-1000~ -rw-r-----+ 1 root systemd-journal 4.9M Aug 4 23:49 user-1000 -rw-r-----+ 1 root systemd-journal 4.0M Jul 11 2013 user-1000 -rw-r-----+ 1 root systemd-journal 8.0M Jan 15 09:07 user-1000.journal -rw-r-----+ 1 root systemd-journal 3.6M Dec 1 03:11 user-990.journal -rw-r-----+ 1 root systemd-journal 8.0M Jan 9 10:30 user-999.journal
By contents, I meant the actual contents :) If you xz them, they shouldn't be more than a hundred megs or so.
Hi Zbigniew, I moved the df93f6ef563440308214bf8c81ff44fe folder to .old and restarted, the problem has now gone away. So the issue is related to the contents of these files. Do these files contain any sensitive information?
(In reply to Alexander Wigen from comment #17) > I moved the df93f6ef563440308214bf8c81ff44fe folder to .old and restarted, > the problem has now gone away. So the issue is related to the contents of > these files. Yes, that is probable. > Do these files contain any sensitive information? You can review them with 'journalctl --directory ...'. Those are normal system logs, so the contain the usual stuff: information about your hostname, IP address, running packages, users logging in and out. If it is a personal machine, that's probably fine to post publicly, if it is a multi-user server, then probably not.
Created attachment 854746 [details] file list of directory So I had the same issue - here's a file listing of the directory that I moved to .old, are any of those of more interest than others?
(In reply to Nathanael Noblet from comment #19) > Created attachment 854746 [details] > file list of directory This is not interesting. The contents of those files are. > So I had the same issue - here's a file listing of the directory that I > moved to .old, are any of those of more interest than others? Yes, but we don't know which. If you want to, you can try to find a minimum subset which still exhibits the bug.
Which file? Do you want all of them? Is there likely going to be sensitive information in the logs?
(In reply to Nathanael Noblet from comment #21) > Which file? The directory /var/log/journal/. > Do you want all of them? Yes. It's probably only a subset which is triggers a bug, but it's not obvious which subset. > Is there likely going to be sensitive > information in the logs? Information about user names, ip addresses, host name, services running, etc. YMMV. I got a set of files from Edgar Hoch which trigger the bug, which should suffice, so for now, I don't need anything more.
Created attachment 868335 [details] patch 1/2
Created attachment 868336 [details] patch 2/2
systemd-208-15.fc20 has been submitted as an update for Fedora 20. https://admin.fedoraproject.org/updates/systemd-208-15.fc20
Package systemd-208-15.fc20: * should fix your issue, * was pushed to the Fedora 20 testing repository, * should be available at your local mirror within two days. Update it with: # su -c 'yum update --enablerepo=updates-testing systemd-208-15.fc20' as soon as you are able to. Please go to the following url: https://admin.fedoraproject.org/updates/FEDORA-2014-3522/systemd-208-15.fc20 then log in and leave karma (feedback).
systemd-208-15.fc20 has been pushed to the Fedora 20 stable repository. If problems still persist, please make note of it in this bug report.
I think something nasty is just happening now - and again. It started happenning in last few days (after applying updates) for the first time for me on my production f20 x86 as my system became slow and something, probably /var/log/messages have eaten all remaining hard drive space. [root@localhost var]# ls -lhS /var/log/messages -rw------- 1 root root 1.4G May 5 22:26 /var/log/messages When cpu is very high noticed systemd-journal and rsyslogd are amongst top five processes.
slobodan: it's the kind of generic symptom which could be caused by various underlying problems - rsyslog is basically a mirror of the systemd journal, and if rate limiting doesn't kick in, it's certainly possible it can get filled with messages. have you looked to see what's actually in the file taking up all that space?
Hi Adam, it is always repeating the same "block" in /var/log/messages, the most probably related to wifi usb dongle and updated kernel package. It is: Call Trace: <c0a08d57>] dump_stack+0x41/0x52 [<c045b5ee>] warn_slowpath_common+0x7e/0xa0 [<c0834235>] ? usb_submit_urb+0x1c5/0x550 [<c0834235>] ? usb_submit_urb+0x1c5/0x550 [<c045b64e>] warn_slowpath_fmt+0x3e/0x60 [<c0834235>] usb_submit_urb+0x1c5/0x550 [<e0d50018>] hif_usb_send+0xb8/0x310 [ath9k_htc] [<e0d4e059>] htc_issue_send.constprop.1+0x59/0x70 [ath9k_htc] [<e0d4e42d>] htc_send_epid+0x1d/0x30 [ath9k_htc] [<e0d509fc>] ath9k_wmi_cmd+0xdc/0x170 [ath9k_htc] [<e0d55f83>] ath9k_regwrite+0x63/0x120 [ath9k_htc] [<e0a50b61>] ath_hw_cycle_counters_update+0x81/0x110 [ath] [<e103f5a5>] ath9k_hw_ani_monitor+0x25/0x1e0 [ath9k_hw] [<e0d55117>] ath9k_htc_ani_work+0x157/0x180 [ath9k_htc] [<c0473f75>] process_one_work+0x115/0x380 [<c0474a8e>] worker_thread+0xfe/0x330 [<c0474990>] ? manage_workers.isra.28+0x250/0x250 [<c047a45c>] kthread+0xac/0xc0 [<c0a16ff7>] ret_from_kernel_thread+0x1b/0x28 [<c047a3b0>] ? insert_kthread_work+0x30/0x30 ---[ end trace 09ec989c9e292e48 ]--- Something that is very scaring is that /var/log/messages opening timestamp was "May 5 20:55:46" and closing was "May 5 21:46:38". So, in less that an hour log file grew from zero to 1.4GB! Probably it stoped when it have eaten all free space on /.
slobodan: OK, so it sounds like there's an issue with rate limiting and also a kernel bug...if you could file both it'd be great. The kernel bug probably at http://bugzilla.kernel.org/ . for the other one...does the systemd journal also get huge, or are the messages properly limited there? (the rate limiting issue may ultimately be on the kernel side too, but I think they're still two separate bugs).
Related to content and size of /var/log/systemd: [root@localhost slobodan]# du -hs /var/log/journal/542c47fae5eb4d1d873a1b41ef83927e/ 2.4G /var/log/journal/542c47fae5eb4d1d873a1b41ef83927e/ There are about 300 files in there, each of 8MB in size and timestamps reveal all files were created/modified that hour. I'll try to reproduce this again and open appropriate report(s).
Thanks. Can you include more context for the kernel trace, particularly the actual WARNING: message printed out?
Sure, please take a look at the wifidongleflood.txt. This behaviour is not happening with previous stable kernel. kernel 3.13.10-200.fc20.i686+PAE from @updates - works ok kernel 3.14.2-200.fc20.i686+PAE from @updates - flooding kernel 3.15.0-0.rc4.git0.1.fc21.i686+PAE from @fedora-rawhide-kernel-nodebug - flooding Maybe wrong was that I have noticed high cpu usage and came here - I am not sure this belongs to this bug report as you said already, so I'll wait for your comment and probably file a bug at kern bugzilla. Should I mention rate limiting there ?
Created attachment 893030 [details] Trace This is flooding /var/log/messages and /var/log/journal
hi, We are using RHEL 2.6.32-358.18.1.el6.x86_64 , & facing same issue, would you please confirm if same bug is present in RHEL
dasharath: this specific issue traced back to systemd's journal, and RHEL 6 does not use that, so it seems unlikely. I recommend reporting your issue separately through the usual support channels.
jwb, linville - can you folks take a look at Slobodan's message and advise what he should do? I'm guessing he'll want to file a kernel bug for the actual issue, beyond that, is it worth reporting the spamming to kernel and/or systemd? thanks!
adam: I have already reported it at kernel bugzilla as yoz suggested - https://bugzilla.kernel.org/show_bug.cgi?id=76311 , I think linville is cc-ed there.
I just had this. The cause was pulseaudio This afternoon I had been fooling around with the system clock to do NTP related tests, so the clock in the syslog was jumping around. A strong hint from my point of view.
(In reply to Ferry Huberts from comment #40) > I just had this. > The cause was pulseaudio > > This afternoon I had been fooling around with the system clock to do NTP > related tests, so the clock in the syslog was jumping around. > A strong hint from my point of view. too quick. F20 pulseaudio.x86_64 5.0-7.fc20 pulseaudio-equalizer.noarch 2.7-12.fc20 pulseaudio-gdm-hooks.x86_64 5.0-7.fc20 pulseaudio-libs.i686 5.0-7.fc20 pulseaudio-libs.x86_64 5.0-7.fc20 pulseaudio-libs-glib2.x86_64 5.0-7.fc20 pulseaudio-module-bluetooth.x86_64 5.0-7.fc20 pulseaudio-module-gconf.x86_64 5.0-7.fc20 pulseaudio-module-x11.x86_64 5.0-7.fc20 pulseaudio-module-zeroconf.x86_64 5.0-7.fc20 pulseaudio-utils.x86_64 5.0-7.fc20 rsyslog.x86_64 7.4.8-2.fc20
I just got this on F20 as well. Oct 24 21:36:23 twillber rsyslogd-2177: imjournal: begin to drop messages due to rate-limiting /var/log/messages isn't flooded due to rate-limiting, but rsyslogd is consuming 100% of CPU: PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 19901 root 20 0 832976 28324 27592 S 100.3 0.4 2:16.00 rsyslogd The root cause is mmc_blk kernel module; I unplugged a card while it was in use.