2005-03-20 04:33:24

by Bodo Eggert

[permalink] [raw]
Subject: [PATCH 2.6.11.2][RFC] printk with anti-cluttering-feature

(I hope I avoided all spam-keywords this time, my previous mails didn't
seem to make it)
(please CC me on reply)

Issue:

On some conditions, the dmesg is spammed with repeated warnings about the
same issue which is neither critical nor going to be fixed. This may
result in losing the boot messages or missing other important messages.

Examples are:

nfs warning: mount version older than kernel
(my mount is newer than documented to be required)

atkbd.c: Keyboard on isa0060/serio0 reports too many keys pressed.
(I'm using a keyboard switch and a IBM PS/2 keyboard)

program smartd is using a deprecated SCSI ioctl, please convert it to SG_IO
(I'll use the latest version as soon as I need to)



Rate-limiting these messages is won't help, since it would still allow
these messages to (slowly or in a burst) spam the log.

Printing these messages only once after booting might result in missing
important messages, especially on long-running systems (e.g. if my
keyboard really breaks after I have used the keyboard switch).


Suggested solution:

Instead, I decided to use a global flag with a semi-random magic number,
which will indicate the last printk being supposed to be limited, and to
reset this flag on each normal printk. By doing this, dmesg will not be
spammed, but the latest issue is displayed last.

(I suggest using the first value from "cksum file.c" as the magic number
unless there are thousands of printks to convert.)

The magic number depends on the CPU being able to read and write a
complete int at once *or* being lucky not to have a magic value that can
be constructed by combining some other magic numbers and printking with
exactly that magic number while the update happens. I can convert the
variable to an atomic type if it is a concern, but that would increase the
chances of a clash due to the 24 bit limit.

The patch increases the size of vmlinux by 141 bytes.
--
The programmer's National Anthem is 'AAAAAAAAHHHHHHHH'


Attachments:
printk_nospam.patch (3.66 kB)

2005-03-20 04:40:57

by Trond Myklebust

[permalink] [raw]
Subject: Re: [PATCH 2.6.11.2][RFC] printk with anti-cluttering-feature

su den 20.03.2005 Klokka 05:37 (+0100) skreiv Bodo Eggert:
> (I hope I avoided all spam-keywords this time, my previous mails didn't
> seem to make it)
> (please CC me on reply)
>
> Issue:
>
> On some conditions, the dmesg is spammed with repeated warnings about the
> same issue which is neither critical nor going to be fixed. This may
> result in losing the boot messages or missing other important messages.
>
> Examples are:
>
> nfs warning: mount version older than kernel
> (my mount is newer than documented to be required)

Throw that one out, please. We have a more complete fix already queued
up on

http://client.linux-nfs.org/Linux-2.6.x/2.6.12-rc1/linux-2.6.12-02-kill_bad_mount_options.dif

Cheers,
Trond

--
Trond Myklebust <[email protected]>

2005-03-20 11:49:45

by Michael Tokarev

[permalink] [raw]
Subject: Re: [PATCH 2.6.11.2][RFC] printk with anti-cluttering-feature

Bodo Eggert wrote:
> (I hope I avoided all spam-keywords this time, my previous mails didn't
> seem to make it)
> (please CC me on reply)
>
> Issue:
>
> On some conditions, the dmesg is spammed with repeated warnings about the
> same issue which is neither critical nor going to be fixed. This may
> result in losing the boot messages or missing other important messages.

There's printk_ratelimit() already, used in quite several places in kernel
(or net_ratelimit() for net/* stuff). See also Documentation/sysctl/kernel.txt,
search for printk_ratelimit. JFYI.

/mjt

2005-03-20 13:45:54

by Bodo Eggert

[permalink] [raw]
Subject: Re: [PATCH 2.6.11.2][RFC] printk with anti-cluttering-feature

On Sun, 20 Mar 2005, Michael Tokarev wrote:
> Bodo Eggert wrote:

> > (please CC me on reply)
> >
> > Issue:
> >
> > On some conditions, the dmesg is spammed with repeated warnings about the
> > same issue which is neither critical nor going to be fixed. This may
> > result in losing the boot messages or missing other important messages.
>
> There's printk_ratelimit() already, used in quite several places in kernel
> (or net_ratelimit() for net/* stuff). See also Documentation/sysctl/kernel.txt,
> search for printk_ratelimit. JFYI.

ACK, but that's designed to work against a DoS, not against cluttering the
log. The messages I want to suppress are low-frequent.

I now realize that some of these warnings may be triggered by userspace,
and since userspace-triggered warnings are a possible DoS, these parts of
code should be rate-limited, too. I think it's best to include a
rate-limit check in my printk_nospam to make it work against slow log
spamming _and_ DoS.

--
"Don't ever be the first, don't ever be the last, and don't ever
volunteer to do anything."
-U. S Navy Swabbie
Fri?, Spammer: [email protected] [email protected]

2005-03-20 21:25:35

by Bodo Eggert

[permalink] [raw]
Subject: [PATCH 2.6.11.2][0/2] printk with anti-cluttering-feature

These patches address the issue of dmesg being slowly spammed with
repeated warnings.

Some parts of the kernel want to notify the user about deprecated or
invalid calls or parameters. These messages will slowly fill dmesg and
hinder you from seing the boot messages.

Examples are:
atkbd.c: Keyboard on isa0060/serio0 reports too many keys pressed.
(I'm using a keyboard switch and a IBM PS/2 keyboard)

program smartd is using a deprecated SCSI ioctl, please convert it to SG_IO
(I'll use the latest version as soon as I need to)

tuner: TV freq (0.00) out of range (44-958)
(I'll update zapping later)

This is prevented by introducing printk_nospam(), which takes an
additional magic value to identify the last one who printk-ed something.
If the current magic matches the one of the last successfull caller,
nothing will be printed. The normal printk will reset the magic to 0,
which ensures that if a messages indicating a current problem won't be
hidden just because it occured before.

Additionally, all these messages will be rate-limited, since they are
usurally triggered by userspace and thereby a way to DoS the machine.
Without the rate-limit, the user could repeatedly call two functions that
cause a printk in order to spam the log.

(The rate limit alone is not sufficient to prevent repeated warnings,
since they would be allowed by the burst limit or by being slow.)

This patch uses an uint, which can be read and written atomically by most
architectures. On architectures not supporting atomic reads to ints, the
message may be dropped or printed twice. I think it's OK, since dropping
for being racy is unlikely (especially compared to hitting the rate
limit), and a double line won't hurt.



The first patch will introduce the printk_nospam function.
The second patch will update the three printks causing my examples.

Since the TV freq message can be triggered by UID != 0, I'll send a hotfix
patch for the 2.6.11.x line, too. This patch is only compile-tested.

2005-03-20 21:31:06

by Bodo Eggert

[permalink] [raw]
Subject: [PATCH 2.6.11.2][1/2] printk with anti-cluttering-feature

Introduce printk_nospam, which will prevent duplicate and excessive
printing.

Signed-Off-By: Bodo Eggert <[email protected]>

diff -purNXdontdiff linux-2.6.11/include/linux/kernel.h linux-2.6.11.new/include/linux/kernel.h
--- linux-2.6.11/include/linux/kernel.h 2005-03-03 15:42:13.000000000 +0100
+++ linux-2.6.11.new/include/linux/kernel.h 2005-03-20 21:15:23.000000000 +0100
@@ -104,6 +104,12 @@ extern int session_of_pgrp(int pgrp);
asmlinkage int vprintk(const char *fmt, va_list args);
asmlinkage int printk(const char * fmt, ...)
__attribute__ ((format (printf, 1, 2)));
+asmlinkage int printk_nospam(unsigned int magic, const char * fmt, ...)
+ __attribute__ ((format (printf, 2, 3)));
+/* Don't print the previously printed message had the same magic or the rate
+ limit would be exceeded.
+ Hint: Use a unique random value for the magic, e.g. the first value from
+ cksum on the file you're editing */

unsigned long int_sqrt(unsigned long);

diff -purNXdontdiff linux-2.6.11/kernel/printk.c linux-2.6.11.new/kernel/printk.c
--- linux-2.6.11/kernel/printk.c 2005-03-18 21:54:35.000000000 +0100
+++ linux-2.6.11.new/kernel/printk.c 2005-03-20 21:15:14.000000000 +0100
@@ -115,6 +115,8 @@ static int preferred_console = -1;
/* Flag: console code may call schedule() */
static int console_may_schedule;

+static int antispam_magic;
+
/*
* Setup a list of consoles. Called from init/main.c
*/
@@ -517,6 +519,26 @@ asmlinkage int printk(const char *fmt, .
va_list args;
int r;

+ antispam_magic = 0;
+
+ va_start(args, fmt);
+ r = vprintk(fmt, args);
+ va_end(args);
+
+ return r;
+}
+
+asmlinkage int printk_nospam(unsigned int magic, const char *fmt, ...)
+{
+ va_list args;
+ int r;
+
+ if (magic == antispam_magic)
+ return 0;
+ if (!printk_ratelimit())
+ return 0;
+ antispam_magic = magic;
+
va_start(args, fmt);
r = vprintk(fmt, args);
va_end(args);
@@ -591,6 +613,7 @@ out:
return printed_len;
}
EXPORT_SYMBOL(printk);
+EXPORT_SYMBOL(printk_nospam);
EXPORT_SYMBOL(vprintk);

/**

2005-03-20 21:39:05

by Bodo Eggert

[permalink] [raw]
Subject: [PATCH 2.6.11.2][2/2] printk with anti-cluttering-feature

Update some functions to use printk_nospam

Signed-Off-By: Bodo Eggert <[email protected]>

diff -purNXdontdiff linux-2.6.11/drivers/block/scsi_ioctl.c linux-2.6.11.new/drivers/block/scsi_ioctl.c
--- linux-2.6.11/drivers/block/scsi_ioctl.c 2005-03-03 15:41:28.000000000 +0100
+++ linux-2.6.11.new/drivers/block/scsi_ioctl.c 2005-03-20 14:56:55.000000000 +0100
@@ -547,7 +547,7 @@ int scsi_cmd_ioctl(struct file *file, st
* old junk scsi send command ioctl
*/
case SCSI_IOCTL_SEND_COMMAND:
- printk(KERN_WARNING "program %s is using a deprecated SCSI ioctl, please convert it to SG_IO\n", current->comm);
+ printk_nospam(2296159591, KERN_WARNING "program %s is using a deprecated SCSI ioctl, please convert it to SG_IO\n", current->comm);
err = -EINVAL;
if (!arg)
break;
diff -purNXdontdiff linux-2.6.11/drivers/input/keyboard/atkbd.c linux-2.6.11.new/drivers/input/keyboard/atkbd.c
--- linux-2.6.11/drivers/input/keyboard/atkbd.c 2005-03-03 15:41:33.000000000 +0100
+++ linux-2.6.11.new/drivers/input/keyboard/atkbd.c 2005-03-20 14:56:55.000000000 +0100
@@ -320,7 +320,7 @@ static irqreturn_t atkbd_interrupt(struc
atkbd_report_key(&atkbd->dev, regs, KEY_HANJA, 3);
goto out;
case ATKBD_RET_ERR:
- printk(KERN_DEBUG "atkbd.c: Keyboard on %s reports too many keys pressed.\n", serio->phys);
+ printk_nospam(2260620158, KERN_DEBUG "atkbd.c: Keyboard on %s reports too many keys pressed.\n", serio->phys);
goto out;
}

diff -purNXdontdiff linux-2.6.11/drivers/media/video/tuner.c linux-2.6.11.new/drivers/media/video/tuner.c
--- linux-2.6.11/drivers/media/video/tuner.c 2005-03-20 20:54:54.000000000 +0100
+++ linux-2.6.11.new/drivers/media/video/tuner.c 2005-03-20 14:56:55.000000000 +0100
@@ -1048,7 +1048,7 @@ static void set_tv_freq(struct i2c_clien
right now we don't have that in the config
struct and this way is still better than no
check at all */
- printk("tuner: TV freq (%d.%02d) out of range (%d-%d)\n",
+ printk_nospam(1801459135, "tuner: TV freq (%d.%02d) out of range (%d-%d)\n",
freq/16,freq%16*100/16,tv_range[0],tv_range[1]);
return;
}

2005-03-20 21:41:41

by Bodo Eggert

[permalink] [raw]
Subject: [PATCH 2.6.11.2][SECURITY] printk with anti-cluttering-feature

Security fix against a log spamming DoS in tuner.c, compile-tested

Signed-Off-By: Bodo Eggert <[email protected]>

--- linux-2.6.11/drivers/media/video/tuner.c 2005-03-20 20:54:54.000000000 +0100
+++ hotfix/drivers/media/video/tuner.c 2005-03-20 21:10:33.000000000 +0100
@@ -1048,8 +1048,9 @@ static void set_tv_freq(struct i2c_clien
right now we don't have that in the config
struct and this way is still better than no
check at all */
- printk("tuner: TV freq (%d.%02d) out of range (%d-%d)\n",
- freq/16,freq%16*100/16,tv_range[0],tv_range[1]);
+ if(printk_ratelimit())
+ printk("tuner: TV freq (%d.%02d) out of range (%d-%d)\n",
+ freq/16,freq%16*100/16,tv_range[0],tv_range[1]);
return;
}
t->tv_freq(c,freq);

2005-03-21 08:21:13

by Bodo Eggert

[permalink] [raw]
Subject: Re: [PATCH 2.6.11.2][2/2] printk with anti-cluttering-feature

On Sun, 20 Mar 2005, Bodo Eggert wrote:

The new kernels have tuner.c fixed differently, removed that part.

> Update some functions to use printk_nospam
>
> Signed-Off-By: Bodo Eggert <[email protected]>
>
> diff -purNXdontdiff linux-2.6.11/drivers/block/scsi_ioctl.c linux-2.6.11.new/drivers/block/scsi_ioctl.c
> --- linux-2.6.11/drivers/block/scsi_ioctl.c 2005-03-03 15:41:28.000000000 +0100
> +++ linux-2.6.11.new/drivers/block/scsi_ioctl.c 2005-03-20 14:56:55.000000000 +0100
> @@ -547,7 +547,7 @@ int scsi_cmd_ioctl(struct file *file, st
> * old junk scsi send command ioctl
> */
> case SCSI_IOCTL_SEND_COMMAND:
> - printk(KERN_WARNING "program %s is using a deprecated SCSI ioctl, please convert it to SG_IO\n", current->comm);
> + printk_nospam(2296159591, KERN_WARNING "program %s is using a deprecated SCSI ioctl, please convert it to SG_IO\n", current->comm);
> err = -EINVAL;
> if (!arg)
> break;
> diff -purNXdontdiff linux-2.6.11/drivers/input/keyboard/atkbd.c linux-2.6.11.new/drivers/input/keyboard/atkbd.c
> --- linux-2.6.11/drivers/input/keyboard/atkbd.c 2005-03-03 15:41:33.000000000 +0100
> +++ linux-2.6.11.new/drivers/input/keyboard/atkbd.c 2005-03-20 14:56:55.000000000 +0100
> @@ -320,7 +320,7 @@ static irqreturn_t atkbd_interrupt(struc
> atkbd_report_key(&atkbd->dev, regs, KEY_HANJA, 3);
> goto out;
> case ATKBD_RET_ERR:
> - printk(KERN_DEBUG "atkbd.c: Keyboard on %s reports too many keys pressed.\n", serio->phys);
> + printk_nospam(2260620158, KERN_DEBUG "atkbd.c: Keyboard on %s reports too many keys pressed.\n", serio->phys);
> goto out;
> }
>

--
Top 100 things you don't want the sysadmin to say:
61. Yes, I chowned all the files to belong to pvcs. Is that a problem to
you?
Fri?, Spammer: [email protected] [email protected]

2005-03-21 14:58:15

by Andi Kleen

[permalink] [raw]
Subject: Re: [PATCH 2.6.11.2][RFC] printk with anti-cluttering-feature

Bodo Eggert <[email protected]> writes:
>
> atkbd.c: Keyboard on isa0060/serio0 reports too many keys pressed.
> (I'm using a keyboard switch and a IBM PS/2 keyboard)

This one should be just taken out. It is as far as I can figure out
completely useless and happens on most machines.

-Andi

2005-03-21 15:49:09

by Hugh Dickins

[permalink] [raw]
Subject: Re: [PATCH 2.6.11.2][RFC] printk with anti-cluttering-feature

On Mon, 21 Mar 2005, Andi Kleen wrote:
> Bodo Eggert <[email protected]> writes:
> >
> > atkbd.c: Keyboard on isa0060/serio0 reports too many keys pressed.
> > (I'm using a keyboard switch and a IBM PS/2 keyboard)
>
> This one should be just taken out. It is as far as I can figure out
> completely useless and happens on most machines.

Heartily seconded! I patch it out of all my kernels, I really don't
want that message every time I happen to hit an unlucky combination of
keys. It's about as irritating as every good keystroke being greeted
by "We thank you for your keystroke, and it will be echoed shortly".

Hugh

2005-03-21 18:45:52

by Bodo Eggert

[permalink] [raw]
Subject: Re: [PATCH 2.6.11.2][RFC] printk with anti-cluttering-feature

On Mon, 21 Mar 2005, Andi Kleen wrote:
> Bodo Eggert <[email protected]> writes:

> > atkbd.c: Keyboard on isa0060/serio0 reports too many keys pressed.
> > (I'm using a keyboard switch and a IBM PS/2 keyboard)
>
> This one should be just taken out. It is as far as I can figure out
> completely useless and happens on most machines.

This leaves one known user. Are there other places that might use this
feature? I asume yes, since I only fixed the message spamming my own log.

If someone gives me a pointer, I could fix those places before I submit
the updated patch. A new function for just one user would look silly.

--
Top 100 things you don't want the sysadmin to say:
56. Sorry, we deleted that package last week...

2005-03-25 00:52:10

by Bodo Eggert

[permalink] [raw]
Subject: Re: [PATCH 2.6.11.2][2/2] printk with anti-cluttering-feature

On Mon, 21 Mar 2005, Bodo Eggert wrote:
> On Sun, 20 Mar 2005, Bodo Eggert wrote:

I just sent an alternative fix kot atkbd.c, which clashes with the
previous version of this patch. This leaves un with one place where
printk_nospam is used. Just in case you still think it's usefull, here is
the modified patch.

BTW: If you're bugged by other kernel messages, I can add them, too.

> The new kernels have tuner.c fixed differently, removed that part.
>
> > Update some functions to use printk_nospam

> > Signed-Off-By: Bodo Eggert <[email protected]>
> >
> > diff -purNXdontdiff linux-2.6.11/drivers/block/scsi_ioctl.c linux-2.6.11.new/drivers/block/scsi_ioctl.c
> > --- linux-2.6.11/drivers/block/scsi_ioctl.c 2005-03-03 15:41:28.000000000 +0100
> > +++ linux-2.6.11.new/drivers/block/scsi_ioctl.c 2005-03-20 14:56:55.000000000 +0100
> > @@ -547,7 +547,7 @@ int scsi_cmd_ioctl(struct file *file, st
> > * old junk scsi send command ioctl
> > */
> > case SCSI_IOCTL_SEND_COMMAND:
> > - printk(KERN_WARNING "program %s is using a deprecated SCSI ioctl, please convert it to SG_IO\n", current->comm);
> > + printk_nospam(2296159591, KERN_WARNING "program %s is using a deprecated SCSI ioctl, please convert it to SG_IO\n", current->comm);
> > err = -EINVAL;
> > if (!arg)
> > break;
--
Funny quotes:
38. Last night I played a blank tape at full blast. The mime next door went
nuts.
Fri?, Spammer: [email protected] [email protected]

2005-03-25 01:58:58

by Bodo Eggert

[permalink] [raw]
Subject: [PATCH 2.6.11.5] atkbd: suppress debug output (was: printk with anti-cluttering-feature)

On Mon, 21 Mar 2005, Andi Kleen wrote:
> Bodo Eggert <[email protected]> writes:

> > atkbd.c: Keyboard on isa0060/serio0 reports too many keys pressed.
> > (I'm using a keyboard switch and a IBM PS/2 keyboard)
>
> This one should be just taken out. It is as far as I can figure out
> completely useless and happens on most machines.

Signed-off-by: Bodo Eggert <[email protected]>

--- linux-2.6.11/drivers/input/keyboard/atkbd.c 2005-03-20 21:50:52.000000000 +0100
+++ linux-2.6.11.new/drivers/input/keyboard/atkbd.c 2005-03-25 01:06:50.000000000 +0100
@@ -320,7 +320,9 @@ static irqreturn_t atkbd_interrupt(struc
atkbd_report_key(&atkbd->dev, regs, KEY_HANJA, 3);
goto out;
case ATKBD_RET_ERR:
+#ifdef ATKBD_DEBUG
printk(KERN_DEBUG "atkbd.c: Keyboard on %s reports too many keys pressed.\n", serio->phys);
+#endif
goto out;
}

--
If you can't remember, then the claymore IS pointed at you.

Fri?, Spammer: [email protected] [email protected]
[email protected] [email protected] [email protected]