Ubuntu

rsyslogd spins CPU on some kernels

Reported by Mathias Gug on 2010-02-18
304
This bug affects 63 people
Affects Status Importance Assigned to Milestone
rsyslog (Ubuntu)
High
Scott James Remnant (Canonical)
Lucid
High
Scott James Remnant (Canonical)

Bug Description

While running 20100218 EC2 image (ami-0512fe6c) rsyslog is constantly the following message (found in /var/log/kern.log):

Feb 18 05:01:52 ubuntu kernel: imklog 4.2.0, log source = /proc/kmsg started.
Feb 18 05:01:52 ubuntu kernel: Cannot read proc file system: 1 - Operation not permitted.
Feb 18 05:02:22 ubuntu kernel: last message repeated 643668 times
Feb 18 05:03:22 ubuntu kernel: last message repeated 1865459 times
Feb 18 05:04:22 ubuntu kernel: last message repeated 1327321 times
Feb 18 05:05:22 ubuntu kernel: last message repeated 1644146 times
Feb 18 05:06:23 ubuntu kernel: last message repeated 1826234 times
Feb 18 05:07:23 ubuntu kernel: last message repeated 1817861 times
Feb 18 05:08:23 ubuntu kernel: last message repeated 1807415 times
Feb 18 05:09:23 ubuntu kernel: last message repeated 1813151 times
Feb 18 05:10:23 ubuntu kernel: last message repeated 1857271 times
Feb 18 05:11:23 ubuntu kernel: last message repeated 1810173 times
Feb 18 05:12:23 ubuntu kernel: last message repeated 1826654 times
Feb 18 05:13:23 ubuntu kernel: last message repeated 1825384 times

Related branches

Mathias Gug (mathiaz) on 2010-02-18
summary: - Cannot read proc file system: 1 - Operation not permitted.
+ 20100218 EC2 image (ami-0512fe6c): Cannot read proc file system: 1 -
+ Operation not permitted.

Also seeing this running lucid's rsyslog 4.2.0-2ubuntu7, on linode's 2.6.32-linode23 paravirt kernel.

Jeff Waugh (jdub) wrote :

most likely rsyslog, not the kernel

affects: linux-ec2 (Ubuntu) → rsyslog (Ubuntu)
Jeff Waugh (jdub) wrote :

Possible dupe, or related to #460738?

Jeff Waugh (jdub) wrote :

rsyslog runs as syslog, can't read /proc/kmsg:

jdub@node:~$ ls /proc/kmsg
-r-------- 1 root root 0 2010-02-18 19:01 /proc/kmsg

Jeff Waugh (jdub) wrote :

Aha -- in its conversion to upstart, the old dd trick wasn't brought over.

LCID Fire (lcid-fire) wrote :

Well - since this is pretty much killing my 1,6 G notebook for now my lucid fixup script contains a call to
sudo service rsyslog stop

LCID Fire (lcid-fire) wrote :

Might be dup of #460738!?

Matt Zimmerman (mdz) wrote :

The changelog says this should work with newer kernels:

rsyslog (4.2.0-2ubuntu6) lucid; urgency=low

  * debian/rsyslog.rsyslog-kmsg.upstart:
    - Drop this additional job; kernel changes have meant that rsyslog
      may read from /proc/kmsg directly after dropping privileges.
      LP: #517773
  * debian/rsyslog.preinst:
    - Remove on upgrade
  * debian/rsyslog.conf:
    - Restore to reading from /proc/kmsg

 -- Scott James Remnant <email address hidden> Wed, 17 Feb 2010 12:23:01 +0000

I'm running 2.6.32-12-generic #16-Ubuntu and it definitely does not work there. Even if it works in the latest kernels, this will be a problem for upgrades from Karmic, because rsyslog gets restarted before the kernel is upgraded.

Changed in rsyslog (Ubuntu):
status: New → Triaged
importance: Undecided → High
tags: added: regression-potential
Changed in rsyslog (Ubuntu Lucid):
assignee: nobody → Scott James Remnant (scott)
milestone: none → lucid-alpha-3
Martin Pitt (pitti) wrote :

Regression from bug 517773, which was not completely implemented.

rsyslog needs to check if it can read from /proc/kmsg as non-root, and not drop privileges if not. In other works, seteuid(), read() -> on fail, seteuid(0) and keep it that way, on success -> setuid() -> permanently drop privs.

summary: - 20100218 EC2 image (ami-0512fe6c): Cannot read proc file system: 1 -
- Operation not permitted.
+ rsyslogd spins CPU on older kernels

Happens for me on 2.6.33-020633rc8-generic from kernel-ppa

After this recent upgrade, rsyslogd takes 50% of my cpu, see also bug #524382

I installed right now the 4.2.0-2ubuntu5.1 version and the high usage of cpu doesn't happen

Fail2Ban (failtoban) on 2010-02-20
tags: added: regression-release
removed: regression-potential

Fail2Ban: This is a regression in a development release, not a stable release; hence regression-potential, not regression-release. (See https://wiki.ubuntu.com/QATeam/RegressionTracking .)

tags: added: regression-potential
removed: regression-release
Gary Trakhman (gary-trakhman) wrote :

Debian Sid's rsyslog_4.4.2 seems to fix it for me.

http://packages.debian.org/sid/rsyslog

Gary Trakhman (gary-trakhman) wrote :

I'm running 2.6.31 btw. But it's lucid otherwise.

Gary Trakhman (gary-trakhman) wrote :

and... it's the same version that's in squeeze

zika (4zika4) wrote :

Putting stop rsyslog in /etc/rc.local tamed it...

Dana Goyette (danagoyette) wrote :

This also happens on the kernel-ppa 2.6.32-rc8 kernel (which means that kernel must lack some necessary kernel patch, or something.)
The line that keeps repeating:
Feb 21 12:55:49 EliteBook kernel: Cannot read proc file system: 1 - Operation not permitted.
Feb 21 12:56:19 EliteBook kernel: last message repeated 3932924 times
Feb 21 12:57:19 EliteBook kernel: last message repeated 6246228 times
Feb 21 12:58:19 EliteBook kernel: last message repeated 6210564 times
Feb 21 12:59:19 EliteBook kernel: last message repeated 6559527 times
Feb 21 13:00:19 EliteBook kernel: last message repeated 5978876 times
Feb 21 13:00:40 EliteBook kernel: last message repeated 2155624 times

Ben Blout (bdb-new) wrote :

I am seeing the problem also. Running a kernel from the mainline-ppa (I was requested to in bug #521260). Uname -a indicates: 2.6.33-999-generic #201002201003 SMP

dpkg --print-avail says I am running rsyslog_4.2.0-2ubuntu5.1_i386

Whinis (john-p-turner) wrote :

I too am having this problem running a custom kernel based off of 2.6.31.12 and I merely increased the frequency timer. However rsyslog seems to immediately jump up to 2 cores of my i7 after the recent update.

I was testing on 2.6.31-rt-9 and I have this issue, looks like the
1kHz timer is what we have in common?

On Mon, Feb 22, 2010 at 9:55 PM, Whinis <email address hidden> wrote:
> I too am having this problem running a custom kernel based off of
> 2.6.31.12 and I merely increased the frequency timer. However rsyslog
> seems to immediately jump up to 2 cores of my i7 after the recent
> update.
>
> --
> rsyslogd spins CPU on older kernels
> https://bugs.launchpad.net/bugs/523610
> You received this bug notification because you are a direct subscriber
> of a duplicate bug.
>

also experiencing this with my intel t2390 processor.
I am experiencing this issue with the current lucid kernel (2.6.32.8) but also in the new kernel (downloaded from ubuntu's kernel ppa) the version of 23 february 2010

Geoff123 (gsking1) wrote :

Same here on lucid with both the ubuntu-studio RT kernel package 2.6.31-rt and custom 2.6.33-rc8 (1000HZ, low-latency desktop, BFS scheduler patch).

RK (kubuntu-rk) wrote :

Same here on 2.6.33-020633rc8-generic; downgrading to 4.2.0-2ubuntu5 fixes it. I'd say 2.6.33 isn't an "older" kernel...

summary: - rsyslogd spins CPU on older kernels
+ rsyslogd spins CPU on some kernels
Michael Marley (mamarley) wrote :

Yeah, same here. I have the problem with 2.6.33 as well.

Something like this seems the sanest approach.

After opening /proc/kmsg, attempt a zero-byte read from it - if that fails with EPERM then we don't load the klog module

That patch isn't right, needs to seteuid() around the read() call, but the module doesn't know what the uid is going to be; wondering whether hard-coding some number in there will upset pitti

why not upgrade rsyslogd? Using debian testing's 4.4.2 package fixed it for me.

On Wed, Feb 24, 2010 at 12:41 PM, Scott James Remnant
<email address hidden> wrote:
> Something like this seems the sanest approach.
>
> After opening /proc/kmsg, attempt a zero-byte read from it - if that
> fails with EPERM then we don't load the klog module
>
> ** Attachment added: "deroot.patchpatch"
>   http://launchpadlibrarian.net/39737237/deroot.patchpatch
>
> --
> rsyslogd spins CPU on some kernels
> https://bugs.launchpad.net/bugs/523610
> You received this bug notification because you are a direct subscriber
> of a duplicate bug.
>

Better version of the patch

Gary: because upgrading doesn't actually fix the problem - if you use Debian's package, your rsyslog is running as *root* - the whole point of this exercise is to make it not need to. If we were to merge rsyslog, we'd still use our deroot.patch, so would still hit the same bug

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package rsyslog - 4.2.0-2ubuntu8

---------------
rsyslog (4.2.0-2ubuntu8) lucid; urgency=low

  * debian/patches/deroot.patch:
    - After opening /proc/kmsg, set the effective user to an unprivileged
      one and attempt a zero-byte read from the file. If this succeeds, we
      know that this will work de-rooted; if this fails, we don't enable
      kernel-message logging. LP: #523610.
 -- Scott James Remnant <email address hidden> Wed, 24 Feb 2010 18:21:54 +0000

Changed in rsyslog (Ubuntu Lucid):
status: Triaged → Fix Released
tags: added: iso-testing
Dave Martin (dave-martin-arm) wrote :

@Scott

Just to check --- is there a risk that the patch to rsyslog will in effect disable kernel logging on any final lucid release, bearing in mind that not all the kernels are in sync (particularly armel imx51)

That would surely be bad, but I've probably misunderstood here...

Gianvito Cavasoli (janvitus) wrote :

This bug still persist on Lucid:

"localhost kernel: imklog: Cannot read proc file system, 1."

I have a kernel vanilla 2.6.33.2 without patches and rsyslog 4.2.0-2ubuntu8.

Rocko (rockorequin) on 2010-04-17
Changed in rsyslog (Ubuntu Lucid):
status: Fix Released → Confirmed
Rocko (rockorequin) wrote :

I confirm Gianvito's findings with 2.6.33.2, ie that the problem is NOT resolved. rsyslog isn't using up CPU cycles, but it is failing to read kmsg.

What I suspect is happening is that attempting a zero-byte read from ksmg always succeeds, so rsyslog is using the wrong test, eg:

sudo python
>>> import os
>>> f=open('/proc/kmsg')
>>> os.seteuid(1000)
>>> f.read(0)
''
>>> f.read(1)
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
IOError: [Errno 1] Operation not permitted

ie rsyslog should try and read at least one byte for its test whether the user can read /proc/kmsg.

Oddly, it looks like the patch (see comment 1 in bug #515623) to allow user "read file" access to /proc/kmsg is incorporated in 2.6.33.2, but it simply isn't working.

On Sat, 2010-04-17 at 06:18 +0000, Rocko wrote:

> I confirm Gianvito's findings with 2.6.33.2, ie that the problem is NOT
> resolved. rsyslog isn't using up CPU cycles, but it is failing to read
> kmsg.
>
Then this isn't the reported bug!

 status fixreleased

Note that the fact it doesn't read kmsg on older kernels is *DELIBERATE*
and will not be fixed.

Scott
--
Scott James Remnant
<email address hidden>

Rocko (rockorequin) wrote :

Apologies, I'll report it as another bug then.

Is it also the intention that rsyslog won't read kmsg on newer kernels? (2.6.33 is a newer kernel, not an older kernel).

Changed in rsyslog (Ubuntu Lucid):
status: Confirmed → Fix Released
Rocko (rockorequin) wrote :

Just to correct an earlier comment I made: that patch in bug #515623 (comment 1) ISN'T in 2.6.33.2. I applied it to 2.6.33.2 and kernel logging now works again. It looks like the patch will be in the vanilla 2.6.34, though. So hopefully 2.6.33 will be the only newer kernel that doesn't allow kernel logging in Lucid.

Right, that's my understanding as well

The design of rsyslog made it very hard to "fall back" to not de-rooting in the case of an unpatched kernel

I solved this issue for me (no kernel hacker) with going back to the last Version 4.2.0-2ubuntu5.

(Just want to mention this for other newbies like my)

simonm (simon-mullis) wrote :

Just to add another option in the spirit of #39. I couldn't find a simple solution and ended up solving this issue by removing rsyslog entirely and now use syslog-ng which does everything I need (only issue when installing was to chown a few logs to root.adm).

mokabar (tim-klingt) wrote :

the -rt kernel is still based on 2.6.33. a natty-based system with the -rt kernel is still prone to this issue

EntityReborn (entityreborn) wrote :

This is still active in 11.04. I am running this under a VPS, running kernel 2.6.32.19-0.2.99.17.22250fd-xen

I see this issue running 11.10; kernel 2.6.32.33-kvm-i386-20110317-dirty.
Temporary workaround was to downgrade to maverick's rsyslogd via: apt-get install rsyslog=4.2.0-2ubuntu8

XabiX (xdealmeida) wrote :

it happens to me on a VPS with :
Linux x.santrex.net 2.6.31.6 #3 SMP Mon May 3 19:58:57 UTC 2010 i686 i686 i386 GNU/Linux

panticz.de (panticz.de) wrote :

same problem under debian squeeze 64bit xen kernel:
Linux oneiric 2.6.32-5-xen-amd64 #1 SMP Thu Nov 3 05:42:31 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux

fixed with:
wget http://mirror.netcologne.de/ubuntu/pool/main/r/rsyslog/rsyslog_4.2.0-2ubuntu8_amd64.deb -O /tmp/rsyslog_4.2.0-2ubuntu8_amd64.deb
dpkg -i /tmp/rsyslog_4.2.0-2ubuntu8_amd64.deb

Malte S. Stretz (mss) wrote :

Still happens when running 11.10 on Proxmox VE 2.0-beta1 in an OpenVZ container:
Linux lorentz-s19 2.6.32-7-pve #1 SMP Thu Feb 16 09:00:32 CET 2012 i686 athlon i386 GNU/Linux

Justin Delegard (justdelegard) wrote :

I just upgraded from 10.04 to 12.04 and encountered this problem. As it turns out I was still using the 10.04 kernel and my Grub menu was woefully out of date and so was my kernel. I ran

apt-get install grub2

and that fixed my loader problems and also fixed the rsyslogd issue. I assume that the loader was expected to have upgraded between my release revisions but was not upgraded as part of the script or some such issue.

Callum Macdonald (chmac) wrote :

I had what I believe to be the same issue on 12.04 Precise 2.6.32-12-pve x86_64 running in a Proxmox container. I downloaded http://archive.ubuntu.com/ubuntu/pool/main/r/rsyslog/rsyslog_4.2.0-2ubuntu8_amd64.deb, installed, and now the error messages are no longer appearing.

Does this bug need to be re-opened? A new bug filed? It's showing fix-released but apparently the issue (or a variation) still exists.

Simon Déziel (sdeziel) wrote :

For those running OpenVZ/Proxmox containers, one simple workaround is to disable the imklog module using this :

  sed -i -e 's/^\$ModLoad imklog/#\$ModLoad imklog/g' /etc/rsyslog.conf

This fixes the 100% CPU usage of rsyslog in Natty, Oneiric and Precise containers.

Jarl (jarl-dk) wrote :

I am still experiencing this on 12.04 (rackspace hosting)

$lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 12.04.1 LTS
Release: 12.04
Codename: precise

$uname -a
Linux ex-test 2.6.32.1-rscloud #15 SMP Mon Feb 22 13:22:15 UTC 2010 x86_64 x86_64 x86_64 GNU/Linux

$aptitude show rsyslog | grep Version
Version: 5.8.6-1ubuntu8

FloSoft (flosoft) wrote :

same problem here :/

Moses Moore (moses-mozai) wrote :

Upgraded from 10.04 LTS to 12.04 LTS, and I was surprised to see my load average at >= 2.00 for days.

OpenVZ virtual private server
`lsb_release -a |grep Desc`: Ubuntu 12.04.1 LTS
`uname -a`: Linux 2.6.32-042stab057.1 x86_64
`dpkg -l rsyslog`: 5.8.6-1ubuntu8

I used the solution suggested in comment #49 above by sdeziel; after disabling that module, rsyslogd is no longer hoarding CPU time, and load average has dropped.

big question: after disabling 'imklog', is rsyslog now acquring *less* information than the Ubuntu 10.04 version? I'd like to know what I'm missing out on, if anything.

Simon Déziel (sdeziel) wrote :

@Moses, from what I could see, rsyslog is unable to get the "kernel" syslog facility regardless of the imklog module presence, even in 10.04. I think the OpenVZ kernel blocks access to this syslog facility for guests.

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers