2008-07-30 17:12:37

by Martin Schwidefsky

[permalink] [raw]
Subject: [patch 1/3] kmsg: Kernel message catalog macros.

From: Michael Holzheu <[email protected]>
From: Martin Schwidefsky <[email protected]>

Introduce a new family of printk macros which prefixes each kmsg message
with a component name and allows to tag the printk with a message id.

The kmsg component name is defined per source file with the KMSG_COMPONENT
macro. The first argument of each kmsg printk is the message id. The
message id "0" is special as it will suppress the message id prefix.

If the message id will be printed to the console / syslog at all depends
on CONFIG_MSG_IDS. If it is "n" then a kmsg_xxx call is just another
printk wrapper. These macros are intended to be used uniformly in the
s390 architecture and the s390 device drivers.

Signed-off-by: Michael Holzheu <[email protected]>
Signed-off-by: Martin Schwidefsky <[email protected]>
---

arch/s390/Kconfig | 9 +++
include/linux/kmsg.h | 124 +++++++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 133 insertions(+)

Index: linux-2.6/arch/s390/Kconfig
===================================================================
--- linux-2.6.orig/arch/s390/Kconfig
+++ linux-2.6/arch/s390/Kconfig
@@ -568,6 +568,15 @@ bool "s390 guest support (EXPERIMENTAL)"
select VIRTIO_CONSOLE
help
Select this option if you want to run the kernel under s390 linux
+
+config KMSG_IDS
+ bool "Kernel message numbers"
+ default y
+ help
+ Select this option if you want to include a message number to the
+ prefix for kernel messages issued by the s390 architecture and
+ driver code. See "Documentation/s390/kmsg.txt" for more details.
+
endmenu

source "net/Kconfig"
Index: linux-2.6/include/linux/kmsg.h
===================================================================
--- /dev/null
+++ linux-2.6/include/linux/kmsg.h
@@ -0,0 +1,124 @@
+#ifndef _LINUX_KMSG_H
+#define _LINUX_KMSG_H
+
+#ifndef __KMSG_CHECKER
+#define __KMSG_CHECK(level, id) KERN_##level
+#endif
+
+#if defined(__KMSG_CHECKER) || !defined(CONFIG_KMSG_IDS)
+
+#define kmsg_dev_alert(id, dev, format, arg...) \
+ printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_dev_err(id, dev, format, arg...) \
+ printk(__KMSG_CHECK(ERR, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_dev_warn(id, dev, format, arg...) \
+ printk(__KMSG_CHECK(WARNING, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_dev_info(id, dev, format, arg...) \
+ printk(__KMSG_CHECK(INFO, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_dev_notice(id, dev, format, arg...) \
+ printk(__KMSG_CHECK(NOTICE, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_alert(id, format, arg...) \
+ printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#define kmsg_err(id, format, arg...) \
+ printk(__KMSG_CHECK(ERR, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#define kmsg_warn(id, format, arg...) \
+ printk(__KMSG_CHECK(WARNING, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#define kmsg_info(id, format, arg...) \
+ printk(__KMSG_CHECK(INFO, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#define kmsg_notice(id, format, arg...) \
+ printk(__KMSG_CHECK(NOTICE, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#else /* __KMSG_CHECKER || !CONFIG_KMSG_IDS */
+
+#define kmsg_dev_alert(id, dev, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
+ "." #id ": %s: " format, (dev)->bus_id , ## arg) : \
+ printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_dev_err(id, dev, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(ERR, id) KMSG_COMPONENT \
+ "." #id ": %s: " format, (dev)->bus_id , ## arg) : \
+ printk(__KMSG_CHECK(ERR, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_dev_warn(id, dev, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(WARNING, id) KMSG_COMPONENT \
+ "." #id ": %s: " format, (dev)->bus_id , ## arg) : \
+ printk(__KMSG_CHECK(WARNING, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_dev_info(id, dev, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(INFO, id) KMSG_COMPONENT \
+ "." #id ": %s: " format, (dev)->bus_id , ## arg) : \
+ printk(__KMSG_CHECK(INFO, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_dev_notice(id, dev, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(NOTICE, id) KMSG_COMPONENT \
+ "." #id ": %s: " format, (dev)->bus_id , ## arg) : \
+ printk(__KMSG_CHECK(NOTICE, id) KMSG_COMPONENT \
+ ": %s: " format, (dev)->bus_id , ## arg)
+
+#define kmsg_alert(id, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
+ "." #id ": " format, ## arg) : \
+ printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#define kmsg_err(id, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(ERR, id) KMSG_COMPONENT \
+ "." #id ": " format, ## arg) : \
+ printk(__KMSG_CHECK(ERR, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#define kmsg_warn(id, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(WARNING, id) KMSG_COMPONENT \
+ "." #id ": " format, ## arg) : \
+ printk(__KMSG_CHECK(WARNING, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#define kmsg_info(id, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(INFO, id) KMSG_COMPONENT \
+ "." #id ": " format, ## arg) : \
+ printk(__KMSG_CHECK(INFO, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#define kmsg_notice(id, format, arg...) \
+ (__builtin_constant_p(id) && (id) > 0) ? \
+ printk(__KMSG_CHECK(NOTICE, id) KMSG_COMPONENT \
+ "." #id ": " format, ## arg) : \
+ printk(__KMSG_CHECK(NOTICE, id) KMSG_COMPONENT \
+ ": " format, ## arg)
+
+#endif /* __KMSG_CHECKER || !CONFIG_KMSG_IDS */
+
+#endif /* _LINUX_KMSG_H */

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.


2008-07-30 19:50:57

by Greg KH

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, Jul 30, 2008 at 06:56:57PM +0200, Martin Schwidefsky wrote:
> From: Michael Holzheu <[email protected]>
> From: Martin Schwidefsky <[email protected]>
>
> Introduce a new family of printk macros which prefixes each kmsg message
> with a component name and allows to tag the printk with a message id.
>
> The kmsg component name is defined per source file with the KMSG_COMPONENT
> macro. The first argument of each kmsg printk is the message id. The
> message id "0" is special as it will suppress the message id prefix.
>
> If the message id will be printed to the console / syslog at all depends
> on CONFIG_MSG_IDS. If it is "n" then a kmsg_xxx call is just another
> printk wrapper. These macros are intended to be used uniformly in the
> s390 architecture and the s390 device drivers.
>
> Signed-off-by: Michael Holzheu <[email protected]>
> Signed-off-by: Martin Schwidefsky <[email protected]>
> ---
>
> arch/s390/Kconfig | 9 +++
> include/linux/kmsg.h | 124 +++++++++++++++++++++++++++++++++++++++++++++++++++
> 2 files changed, 133 insertions(+)
>
> Index: linux-2.6/arch/s390/Kconfig
> ===================================================================
> --- linux-2.6.orig/arch/s390/Kconfig
> +++ linux-2.6/arch/s390/Kconfig
> @@ -568,6 +568,15 @@ bool "s390 guest support (EXPERIMENTAL)"
> select VIRTIO_CONSOLE
> help
> Select this option if you want to run the kernel under s390 linux
> +
> +config KMSG_IDS
> + bool "Kernel message numbers"
> + default y
> + help
> + Select this option if you want to include a message number to the
> + prefix for kernel messages issued by the s390 architecture and
> + driver code. See "Documentation/s390/kmsg.txt" for more details.
> +
> endmenu
>
> source "net/Kconfig"
> Index: linux-2.6/include/linux/kmsg.h
> ===================================================================
> --- /dev/null
> +++ linux-2.6/include/linux/kmsg.h
> @@ -0,0 +1,124 @@
> +#ifndef _LINUX_KMSG_H
> +#define _LINUX_KMSG_H
> +
> +#ifndef __KMSG_CHECKER
> +#define __KMSG_CHECK(level, id) KERN_##level
> +#endif

What if __KMSG_CHECKER is enabled? What does __KMSG_CHECK resolve to
then?

And what sets __KMSG_CHECKER?

thanks,

greg k-h

2008-07-30 22:02:27

by Kay Sievers

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, Jul 30, 2008 at 18:56, Martin Schwidefsky
<[email protected]> wrote:

> +#define kmsg_dev_alert(id, dev, format, arg...) \
> + printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
> + ": %s: " format, (dev)->bus_id , ## arg)

Care to use dev_name(), bus_id will be removed soon.

Thanks,
Kay

2008-07-30 22:12:29

by Greg KH

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, Jul 31, 2008 at 12:02:04AM +0200, Kay Sievers wrote:
> On Wed, Jul 30, 2008 at 18:56, Martin Schwidefsky
> <[email protected]> wrote:
>
> > +#define kmsg_dev_alert(id, dev, format, arg...) \
> > + printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
> > + ": %s: " format, (dev)->bus_id , ## arg)
>
> Care to use dev_name(), bus_id will be removed soon.

Hm, just use dev_printk() instead, it handles all of these kinds of
changes automatically.

thanks,

greg k-h

2008-07-31 08:36:26

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, 2008-07-30 at 12:39 -0700, Greg KH wrote:
> > Index: linux-2.6/include/linux/kmsg.h
> > ===================================================================
> > --- /dev/null
> > +++ linux-2.6/include/linux/kmsg.h
> > @@ -0,0 +1,124 @@
> > +#ifndef _LINUX_KMSG_H
> > +#define _LINUX_KMSG_H
> > +
> > +#ifndef __KMSG_CHECKER
> > +#define __KMSG_CHECK(level, id) KERN_##level
> > +#endif
>
> What if __KMSG_CHECKER is enabled? What does __KMSG_CHECK resolve to
> then?
>
> And what sets __KMSG_CHECKER?

The kmsg-doc script sets __KMSG_CHECKER and nothing else should ever
define it. It is used to preprocess the .c files to get at the kernel
messages. See process_cpp_file in the kmsg-doc script.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-07-31 08:36:44

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, 2008-07-31 at 00:02 +0200, Kay Sievers wrote:
> On Wed, Jul 30, 2008 at 18:56, Martin Schwidefsky
> <[email protected]> wrote:
>
> > +#define kmsg_dev_alert(id, dev, format, arg...) \
> > + printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
> > + ": %s: " format, (dev)->bus_id , ## arg)
>
> Care to use dev_name(), bus_id will be removed soon.

Yes, will do. Thanks.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-07-31 09:11:28

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, 2008-07-30 at 15:04 -0700, Greg KH wrote:
> On Thu, Jul 31, 2008 at 12:02:04AM +0200, Kay Sievers wrote:
> > On Wed, Jul 30, 2008 at 18:56, Martin Schwidefsky
> > <[email protected]> wrote:
> >
> > > +#define kmsg_dev_alert(id, dev, format, arg...) \
> > > + printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
> > > + ": %s: " format, (dev)->bus_id , ## arg)
> >
> > Care to use dev_name(), bus_id will be removed soon.
>
> Hm, just use dev_printk() instead, it handles all of these kinds of
> changes automatically.

Using dev_printk won't work because of the order of the elements of the
printk. The kmsg tag should not have a "random" position in the printk
but should be the first element. If we use dev_printk the kmsg tag will
be the third element, for other kmsg printks it will be the first. In
addition the kmsg message tag for the device drivers already includes
the driver name ..

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-05 22:37:29

by Greg KH

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, Jul 31, 2008 at 11:10:04AM +0200, Martin Schwidefsky wrote:
> On Wed, 2008-07-30 at 15:04 -0700, Greg KH wrote:
> > On Thu, Jul 31, 2008 at 12:02:04AM +0200, Kay Sievers wrote:
> > > On Wed, Jul 30, 2008 at 18:56, Martin Schwidefsky
> > > <[email protected]> wrote:
> > >
> > > > +#define kmsg_dev_alert(id, dev, format, arg...) \
> > > > + printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
> > > > + ": %s: " format, (dev)->bus_id , ## arg)
> > >
> > > Care to use dev_name(), bus_id will be removed soon.
> >
> > Hm, just use dev_printk() instead, it handles all of these kinds of
> > changes automatically.
>
> Using dev_printk won't work because of the order of the elements of the
> printk. The kmsg tag should not have a "random" position in the printk
> but should be the first element. If we use dev_printk the kmsg tag will
> be the third element, for other kmsg printks it will be the first. In
> addition the kmsg message tag for the device drivers already includes
> the driver name ..

But the structure of dev_printk() is well definied and should be pretty
trival to parse even with missing fields.

And if not, fix up dev_printk() to properly delinate when we have
missing fields, why create a totally new thing here that we need to
convert subsystems into?

thanks,

greg k-h

2008-08-06 08:39:30

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Tue, 2008-08-05 at 15:31 -0700, Greg KH wrote:
> On Thu, Jul 31, 2008 at 11:10:04AM +0200, Martin Schwidefsky wrote:
> > On Wed, 2008-07-30 at 15:04 -0700, Greg KH wrote:
> > > On Thu, Jul 31, 2008 at 12:02:04AM +0200, Kay Sievers wrote:
> > > > On Wed, Jul 30, 2008 at 18:56, Martin Schwidefsky
> > > > <[email protected]> wrote:
> > > >
> > > > > +#define kmsg_dev_alert(id, dev, format, arg...) \
> > > > > + printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
> > > > > + ": %s: " format, (dev)->bus_id , ## arg)
> > > >
> > > > Care to use dev_name(), bus_id will be removed soon.
> > >
> > > Hm, just use dev_printk() instead, it handles all of these kinds of
> > > changes automatically.
> >
> > Using dev_printk won't work because of the order of the elements of the
> > printk. The kmsg tag should not have a "random" position in the printk
> > but should be the first element. If we use dev_printk the kmsg tag will
> > be the third element, for other kmsg printks it will be the first. In
> > addition the kmsg message tag for the device drivers already includes
> > the driver name ..
>
> But the structure of dev_printk() is well definied and should be pretty
> trival to parse even with missing fields.

The missing field is the message tag. Which is the key for the message
lookup. As far as the kmsg catalog is concerned this is a pretty
important field that may not be missing from the printk itself.

> And if not, fix up dev_printk() to properly delinate when we have
> missing fields, why create a totally new thing here that we need to
> convert subsystems into?

To "fix" dev_printk would mean to add the message tag. Which requires to
change all callers. The better approach is to add a new printk wrapper
and decide for each subsystem if it shouuld be converted. I'm not
advocating to change everything. The kmsg macros is a way to document
the message from a piece of code if you choose to use these macros.

What could be done is to move the kmsg_dev_xxx macros to
include/linux/device.h if you want to keep all device printk related
definitions in one place. Would that be more acceptable ?

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-06 20:15:56

by Greg KH

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, Aug 06, 2008 at 10:35:16AM +0200, Martin Schwidefsky wrote:
> On Tue, 2008-08-05 at 15:31 -0700, Greg KH wrote:
> > On Thu, Jul 31, 2008 at 11:10:04AM +0200, Martin Schwidefsky wrote:
> > > On Wed, 2008-07-30 at 15:04 -0700, Greg KH wrote:
> > > > On Thu, Jul 31, 2008 at 12:02:04AM +0200, Kay Sievers wrote:
> > > > > On Wed, Jul 30, 2008 at 18:56, Martin Schwidefsky
> > > > > <[email protected]> wrote:
> > > > >
> > > > > > +#define kmsg_dev_alert(id, dev, format, arg...) \
> > > > > > + printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
> > > > > > + ": %s: " format, (dev)->bus_id , ## arg)
> > > > >
> > > > > Care to use dev_name(), bus_id will be removed soon.
> > > >
> > > > Hm, just use dev_printk() instead, it handles all of these kinds of
> > > > changes automatically.
> > >
> > > Using dev_printk won't work because of the order of the elements of the
> > > printk. The kmsg tag should not have a "random" position in the printk
> > > but should be the first element. If we use dev_printk the kmsg tag will
> > > be the third element, for other kmsg printks it will be the first. In
> > > addition the kmsg message tag for the device drivers already includes
> > > the driver name ..
> >
> > But the structure of dev_printk() is well definied and should be pretty
> > trival to parse even with missing fields.
>
> The missing field is the message tag. Which is the key for the message
> lookup. As far as the kmsg catalog is concerned this is a pretty
> important field that may not be missing from the printk itself.

No, I mean use dev_printk() as the base for your logging macro. Add
your message tag as the first field after the dev_printk() information.

thanks,

greg k-h

2008-08-07 08:33:28

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, 2008-08-06 at 13:07 -0700, Greg KH wrote:
> > > > Using dev_printk won't work because of the order of the elements of the
> > > > printk. The kmsg tag should not have a "random" position in the printk
> > > > but should be the first element. If we use dev_printk the kmsg tag will
> > > > be the third element, for other kmsg printks it will be the first. In
> > > > addition the kmsg message tag for the device drivers already includes
> > > > the driver name ..
> > >
> > > But the structure of dev_printk() is well definied and should be pretty
> > > trival to parse even with missing fields.
> >
> > The missing field is the message tag. Which is the key for the message
> > lookup. As far as the kmsg catalog is concerned this is a pretty
> > important field that may not be missing from the printk itself.
>
> No, I mean use dev_printk() as the base for your logging macro. Add
> your message tag as the first field after the dev_printk() information.

Hmm, you are proposing to introduce a second format for the kmsg
messages to avoid the need for some more printk wrapper macros. To me it
seems that this has two problems:
1) The message tag is for the user of the system. If it does not have a
fixed position it gets confusing.
2) The message tag for a driver message usually already includes the
driver name, the dev_printk will print it again. This is ugly and
reduces the quality of the message.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-07 16:11:31

by Joe Perches

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, 2008-08-07 at 10:31 +0200, Martin Schwidefsky wrote:
> On Wed, 2008-08-06 at 13:07 -0700, Greg KH wrote:
> > No, I mean use dev_printk() as the base for your logging macro. Add
> > your message tag as the first field after the dev_printk() information.
> Hmm, you are proposing to introduce a second format for the kmsg
> messages to avoid the need for some more printk wrapper macros. To me it
> seems that this has two problems:
> 1) The message tag is for the user of the system. If it does not have a
> fixed position it gets confusing.

I think the message tag today is not useful for a user.

It seems a barely useful maintainer value.

Perhaps the message tag allows for run-time language
translation and maybe a bit better selective logging.

> 2) The message tag for a driver message usually already includes the
> driver name, the dev_printk will print it again. This is ugly and
> reduces the quality of the message.

Ugly is a beholder problem.

Either printk or dev_printk could reorder the output.

2008-08-07 17:15:07

by Greg KH

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, Aug 07, 2008 at 10:31:41AM +0200, Martin Schwidefsky wrote:
> On Wed, 2008-08-06 at 13:07 -0700, Greg KH wrote:
> > > > > Using dev_printk won't work because of the order of the elements of the
> > > > > printk. The kmsg tag should not have a "random" position in the printk
> > > > > but should be the first element. If we use dev_printk the kmsg tag will
> > > > > be the third element, for other kmsg printks it will be the first. In
> > > > > addition the kmsg message tag for the device drivers already includes
> > > > > the driver name ..
> > > >
> > > > But the structure of dev_printk() is well definied and should be pretty
> > > > trival to parse even with missing fields.
> > >
> > > The missing field is the message tag. Which is the key for the message
> > > lookup. As far as the kmsg catalog is concerned this is a pretty
> > > important field that may not be missing from the printk itself.
> >
> > No, I mean use dev_printk() as the base for your logging macro. Add
> > your message tag as the first field after the dev_printk() information.
>
> Hmm, you are proposing to introduce a second format for the kmsg
> messages to avoid the need for some more printk wrapper macros. To me it
> seems that this has two problems:

No, only 1 format, use dev_printk() instead of printk() in your macro.

> 1) The message tag is for the user of the system. If it does not have a
> fixed position it gets confusing.

How would it not be in a fixed position with dev_printk()?

> 2) The message tag for a driver message usually already includes the
> driver name, the dev_printk will print it again. This is ugly and
> reduces the quality of the message.

Then the message needs to change and remove that "driver name", as it is
redundant, saving a tiny ammount of space :)

thanks,

greg k-h

2008-08-10 00:04:47

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, 2008-08-07 at 10:01 -0700, Greg KH wrote:
> On Thu, Aug 07, 2008 at 10:31:41AM +0200, Martin Schwidefsky wrote:
> > On Wed, 2008-08-06 at 13:07 -0700, Greg KH wrote:
> > > > > > Using dev_printk won't work because of the order of the elements of the
> > > > > > printk. The kmsg tag should not have a "random" position in the printk
> > > > > > but should be the first element. If we use dev_printk the kmsg tag will
> > > > > > be the third element, for other kmsg printks it will be the first. In
> > > > > > addition the kmsg message tag for the device drivers already includes
> > > > > > the driver name ..
> > > > >
> > > > > But the structure of dev_printk() is well definied and should be pretty
> > > > > trival to parse even with missing fields.
> > > >
> > > > The missing field is the message tag. Which is the key for the message
> > > > lookup. As far as the kmsg catalog is concerned this is a pretty
> > > > important field that may not be missing from the printk itself.
> > >
> > > No, I mean use dev_printk() as the base for your logging macro. Add
> > > your message tag as the first field after the dev_printk() information.
> >
> > Hmm, you are proposing to introduce a second format for the kmsg
> > messages to avoid the need for some more printk wrapper macros. To me it
> > seems that this has two problems:
>
> No, only 1 format, use dev_printk() instead of printk() in your macro.

No, there are more printks in the system then just dev_printk. The kmsg interface
is supposed to cover all of them.

> > 1) The message tag is for the user of the system. If it does not have a
> > fixed position it gets confusing.
>
> How would it not be in a fixed position with dev_printk()?

It is fixed in the macro for standard kmsg printks, there the message
tag is the first field. It is fixed in the macro for the dev_printk
variant of the kmsg message, there it is the third field. This mismatch
I refer to as not have a fixed position, for some message (the standard
ones) it is at the start of the final message, for others (the
dev_printk ones) it is in the middle of the message. Not good.

> > 2) The message tag for a driver message usually already includes the
> > driver name, the dev_printk will print it again. This is ugly and
> > reduces the quality of the message.
>
> Then the message needs to change and remove that "driver name", as it is
> redundant, saving a tiny ammount of space :)

Then lets look at how this will look like. First a standard printk
message and its conversion to kmsg:
printk(KERN_WARNING
"cpcmd: could not allocate response buffer\n");
vs.
kmsg_warn(1, "The cpcmd kernel function failed "
"to allocate a response buffer\n");

The message comes out as
cpcmd: cound not allocate response buffer
vs.
cpcmd.1: The cpcmd kernel function failed to allocate a response buffer

As an example for a dev_printk I use a message from the zfcp driver:
dev_warn(&req->adapter->ccw_device->dev,
"The local link is down: no light detected.\n");
vs.
kmsg_dev_warn(27, &req->adapter->ccw_device->dev,
"The local link is down: no light detected.\n");

The dev_printk versus the original kmsg macro comes out as
zfcp: 0.0.1234: The local link is down: no light detected.
vs.
zfcp.27: 0.0.1234: The local link is down: no light detected.

If I would just use dev_printk in kmsg_dev_warn as proposed by Greg:
zfcp: 0.0.1234: zfcp.27: The local link is down: no light detected.

If the message component is skipped from the message tag:
zfcp: 0.0.1234: 27: The local link is down: no light detected.

Is it just me who thinks that the later two message variants are crap?

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.


2008-08-10 00:08:52

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, 2008-08-07 at 08:59 -0700, Joe Perches wrote:
> On Thu, 2008-08-07 at 10:31 +0200, Martin Schwidefsky wrote:
> > On Wed, 2008-08-06 at 13:07 -0700, Greg KH wrote:
> > > No, I mean use dev_printk() as the base for your logging macro. Add
> > > your message tag as the first field after the dev_printk() information.
> > Hmm, you are proposing to introduce a second format for the kmsg
> > messages to avoid the need for some more printk wrapper macros. To me it
> > seems that this has two problems:
> > 1) The message tag is for the user of the system. If it does not have a
> > fixed position it gets confusing.
>
> I think the message tag today is not useful for a user.
>
> It seems a barely useful maintainer value.
>
> Perhaps the message tag allows for run-time language
> translation and maybe a bit better selective logging.

Aehhm, .. what ? If a user does not understand a message directly
how can he NOT be interested in the kmsg tag? As a random example
consider the situation when the user gets the message

monwriter.1: Writing monitor data failed with rc=5

Usually a user will go "Huh?" except if he is a z/VM expert. Looking
at the source code won't help too much either:

static int monwrite_diag(struct monwrite_hdr *myhdr, char *buffer, int fcn)
{
struct appldata_product_id id;
int rc;

strcpy(id.prod_nr, "LNXAPPL");
id.prod_fn = myhdr->applid;
id.record_nr = myhdr->record_num;
id.version_nr = myhdr->version;
id.release_nr = myhdr->release;
id.mod_lvl = myhdr->mod_level;
rc = appldata_asm(&id, fcn, (void *) buffer, myhdr->datalen);
if (rc <= 0)
return rc;
if (rc == 5)
return -EPERM;
kmsg_err(1,"Writing monitor data failed with rc=%i\n", rc);
return -EINVAL;
}

What the user should do is to cut-copy-paste the kmsg tag monwriter.1
and pass it to man:

# man monwriter.1

What the user will then get is the man page that has been generated
from the kmsg comment with "make D=2":

--- snip
monwriter.1(9) monwriter.1(9)

Message
monwriter.1: Writing monitor data failed with rc=%i

Severity
Error

Parameters
@1: return code

Description
The monitor stream application device driver used the z/VM diagnose
call DIAG X'DC' to start writing monitor data. z/VM returned an error
and the monitor data cannot be written. If the return code is 5, your
z/VM guest virtual machine is not authorized to write monitor data.

User action
If the return code is 5, ensure that your z/VM guest virtual machine's
entry in the z/VM directory includes the OPTION APPLMON statement. For
other return codes see the section about DIAGNOSE Code X'DC' in "z/VM
CP Programming Services".

LINUX Linux Messages monwriter.1(9)
--- snip

Now the user actually gets help: the description tells him that rc=5
probably is because the virtual machine is not authorized. The key to
be able to get to the description associated to a message is the kmsg
tag.

By the way the kmsg comment for monwriter.1 is as follows just in case
you are wondering:

/*?
* Tag: monwriter.1
* Text: "Writing monitor data failed with rc=%i"
* Severity: Error
* Parameter:
* @1: return code
* Description:
* The monitor stream application device driver used the z/VM diagnose call
* DIAG X'DC' to start writing monitor data. z/VM returned an error and the
* monitor data cannot be written. If the return code is 5, your z/VM guest
* virtual machine is not authorized to write monitor data.
* User action:
* If the return code is 5, ensure that your z/VM guest virtual machine's
* entry in the z/VM directory includes the OPTION APPLMON statement.
* For other return codes see the section about DIAGNOSE Code X'DC'
* in "z/VM CP Programming Services".
*/

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-11 10:55:06

by Jan Kara

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Sun 10-08-08 02:03:41, Martin Schwidefsky wrote:
...
> Then lets look at how this will look like. First a standard printk
> message and its conversion to kmsg:
> printk(KERN_WARNING
> "cpcmd: could not allocate response buffer\n");
> vs.
> kmsg_warn(1, "The cpcmd kernel function failed "
> "to allocate a response buffer\n");
>
> The message comes out as
> cpcmd: cound not allocate response buffer
> vs.
> cpcmd.1: The cpcmd kernel function failed to allocate a response buffer
>
> As an example for a dev_printk I use a message from the zfcp driver:
> dev_warn(&req->adapter->ccw_device->dev,
> "The local link is down: no light detected.\n");
> vs.
> kmsg_dev_warn(27, &req->adapter->ccw_device->dev,
> "The local link is down: no light detected.\n");
>
> The dev_printk versus the original kmsg macro comes out as
> zfcp: 0.0.1234: The local link is down: no light detected.
> vs.
> zfcp.27: 0.0.1234: The local link is down: no light detected.
>
> If I would just use dev_printk in kmsg_dev_warn as proposed by Greg:
> zfcp: 0.0.1234: zfcp.27: The local link is down: no light detected.
>
> If the message component is skipped from the message tag:
> zfcp: 0.0.1234: 27: The local link is down: no light detected.
>
> Is it just me who thinks that the later two message variants are crap?
If I may vote in this poll ;) I agree with you that the first two device
messages look better (more comprehensible) than the last two...

Honza
--
Jan Kara <[email protected]>
SUSE Labs, CR

2008-08-13 00:35:36

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, Jul 30, 2008 at 9:56 AM, Martin Schwidefsky
<[email protected]> wrote:
> From: Michael Holzheu <[email protected]>
> From: Martin Schwidefsky <[email protected]>
>
> Introduce a new family of printk macros which prefixes each kmsg message
> with a component name and allows to tag the printk with a message id.

We've been talking about doing something like this, just this week. AKPM
pointed me at this thread. Good timing. :)

> +#define kmsg_dev_alert(id, dev, format, arg...) \
> + printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
> + ": %s: " format, (dev)->bus_id , ## arg)

Rather than the gcc-specific '## arg', shouldn't we use the standard C99
form: '##__VA_ARGS__' ?

As a format, I would argue to leave out the spaces after colons, making
the inevitable string splitting even easier.

I don't care for the magic file-global KMSG_COMPONENT. It just feels
wrong. In most cases, I want the prefix to be hierarchical. For example,
rather than "tg3" I want "net.tg3" or "netdev:tg3" or something.

Further, We want to make a clearer denotation between "just another
printk()" and these things, which are really "important events". Maybe a
global prefix that makes it easy to seperate them out? Or a parallel
"event" interface that logs to printk() and a netlink socket?


Tim

2008-08-13 04:33:19

by Rusty Russell

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thursday 31 July 2008 02:56:57 Martin Schwidefsky wrote:
> From: Michael Holzheu <[email protected]>
> From: Martin Schwidefsky <[email protected]>
>
> Introduce a new family of printk macros which prefixes each kmsg message
> with a component name and allows to tag the printk with a message id.

Can you hash the format string to generate the id? 6 hex digits should be
enough, and your tool can check for clashes. As it's bad form to have
identical strings for different semantics anyway, this seems to make sense.

Rusty.

2008-08-13 07:04:28

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

But there are a number of places that have different strings for the
same meaning: "Can't" vs "can't" vs "can not" vs "failed to", etc.

This is a big part of what hurts us - you end up with lots of loose
regexes when parsing logs.

Tim



On Tue, Aug 12, 2008 at 9:33 PM, Rusty Russell <[email protected]> wrote:
> On Thursday 31 July 2008 02:56:57 Martin Schwidefsky wrote:
>> From: Michael Holzheu <[email protected]>
>> From: Martin Schwidefsky <[email protected]>
>>
>> Introduce a new family of printk macros which prefixes each kmsg message
>> with a component name and allows to tag the printk with a message id.
>
> Can you hash the format string to generate the id? 6 hex digits should be
> enough, and your tool can check for clashes. As it's bad form to have
> identical strings for different semantics anyway, this seems to make sense.
>
> Rusty.
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/
>

2008-08-13 07:48:58

by Pavel Machek

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

Hi!

> But there are a number of places that have different strings for the
> same meaning: "Can't" vs "can't" vs "can not" vs "failed to", etc.

Do you have examples?

That wastes space in bzImage (and hints of duplicated code), so we may
want to fix it anyway.

Pavel

--
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

2008-08-13 14:50:41

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, Aug 13, 2008 at 12:13 AM, Pavel Machek <[email protected]> wrote:
> Hi!
>
>> But there are a number of places that have different strings for the
>> same meaning: "Can't" vs "can't" vs "can not" vs "failed to", etc.
>
> Do you have examples?
>
> That wastes space in bzImage (and hints of duplicated code), so we may
> want to fix it anyway.

I can look for the specific examples. I just saw the regexes we use
this week and was taken aback at how they have been loosened for these
sorts of cases.

2008-08-14 04:15:09

by Rusty Russell

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wednesday 13 August 2008 17:04:11 Tim Hockin wrote:
> But there are a number of places that have different strings for the
> same meaning: "Can't" vs "can't" vs "can not" vs "failed to", etc.
>
> This is a big part of what hurts us - you end up with lots of loose
> regexes when parsing logs.

Well, if they're to be the same messages under the manual-numbering scheme,
someone has to verify that they are really the same anyway. Not much more
work to simply fix them in that case, is it?

If it improves normal kernel messages, then everyone wins.
Rusty.

2008-08-14 15:40:46

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Aug 13, 2008 9:15 PM, "Rusty Russell" <[email protected]> wrote:

> On Wednesday 13 August 2008 17:04:11 Tim Hockin wrote:
>> But there are a number of places that have ...Well, if they're to be the
>> same messages under the manual-numbering scheme,
>
> someone has to verify that they are really the same anyway. Not much more
> work to simply fix them in that case, is it?
>
> If it improves normal kernel messages, then everyone wins.

Oh, I agree with that. I personally don't care much for the msg ID part of
this patch (I mean I don't care either way). It might be nice to have man
pages, but I just see it becoming out of sync, duplicate numbers, etc.

What I want to see is the elevation of these call-sites from "it's just a
printk()" to "it's a report-worthy event and part of our user<->kernel API". I
want people to add them when it's appropriate and then not change the strings
later. I don't care if, in the end, they are structured strings. I do care if
I have to run dozens of regexes against thousands of log-lines on thousands of
systems.

:)

Tim

2008-08-14 17:05:06

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Tue, 2008-08-12 at 17:35 -0700, Tim Hockin wrote:
> On Wed, Jul 30, 2008 at 9:56 AM, Martin Schwidefsky
> <[email protected]> wrote:
> > From: Michael Holzheu <[email protected]>
> > From: Martin Schwidefsky <[email protected]>
> >
> > Introduce a new family of printk macros which prefixes each kmsg message
> > with a component name and allows to tag the printk with a message id.
>
> We've been talking about doing something like this, just this week. AKPM
> pointed me at this thread. Good timing. :)

Good to hear that we are not the only one working on this.

> > +#define kmsg_dev_alert(id, dev, format, arg...) \
> > + printk(__KMSG_CHECK(ALERT, id) KMSG_COMPONENT \
> > + ": %s: " format, (dev)->bus_id , ## arg)
>
> Rather than the gcc-specific '## arg', shouldn't we use the standard C99
> form: '##__VA_ARGS__' ?

Ok, I changed the macros accordingly.

> As a format, I would argue to leave out the spaces after colons, making
> the inevitable string splitting even easier.

Makes sense and it does not make the message harder to read.

> I don't care for the magic file-global KMSG_COMPONENT. It just feels
> wrong. In most cases, I want the prefix to be hierarchical. For example,
> rather than "tg3" I want "net.tg3" or "netdev:tg3" or something.

But what is the alternative to the #define to specify the base name of
the message tag? KBUILD_MODNAME has been proposed but I don't think this
is a good idea since I want the message tags to be independent of the
code structure.

> Further, We want to make a clearer denotation between "just another
> printk()" and these things, which are really "important events". Maybe a
> global prefix that makes it easy to seperate them out? Or a parallel
> "event" interface that logs to printk() and a netlink socket?

Well the kmsg macros distinguish between id==0 and id>0 messages. For a
id==0 message there is no documentation required and the kmsg prefix
will be just the KMSG_COMPONENT. You could consider that to be "just
another printk". For id>0 the kmsg macros will create the tuppel
KMSG_COMPONENT.ID so you already can separate "normal" and "important"
prinkts.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-14 17:08:11

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, 2008-08-13 at 14:33 +1000, Rusty Russell wrote:
> On Thursday 31 July 2008 02:56:57 Martin Schwidefsky wrote:
> > From: Michael Holzheu <[email protected]>
> > From: Martin Schwidefsky <[email protected]>
> >
> > Introduce a new family of printk macros which prefixes each kmsg message
> > with a component name and allows to tag the printk with a message id.
>
> Can you hash the format string to generate the id? 6 hex digits should be
> enough, and your tool can check for clashes. As it's bad form to have
> identical strings for different semantics anyway, this seems to make sense.

First, how do you do that with the C preprocessor? Second the kmsg-doc
script will check that the message format strings match if a kmsg with a
specific id is used in multiple locations.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-14 17:12:58

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, 2008-08-14 at 08:40 -0700, Tim Hockin wrote:
> On Aug 13, 2008 9:15 PM, "Rusty Russell" <[email protected]> wrote:
>
> > On Wednesday 13 August 2008 17:04:11 Tim Hockin wrote:
> >> But there are a number of places that have ...Well, if they're to be the
> >> same messages under the manual-numbering scheme,
> >
> > someone has to verify that they are really the same anyway. Not much more
> > work to simply fix them in that case, is it?
> >
> > If it improves normal kernel messages, then everyone wins.
>
> Oh, I agree with that. I personally don't care much for the msg ID part of
> this patch (I mean I don't care either way). It might be nice to have man
> pages, but I just see it becoming out of sync, duplicate numbers, etc.

No, the kmsg-doc script will prevent that the kmsg message will become
of of sync and it checks for duplicate numbers. The idea here is that
the kmsg man pages are generated with the kernel compile (just try it
with "make D=2").

> What I want to see is the elevation of these call-sites from "it's just a
> printk()" to "it's a report-worthy event and part of our user<->kernel API". I
> want people to add them when it's appropriate and then not change the strings
> later. I don't care if, in the end, they are structured strings. I do care if
> I have to run dozens of regexes against thousands of log-lines on thousands of
> systems.
>
> :)

Yes, and this has already happened with the s390 device driver messages.
With the conversion to kmsg our developers removed a lot of crud from
the code, this alone makes it worthwhile.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-14 18:50:29

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, Aug 14, 2008 at 10:04 AM, Martin Schwidefsky
<[email protected]> wrote:

>> I don't care for the magic file-global KMSG_COMPONENT. It just feels
>> wrong. In most cases, I want the prefix to be hierarchical. For example,
>> rather than "tg3" I want "net.tg3" or "netdev:tg3" or something.
>
> But what is the alternative to the #define to specify the base name of
> the message tag? KBUILD_MODNAME has been proposed but I don't think this
> is a good idea since I want the message tags to be independent of the
> code structure.

We had talked internally about something like this:

globally:

// this is the actual implementation
extern void send_kmsg(int level, const char *fmt, ...);

// this is a convenience wrapper, maybe not needed as they get combinatoric
#define kmsg_err(fmt, ...) \
send_kmsg(KERN_ERROR, fmt, ##__VA_ARGS__)

inside a subsystem-specific header:

#define mysubsys_kmsg_err(fmt, ...) \
kmsg_err("mysubsys:" fmt "\n", ##__VA_ARGS__)

inside each subsystem-driver:

#define mydriver_kmsg_err(fmt, ...) \
mysubsys_kmsg_err("mydriver:" fmt, ##__VA_ARGS__)

then the driver just calls:

mydriver_kmsg_err("something happened");

and you get, at the bottom:

printk(KERN_ERROR "mysubsy:mydriver:something happened\n");

I'm not sure how your ID number fits in there, propbably

printk(KERN_ERROR "mysubsy:mydriver.%d something happened\n", id);

That way, the hierarchy is defined by the meaningful hierarchy of
subsystems and busses and drivers. Subsystems which have device structs
can add them into the mix (netdev, ATA, etc). The core infrastructure
stays small, while providing driver and subsys maintainers the flexibility
to define their own event hierarchies.

>> Further, We want to make a clearer denotation between "just another
>> printk()" and these things, which are really "important events". Maybe a
>> global prefix that makes it easy to seperate them out? Or a parallel
>> "event" interface that logs to printk() and a netlink socket?
>
> Well the kmsg macros distinguish between id==0 and id>0 messages. For a
> id==0 message there is no documentation required and the kmsg prefix
> will be just the KMSG_COMPONENT. You could consider that to be "just
> another printk". For id>0 the kmsg macros will create the tuppel
> KMSG_COMPONENT.ID so you already can separate "normal" and "important"
> prinkts.

That works, I suppose. I'd still advocate for a netlink-style conduit
(maybe with buffering?) for "important event" kmsgs, separate from plain
old printk.

I'd also advocate that maybe we should go a bit further with the
structure, by providing a soft-structured set of key-value pairs. I'm not
100% on the details, but something like:

printk(KERN_ERROR
"mysubsy:mydriver.%d something happened -- pid=%d status=0x%04x\n",
id, pid, status);

Where everything after "--" (or some other delimiter) is a key=value.

>> What I want to see is the elevation of these call-sites from "it's just a
>> printk()" to "it's a report-worthy event and part of our user<->kernel
>> API". I want people to add them when it's appropriate and then not change
>> the strings later. I don't care if, in the end, they are structured
>> strings. I do care if I have to run dozens of regexes against thousands
>> of log-lines on thousands of systems.

> Yes, and this has already happened with the s390 device driver messages.
> With the conversion to kmsg our developers removed a lot of crud from
> the code, this alone makes it worthwhile.

Do you see *every* printk() becoming a kmsg? Just printk() in drivers?
Or just some hand-chosen printk()s ?

Tim

2008-08-14 23:23:18

by Rusty Russell

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Friday 15 August 2008 03:07:03 Martin Schwidefsky wrote:
> On Wed, 2008-08-13 at 14:33 +1000, Rusty Russell wrote:
> > On Thursday 31 July 2008 02:56:57 Martin Schwidefsky wrote:
> > > From: Michael Holzheu <[email protected]>
> > > From: Martin Schwidefsky <[email protected]>
> > >
> > > Introduce a new family of printk macros which prefixes each kmsg
> > > message with a component name and allows to tag the printk with a
> > > message id.
> >
> > Can you hash the format string to generate the id? 6 hex digits should
> > be enough, and your tool can check for clashes. As it's bad form to have
> > identical strings for different semantics anyway, this seems to make
> > sense.
>
> First, how do you do that with the C preprocessor? Second the kmsg-doc
> script will check that the message format strings match if a kmsg with a
> specific id is used in multiple locations.

Well, why would you do it with the preprocessor? It's simplest to spit it out
at runtime.

The (offline) catalogger will need to generate them, of course.
Rusty.

2008-08-15 03:09:23

by Joe Perches

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, 2008-08-14 at 11:50 -0700, Tim Hockin wrote:
> // this is the actual implementation
> extern void send_kmsg(int level, const char *fmt, ...);
> // this is a convenience wrapper, maybe not needed as they get combinatoric
> #define kmsg_err(fmt, ...) \
> send_kmsg(KERN_ERROR, fmt, ##__VA_ARGS__)
> inside a subsystem-specific header:
> #define mysubsys_kmsg_err(fmt, ...) \
> kmsg_err("mysubsys:" fmt "\n", ##__VA_ARGS__)
> inside each subsystem-driver:
> #define mydriver_kmsg_err(fmt, ...) \
> mysubsys_kmsg_err("mydriver:" fmt, ##__VA_ARGS__)
> then the driver just calls:
> mydriver_kmsg_err("something happened");

I think adding system/subsystem/driver prefixes
to function names is not good.

Though Martin Schwidefsky thinks KMSG_COMPONENT is necessary,
I am unconvinced.

Perhaps using something like Jason Baron's new dynamic
debug infrastructure, all the event logging functions
could optionally print KBUILD_MODNAME, __func__ and __line__
if desired.

> Do you see *every* printk() becoming a kmsg?
> Just printk() in drivers?
> Or just some hand-chosen printk()s ?

I'd prefer every printk(KERN_<level> become pr_<level>
and kernel.h be reorganized so that all logging functions
are declared in a separate include file, maybe logging.h

kmsg_<level> could eventually live in logging.h

Here's a reorganization of kernel.h:
----------------------

Create <linux/logging.h>
Move content of <linux/ratelimit.h> into <linux/logging.h>
Delete <linux/ratelimit.h>
Move logging content from <linux/kernel.h> into <linux/logging.h>

Signed-off-by: Joe Perches <[email protected]>
---
include/linux/kernel.h | 109 +----------------------------------
include/linux/logging.h | 139 +++++++++++++++++++++++++++++++++++++++++++++
include/linux/ratelimit.h | 27 ---------
3 files changed, 141 insertions(+), 134 deletions(-)

diff --git a/include/linux/kernel.h b/include/linux/kernel.h
index 2651f80..63e647b 100644
--- a/include/linux/kernel.h
+++ b/include/linux/kernel.h
@@ -15,13 +15,11 @@
#include <linux/bitops.h>
#include <linux/log2.h>
#include <linux/typecheck.h>
-#include <linux/ratelimit.h>
+#include <linux/logging.h>
+
#include <asm/byteorder.h>
#include <asm/bug.h>

-extern const char linux_banner[];
-extern const char linux_proc_banner[];
-
#define USHORT_MAX ((u16)(~0U))
#define SHORT_MAX ((s16)(USHORT_MAX>>1))
#define SHORT_MIN (-SHORT_MAX - 1)
@@ -81,29 +79,6 @@ extern const char linux_proc_banner[];
*/
#define lower_32_bits(n) ((u32)(n))

-#define KERN_EMERG "<0>" /* system is unusable */
-#define KERN_ALERT "<1>" /* action must be taken immediately */
-#define KERN_CRIT "<2>" /* critical conditions */
-#define KERN_ERR "<3>" /* error conditions */
-#define KERN_WARNING "<4>" /* warning conditions */
-#define KERN_NOTICE "<5>" /* normal but significant condition */
-#define KERN_INFO "<6>" /* informational */
-#define KERN_DEBUG "<7>" /* debug-level messages */
-
-/*
- * Annotation for a "continued" line of log printout (only done after a
- * line that had no enclosing \n). Only to be used by core/arch code
- * during early bootup (a continued line is not SMP-safe otherwise).
- */
-#define KERN_CONT ""
-
-extern int console_printk[];
-
-#define console_loglevel (console_printk[0])
-#define default_message_loglevel (console_printk[1])
-#define minimum_console_loglevel (console_printk[2])
-#define default_console_loglevel (console_printk[3])
-
struct completion;
struct pt_regs;
struct user;
@@ -190,48 +165,8 @@ extern int kernel_text_address(unsigned long addr);
struct pid;
extern struct pid *session_of_pgrp(struct pid *pgrp);

-#ifdef CONFIG_PRINTK
-asmlinkage int vprintk(const char *fmt, va_list args)
- __attribute__ ((format (printf, 1, 0)));
-asmlinkage int printk(const char * fmt, ...)
- __attribute__ ((format (printf, 1, 2))) __cold;
-
-extern struct ratelimit_state printk_ratelimit_state;
-extern int printk_ratelimit(void);
-extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
- unsigned int interval_msec);
-#else
-static inline int vprintk(const char *s, va_list args)
- __attribute__ ((format (printf, 1, 0)));
-static inline int vprintk(const char *s, va_list args) { return 0; }
-static inline int printk(const char *s, ...)
- __attribute__ ((format (printf, 1, 2)));
-static inline int __cold printk(const char *s, ...) { return 0; }
-static inline int printk_ratelimit(void) { return 0; }
-static inline bool printk_timed_ratelimit(unsigned long *caller_jiffies, \
- unsigned int interval_msec) \
- { return false; }
-#endif
-
-extern void asmlinkage __attribute__((format(printf, 1, 2)))
- early_printk(const char *fmt, ...);
-
unsigned long int_sqrt(unsigned long);

-static inline void console_silent(void)
-{
- console_loglevel = 0;
-}
-
-static inline void console_verbose(void)
-{
- if (console_loglevel)
- console_loglevel = 15;
-}
-
-extern void bust_spinlocks(int yes);
-extern void wake_up_klogd(void);
-extern int oops_in_progress; /* If set, an oops, panic(), BUG() or die() is in progress */
extern int panic_timeout;
extern int panic_on_oops;
extern int panic_on_unrecovered_nmi;
@@ -261,22 +196,6 @@ extern enum system_states {
#define TAINT_OVERRIDDEN_ACPI_TABLE (1<<8)
#define TAINT_WARN (1<<9)

-extern void dump_stack(void) __cold;
-
-enum {
- DUMP_PREFIX_NONE,
- DUMP_PREFIX_ADDRESS,
- DUMP_PREFIX_OFFSET
-};
-extern void hex_dump_to_buffer(const void *buf, size_t len,
- int rowsize, int groupsize,
- char *linebuf, size_t linebuflen, bool ascii);
-extern void print_hex_dump(const char *level, const char *prefix_str,
- int prefix_type, int rowsize, int groupsize,
- const void *buf, size_t len, bool ascii);
-extern void print_hex_dump_bytes(const char *prefix_str, int prefix_type,
- const void *buf, size_t len);
-
extern const char hex_asc[];
#define hex_asc_lo(x) hex_asc[((x) & 0x0f)]
#define hex_asc_hi(x) hex_asc[((x) & 0xf0) >> 4]
@@ -288,30 +207,6 @@ static inline char *pack_hex_byte(char *buf, u8 byte)
return buf;
}

-#define pr_emerg(fmt, arg...) \
- printk(KERN_EMERG fmt, ##arg)
-#define pr_alert(fmt, arg...) \
- printk(KERN_ALERT fmt, ##arg)
-#define pr_crit(fmt, arg...) \
- printk(KERN_CRIT fmt, ##arg)
-#define pr_err(fmt, arg...) \
- printk(KERN_ERR fmt, ##arg)
-#define pr_warning(fmt, arg...) \
- printk(KERN_WARNING fmt, ##arg)
-#define pr_notice(fmt, arg...) \
- printk(KERN_NOTICE fmt, ##arg)
-#define pr_info(fmt, arg...) \
- printk(KERN_INFO fmt, ##arg)
-
-#ifdef DEBUG
-/* If you are writing a driver, please use dev_dbg instead */
-#define pr_debug(fmt, arg...) \
- printk(KERN_DEBUG fmt, ##arg)
-#else
-#define pr_debug(fmt, arg...) \
- ({ if (0) printk(KERN_DEBUG fmt, ##arg); 0; })
-#endif
-
/*
* Display an IP address in readable format.
*/
diff --git a/include/linux/logging.h b/include/linux/logging.h
new file mode 100644
index 0000000..63734cd
--- /dev/null
+++ b/include/linux/logging.h
@@ -0,0 +1,139 @@
+#ifndef _LINUX_LOGGING_H
+#define _LINUX_LOGGING_H
+
+#include <linux/param.h>
+
+extern const char linux_banner[];
+extern const char linux_proc_banner[];
+
+extern const char *print_tainted(void);
+
+extern int console_printk[];
+
+#define console_loglevel (console_printk[0])
+#define default_message_loglevel (console_printk[1])
+#define minimum_console_loglevel (console_printk[2])
+#define default_console_loglevel (console_printk[3])
+
+static inline void console_silent(void)
+{
+ console_loglevel = 0;
+}
+
+static inline void console_verbose(void)
+{
+ if (console_loglevel)
+ console_loglevel = 15;
+}
+
+
+#ifdef CONFIG_PRINTK
+asmlinkage int vprintk(const char *fmt, va_list args)
+ __attribute__ ((format (printf, 1, 0)));
+asmlinkage int printk(const char * fmt, ...)
+ __attribute__ ((format (printf, 1, 2))) __cold;
+
+extern struct ratelimit_state printk_ratelimit_state;
+extern int printk_ratelimit(void);
+extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
+ unsigned int interval_msec);
+#else
+static inline int vprintk(const char *s, va_list args)
+ __attribute__ ((format (printf, 1, 0)));
+static inline int vprintk(const char *s, va_list args) { return 0; }
+static inline int printk(const char *s, ...)
+ __attribute__ ((format (printf, 1, 2)));
+static inline int __cold printk(const char *s, ...) { return 0; }
+static inline int printk_ratelimit(void) { return 0; }
+static inline bool printk_timed_ratelimit(unsigned long *caller_jiffies, \
+ unsigned int interval_msec) \
+ { return false; }
+#endif
+
+extern void asmlinkage __attribute__((format(printf, 1, 2)))
+ early_printk(const char *fmt, ...);
+
+extern void dump_stack(void) __cold;
+
+enum {
+ DUMP_PREFIX_NONE,
+ DUMP_PREFIX_ADDRESS,
+ DUMP_PREFIX_OFFSET
+};
+extern void hex_dump_to_buffer(const void *buf, size_t len,
+ int rowsize, int groupsize,
+ char *linebuf, size_t linebuflen, bool ascii);
+extern void print_hex_dump(const char *level, const char *prefix_str,
+ int prefix_type, int rowsize, int groupsize,
+ const void *buf, size_t len, bool ascii);
+extern void print_hex_dump_bytes(const char *prefix_str, int prefix_type,
+ const void *buf, size_t len);
+
+#define KERN_EMERG "<0>" /* system is unusable */
+#define KERN_ALERT "<1>" /* action must be taken immediately */
+#define KERN_CRIT "<2>" /* critical conditions */
+#define KERN_ERR "<3>" /* error conditions */
+#define KERN_WARNING "<4>" /* warning conditions */
+#define KERN_NOTICE "<5>" /* normal but significant condition */
+#define KERN_INFO "<6>" /* informational */
+#define KERN_DEBUG "<7>" /* debug-level messages */
+
+/*
+ * Annotation for a "continued" line of log printout (only done after a
+ * line that had no enclosing \n). Only to be used by core/arch code
+ * during early bootup (a continued line is not SMP-safe otherwise).
+ */
+#define KERN_CONT ""
+
+#define pr_emerg(fmt, arg...) \
+ printk(KERN_EMERG fmt, ##arg)
+#define pr_alert(fmt, arg...) \
+ printk(KERN_ALERT fmt, ##arg)
+#define pr_crit(fmt, arg...) \
+ printk(KERN_CRIT fmt, ##arg)
+#define pr_err(fmt, arg...) \
+ printk(KERN_ERR fmt, ##arg)
+#define pr_warning(fmt, arg...) \
+ printk(KERN_WARNING fmt, ##arg)
+#define pr_notice(fmt, arg...) \
+ printk(KERN_NOTICE fmt, ##arg)
+#define pr_info(fmt, arg...) \
+ printk(KERN_INFO fmt, ##arg)
+
+#ifdef DEBUG
+/* If you are writing a driver, please use dev_dbg instead */
+#define pr_debug(fmt, arg...) \
+ printk(KERN_DEBUG fmt, ##arg)
+#else
+#define pr_debug(fmt, arg...) \
+ ({ if (0) printk(KERN_DEBUG fmt, ##arg); 0; })
+#endif
+
+extern void bust_spinlocks(int yes);
+extern void wake_up_klogd(void);
+extern int oops_in_progress; /* If set, an oops, panic(), BUG() or die() is in progress */
+
+#define DEFAULT_RATELIMIT_INTERVAL (5 * HZ)
+#define DEFAULT_RATELIMIT_BURST 10
+
+struct ratelimit_state {
+ int interval;
+ int burst;
+ int printed;
+ int missed;
+ unsigned long begin;
+};
+
+#define DEFINE_RATELIMIT_STATE(name, interval, burst) \
+ struct ratelimit_state name = {interval, burst,}
+
+extern int __ratelimit(struct ratelimit_state *rs);
+
+static inline int ratelimit(void)
+{
+ static DEFINE_RATELIMIT_STATE(rs, DEFAULT_RATELIMIT_INTERVAL,
+ DEFAULT_RATELIMIT_BURST);
+ return __ratelimit(&rs);
+}
+
+#endif
diff --git a/include/linux/ratelimit.h b/include/linux/ratelimit.h
deleted file mode 100644
index 18a5b9b..0000000
--- a/include/linux/ratelimit.h
+++ /dev/null
@@ -1,27 +0,0 @@
-#ifndef _LINUX_RATELIMIT_H
-#define _LINUX_RATELIMIT_H
-#include <linux/param.h>
-
-#define DEFAULT_RATELIMIT_INTERVAL (5 * HZ)
-#define DEFAULT_RATELIMIT_BURST 10
-
-struct ratelimit_state {
- int interval;
- int burst;
- int printed;
- int missed;
- unsigned long begin;
-};
-
-#define DEFINE_RATELIMIT_STATE(name, interval, burst) \
- struct ratelimit_state name = {interval, burst,}
-
-extern int __ratelimit(struct ratelimit_state *rs);
-
-static inline int ratelimit(void)
-{
- static DEFINE_RATELIMIT_STATE(rs, DEFAULT_RATELIMIT_INTERVAL,
- DEFAULT_RATELIMIT_BURST);
- return __ratelimit(&rs);
-}
-#endif

2008-08-15 03:46:43

by Greg KH

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, Aug 14, 2008 at 08:08:59PM -0700, Joe Perches wrote:
> On Thu, 2008-08-14 at 11:50 -0700, Tim Hockin wrote:
> > // this is the actual implementation
> > extern void send_kmsg(int level, const char *fmt, ...);
> > // this is a convenience wrapper, maybe not needed as they get combinatoric
> > #define kmsg_err(fmt, ...) \
> > send_kmsg(KERN_ERROR, fmt, ##__VA_ARGS__)
> > inside a subsystem-specific header:
> > #define mysubsys_kmsg_err(fmt, ...) \
> > kmsg_err("mysubsys:" fmt "\n", ##__VA_ARGS__)
> > inside each subsystem-driver:
> > #define mydriver_kmsg_err(fmt, ...) \
> > mysubsys_kmsg_err("mydriver:" fmt, ##__VA_ARGS__)
> > then the driver just calls:
> > mydriver_kmsg_err("something happened");
>
> I think adding system/subsystem/driver prefixes
> to function names is not good.

Eeek!

What is wrong with what we have already agreed to standardise on here
people? dev_printk() for devices! It uniquely shows the device, what
driver is bound to it (if any), the bus id, and everything else.

It's in a parseable, standard format, that everyone agreed a few years
was going to be the way to go!

And now you want to create your own new one? Come on, please don't be
that foolish. Please work with what we already have. Extend it or
something to have these "magic tokens" that you all want to index off
of, that's fine, I really could care less (and I really think it's going
to be a pain in the end, does everyone forget how frickin fast this
body of software moves?)

But whatever you do, don't create yet-another-printk-macro that you are
going to want everyone to use in their drivers/modules. We've already
done that, and we are still slowly converting people over to them (I did
just that for a large number USB drivers just today...)

Work off of dev_printk() and friends, don't do something new.

thanks,

greg k-h

2008-08-15 05:33:22

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, Aug 14, 2008 at 8:44 PM, Greg KH <[email protected]> wrote:
>
> What is wrong with what we have already agreed to standardise on here
> people? dev_printk() for devices! It uniquely shows the device, what
> driver is bound to it (if any), the bus id, and everything else.

Part of the problem, imho, is the "if any" part. But I am more than happy to
build on existing solutions. All the world is not a dev, though. I'd like to
be able to report something like an OOM kill in (roughly) the same way as an
ATA error, and I want (though could be talked out of) a way to tell these
"events" (for lack of a better word) apart from plain-old-printk()s.

Tim

2008-08-15 11:21:37

by Jan Blunck

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, Aug 14, Tim Hockin wrote:

> On Thu, Aug 14, 2008 at 8:44 PM, Greg KH <[email protected]> wrote:
> >
> > What is wrong with what we have already agreed to standardise on here
> > people? dev_printk() for devices! It uniquely shows the device, what
> > driver is bound to it (if any), the bus id, and everything else.
>
> Part of the problem, imho, is the "if any" part. But I am more than happy to
> build on existing solutions. All the world is not a dev, though. I'd like to
> be able to report something like an OOM kill in (roughly) the same way as an
> ATA error, and I want (though could be talked out of) a way to tell these
> "events" (for lack of a better word) apart from plain-old-printk()s.

If I interpret Martins patches correctly he wants to be able to put add
extended information to specific messages the kernel is printing. This is a
good way to explain the rational of certain situations to people unwilling to
read the sources ;)

I don't think that he wants to unify all the printk's in the system. I don't
think that reporting all errors "in the same way as an ATA error" makes any
sense. That would just lead to very stupid and unnatural messages for all
errors that are not like "ATA errors". Annotation of existing errors is a much
more flexible and feasible solution to that problem.

2008-08-15 15:40:04

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Fri, Aug 15, 2008 at 4:21 AM, Jan Blunck <[email protected]> wrote:
> On Thu, Aug 14, Tim Hockin wrote:
>
>> On Thu, Aug 14, 2008 at 8:44 PM, Greg KH <[email protected]> wrote:
>> >
>> > What is wrong with what we have already agreed to standardise on here
>> > people? dev_printk() for devices! It uniquely shows the device, what
>> > driver is bound to it (if any), the bus id, and everything else.
>>
>> Part of the problem, imho, is the "if any" part. But I am more than happy to
>> build on existing solutions. All the world is not a dev, though. I'd like to
>> be able to report something like an OOM kill in (roughly) the same way as an
>> ATA error, and I want (though could be talked out of) a way to tell these
>> "events" (for lack of a better word) apart from plain-old-printk()s.
>
> I don't think that he wants to unify all the printk's in the system. I don't
> think that reporting all errors "in the same way as an ATA error" makes any
> sense. That would just lead to very stupid and unnatural messages for all
> errors that are not like "ATA errors". Annotation of existing errors is a much
> more flexible and feasible solution to that problem.

Please don't misinterpret. I don't want to make other errors parse
like an ATA error, I want to make the plumbing be parallel. I want
one umbrella mechanism for reporting things that are more important
than just-another-printk().

Because frankly, "parse dmesg" is a pretty crappy way to have to
monitor your system for failures, and I am tired of explaining to
people why we still do that.

Tim

2008-08-15 16:06:57

by Greg KH

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Thu, Aug 14, 2008 at 10:33:10PM -0700, Tim Hockin wrote:
> On Thu, Aug 14, 2008 at 8:44 PM, Greg KH <[email protected]> wrote:
> >
> > What is wrong with what we have already agreed to standardise on here
> > people? dev_printk() for devices! It uniquely shows the device, what
> > driver is bound to it (if any), the bus id, and everything else.
>
> Part of the problem, imho, is the "if any" part. But I am more than happy to
> build on existing solutions. All the world is not a dev, though.

No, but way over half the kernel is.

> I'd like to be able to report something like an OOM kill in (roughly)
> the same way as an ATA error, and I want (though could be talked out
> of) a way to tell these "events" (for lack of a better word) apart
> from plain-old-printk()s.

That's great, then create something that can handle both! Don't throw
away some wonderful information that way over half the kernel has access
to just because the minority doesn't. That would mean that we would
loose information in those drivers overall.

thanks,

greg k-h

2008-08-15 17:03:26

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Fri, Aug 15, 2008 at 9:03 AM, Greg KH <[email protected]> wrote:

>> I'd like to be able to report something like an OOM kill in (roughly)
>> the same way as an ATA error, and I want (though could be talked out
>> of) a way to tell these "events" (for lack of a better word) apart
>> from plain-old-printk()s.
>
> That's great, then create something that can handle both! Don't throw
> away some wonderful information that way over half the kernel has access
> to just because the minority doesn't. That would mean that we would
> loose information in those drivers overall.

Sorry, I never meant to imply that dev_printk() was to be ignored, my
examples was meant to be trivial to demonstrate :) dev_printk() is
good. We should keep it :)

2008-08-15 20:43:23

by Rick Troth

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, 13 Aug 2008, Rusty Russell wrote:
>
> Can you hash the format string to generate the id? 6 hex digits should be
> enough, and your tool can check for clashes. As it's bad form to have
> identical strings for different semantics anyway, this seems to make sense.

I second this suggestion (or propose something like it).
A short hash or even an index into some off-line table
lets the user hit the right page when looking for an explanation.

I've been using a similar (and perhaps ugly to some eyes)
numeric message catalog for years (with token substitution and all).
The catalogs can be translated and then replaced with local language
so the users don't have to learn English (or French, or German,
or Japanese, or Chinese).

-- R; <><

2008-08-16 17:45:28

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Fri, 2008-08-15 at 16:05 -0400, Rick Troth wrote:
> On Wed, 13 Aug 2008, Rusty Russell wrote:
> > Can you hash the format string to generate the id? 6 hex digits should be
> > enough, and your tool can check for clashes. As it's bad form to have
> > identical strings for different semantics anyway, this seems to make sense.
>
> I second this suggestion (or propose something like it).
> A short hash or even an index into some off-line table
> lets the user hit the right page when looking for an explanation.

The kmsg id is just that, an index into the table of message for a
particular component.

> I've been using a similar (and perhaps ugly to some eyes)
> numeric message catalog for years (with token substitution and all).
> The catalogs can be translated and then replaced with local language
> so the users don't have to learn English (or French, or German,
> or Japanese, or Chinese).

That is what we are trying to achieve as well.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-16 17:50:08

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Fri, 2008-08-15 at 09:22 +1000, Rusty Russell wrote:
> On Friday 15 August 2008 03:07:03 Martin Schwidefsky wrote:
> > On Wed, 2008-08-13 at 14:33 +1000, Rusty Russell wrote:
> > > On Thursday 31 July 2008 02:56:57 Martin Schwidefsky wrote:
> > > > From: Michael Holzheu <[email protected]>
> > > > From: Martin Schwidefsky <[email protected]>
> > > >
> > > > Introduce a new family of printk macros which prefixes each kmsg
> > > > message with a component name and allows to tag the printk with a
> > > > message id.
> > >
> > > Can you hash the format string to generate the id? 6 hex digits should
> > > be enough, and your tool can check for clashes. As it's bad form to have
> > > identical strings for different semantics anyway, this seems to make
> > > sense.
> >
> > First, how do you do that with the C preprocessor? Second the kmsg-doc
> > script will check that the message format strings match if a kmsg with a
> > specific id is used in multiple locations.
>
> Well, why would you do it with the preprocessor? It's simplest to spit it out
> at runtime.

Ok, so a specialized version of printk will do the work to calculate
the hash. Only, what will we do if there ever is a conflict? The message
tag has to be unique. The shorter the hash is, the more likely a
collision gets. Don't know if 6 hash digits is enough to just ignore the
problem.

> The (offline) catalogger will need to generate them, of course.
> Rusty.

Sounds doable to me.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-16 18:06:58

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Fri, 2008-08-15 at 10:03 -0700, Tim Hockin wrote:
> On Fri, Aug 15, 2008 at 9:03 AM, Greg KH <[email protected]> wrote:
> >> I'd like to be able to report something like an OOM kill in (roughly)
> >> the same way as an ATA error, and I want (though could be talked out
> >> of) a way to tell these "events" (for lack of a better word) apart
> >> from plain-old-printk()s.
> >
> > That's great, then create something that can handle both! Don't throw
> > away some wonderful information that way over half the kernel has access
> > to just because the minority doesn't. That would mean that we would
> > loose information in those drivers overall.
>
> Sorry, I never meant to imply that dev_printk() was to be ignored, my
> examples was meant to be trivial to demonstrate :) dev_printk() is
> good. We should keep it :)

The invention of dev_printk was a good thing. It adds structure to the
messages if it is about a device. Before we had a simple printk that did
or did not include information about the device driver and the device
name. dev_printk makes sure that this information is always added.
BUT, what dev_printk does not do is to make sure that the message can be
uniquely identified so that the description of the message can be found
in the message catalog. Our approach is to combine the driver name and a
simple index into a message tag. The original dev_printk remains almost
unchanged. A typical hunk in the code looks like this:

@@ -24,8 +27,8 @@ static int zfcp_ccw_probe(struct ccw_dev

down(&zfcp_data.config_sema);
if (zfcp_adapter_enqueue(ccw_device)) {
- dev_err(&ccw_device->dev,
- "Setup of data structures failed.\n");
+ kmsg_dev_err(73, &ccw_device->dev,
+ "Setup of data structures failed.\n");
retval = -EINVAL;
}
up(&zfcp_data.config_sema);

The kmsg_dev_printk still has almost the same structure, only the
message id is added. There is one real difference though:
the driver name is specified with KMSG_COMPONENT and not via
dev_driver_string(dev). We do that so that the kmsg-doc script can
actually find the driver name. The dev_driver_string(dev) is dynamic and
a static tool has a hard time to find the actual driver string.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-16 19:36:56

by Joe Perches

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Sun, 2008-08-10 at 02:08 +0200, Martin Schwidefsky wrote:
> On Thu, 2008-08-07 at 08:59 -0700, Joe Perches wrote:
> > On Thu, 2008-08-07 at 10:31 +0200, Martin Schwidefsky wrote:
> > > 1) The message tag is for the user of the system. If it does not have a
> > > fixed position it gets confusing.
> > I think the message tag today is not useful for a user.
> > It seems a barely useful maintainer value.
> > Perhaps the message tag allows for run-time language
> > translation and maybe a bit better selective logging.
> Aehhm, .. what ? If a user does not understand a message directly
> how can he NOT be interested in the kmsg tag? As a random example
> consider the situation when the user gets the message
>
> monwriter.1: Writing monitor data failed with rc=5
>
> Usually a user will go "Huh?" except if he is a z/VM expert. Looking
> at the source code won't help too much either:
>
> static int monwrite_diag(struct monwrite_hdr *myhdr, char *buffer, int fcn)
> {
> struct appldata_product_id id;
> int rc;
>
> strcpy(id.prod_nr, "LNXAPPL");
> id.prod_fn = myhdr->applid;
> id.record_nr = myhdr->record_num;
> id.version_nr = myhdr->version;
> id.release_nr = myhdr->release;
> id.mod_lvl = myhdr->mod_level;
> rc = appldata_asm(&id, fcn, (void *) buffer, myhdr->datalen);
> if (rc <= 0)
> return rc;
> if (rc == 5)
> return -EPERM;
> kmsg_err(1,"Writing monitor data failed with rc=%i\n", rc);
> return -EINVAL;
> }
>
> What the user should do is to cut-copy-paste the kmsg tag monwriter.1
> and pass it to man:
>
> # man monwriter.1
>
> What the user will then get is the man page that has been generated
> from the kmsg comment with "make D=2":
>
> --- snip
> monwriter.1(9) monwriter.1(9)
>
> Message
> monwriter.1: Writing monitor data failed with rc=%i
>
> Severity
> Error
>
> Parameters
> @1: return code
>
> Description
> The monitor stream application device driver used the z/VM diagnose
> call DIAG X'DC' to start writing monitor data. z/VM returned an error
> and the monitor data cannot be written. If the return code is 5, your
> z/VM guest virtual machine is not authorized to write monitor data.
>
> User action
> If the return code is 5, ensure that your z/VM guest virtual machine's
> entry in the z/VM directory includes the OPTION APPLMON statement. For
> other return codes see the section about DIAGNOSE Code X'DC' in "z/VM
> CP Programming Services".

Doesn't this example better illustrate the barely useful
user value of such a message and documentation?

In your example, monwriter.1 with a return code of 5 isn't possible.

2008-08-16 20:48:34

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Sat, Aug 16, 2008 at 10:49 AM, Martin Schwidefsky
<[email protected]> wrote:

>> > > Can you hash the format string to generate the id? 6 hex digits should
>> > > be enough, and your tool can check for clashes. As it's bad form to have
>> > > identical strings for different semantics anyway, this seems to make
>> > > sense.

> Ok, so a specialized version of printk will do the work to calculate
> the hash. Only, what will we do if there ever is a conflict? The message
> tag has to be unique. The shorter the hash is, the more likely a
> collision gets. Don't know if 6 hash digits is enough to just ignore the
> problem.

And if you ever need to change the text that is in the format string?
The hash changes. That seems exactly counter to your goal...

Tim

2008-08-17 03:40:32

by Rick Troth

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

This is really an easy thing to do.
It can be achieved without a huge retro-fit.
It can happen even without yet another macro.
(Not saying that there should not be a new macro or new function,
just that we can enjoy unique message IDs without those mechanisms.)

Martin Schwidefsky said:
> > Ok, so a specialized version of printk will do the work to calculate
> > the hash. Only, what will we do if there ever is a conflict? The message
> > tag has to be unique. The shorter the hash is, the more likely a
> > collision gets. Don't know if 6 hash digits is enough to just ignore the
> > problem.

Point to note: the message tag has to be unique.
The tag is what's relevant, what gets catalogued.

I don't really see the value of a hash per se.
What Martin has suggested (unless I have misunderstood) is
the driver name combined with some index number ==> unique msg id.
That's not exactly a "hash". (One can generate a hash from it,
but why bother? You've got a unique string already.)

Then Tim Hockin wrote:
> And if you ever need to change the text that is in the format string?
> The hash changes. That seems exactly counter to your goal...

Whether hashed or not, what's needed is premeditated reporting,
intentional dividing between variable content (like device ID)
and the explanatory text arround it. Prefix each line with a token
(or as most are calling it, a "tag") that can be looked up off-line.

I hope no one is thinking gettext in this thread.
Don't clutter the kernel with something like gettext.

And don't burden the kernel with run-time text crunching.
Message codes go in when the module is written.
They get looked up either in user space or off-line.
Easy! Almost trivial!

-- R; <><

2008-08-17 05:11:40

by Rusty Russell

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Sunday 17 August 2008 06:40:50 Tim Hockin wrote:
> On Sat, Aug 16, 2008 at 10:49 AM, Martin Schwidefsky
>
> <[email protected]> wrote:
> >> > > Can you hash the format string to generate the id? 6 hex digits
> >> > > should be enough, and your tool can check for clashes. As it's bad
> >> > > form to have identical strings for different semantics anyway, this
> >> > > seems to make sense.
> >
> > Ok, so a specialized version of printk will do the work to calculate
> > the hash. Only, what will we do if there ever is a conflict? The message
> > tag has to be unique. The shorter the hash is, the more likely a
> > collision gets. Don't know if 6 hash digits is enough to just ignore the
> > problem.
>
> And if you ever need to change the text that is in the format string?
> The hash changes. That seems exactly counter to your goal...

You need to catalogue them all anyway, so you can detect clashes at build
time. Yes, you have to change the new string in that case, but that's easy.

And the number changing as the message changes is arguably a feature. You
shouldn't (and we generally don't) idly change kernel messages.

Rusty.

2008-08-17 17:27:56

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Sat, 2008-08-16 at 12:36 -0700, Joe Perches wrote:
> Doesn't this example better illustrate the barely useful
> user value of such a message and documentation?
>
> In your example, monwriter.1 with a return code of 5 isn't possible.

That is true, thanks for pointing out this bug. I doesn't change
anything about the need for a message documentation though, it only
proves that the documentation can have errors. At least the customers
running linux on System z want to have the documentation.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-17 17:29:30

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Sat, 2008-08-16 at 13:40 -0700, Tim Hockin wrote:
> >> > > Can you hash the format string to generate the id? 6 hex digits should
> >> > > be enough, and your tool can check for clashes. As it's bad form to have
> >> > > identical strings for different semantics anyway, this seems to make
> >> > > sense.
>
> > Ok, so a specialized version of printk will do the work to calculate
> > the hash. Only, what will we do if there ever is a conflict? The message
> > tag has to be unique. The shorter the hash is, the more likely a
> > collision gets. Don't know if 6 hash digits is enough to just ignore the
> > problem.
>
> And if you ever need to change the text that is in the format string?
> The hash changes. That seems exactly counter to your goal...

The only problem here is trivial change like typos. Then the hash
changes although the message is semantically still the same. If the
message really changes, its id should change as well.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-17 17:31:46

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Sun, Aug 17, 2008 at 10:28 AM, Martin Schwidefsky
<[email protected]> wrote:
> On Sat, 2008-08-16 at 13:40 -0700, Tim Hockin wrote:
>> >> > > Can you hash the format string to generate the id? 6 hex digits should
>> >> > > be enough, and your tool can check for clashes. As it's bad form to have
>> >> > > identical strings for different semantics anyway, this seems to make
>> >> > > sense.
>>
>> > Ok, so a specialized version of printk will do the work to calculate
>> > the hash. Only, what will we do if there ever is a conflict? The message
>> > tag has to be unique. The shorter the hash is, the more likely a
>> > collision gets. Don't know if 6 hash digits is enough to just ignore the
>> > problem.
>>
>> And if you ever need to change the text that is in the format string?
>> The hash changes. That seems exactly counter to your goal...
>
> The only problem here is trivial change like typos. Then the hash
> changes although the message is semantically still the same. If the
> message really changes, its id should change as well.

That's what I meant. Never underestimate the urge to fix the
printk(), because "hey, it's JUST A PRINTK". That's one of my
motivations - to make it no longer just a printk.

2008-08-17 17:33:45

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Sun, 2008-08-17 at 15:11 +1000, Rusty Russell wrote:
> > > Ok, so a specialized version of printk will do the work to calculate
> > > the hash. Only, what will we do if there ever is a conflict? The message
> > > tag has to be unique. The shorter the hash is, the more likely a
> > > collision gets. Don't know if 6 hash digits is enough to just ignore the
> > > problem.
> >
> > And if you ever need to change the text that is in the format string?
> > The hash changes. That seems exactly counter to your goal...
>
> You need to catalogue them all anyway, so you can detect clashes at build
> time. Yes, you have to change the new string in that case, but that's easy.

Is the suggestion that in case of a clash just change the message string
slightly to avoid the clash ?

> And the number changing as the message changes is arguably a feature. You
> shouldn't (and we generally don't) idly change kernel messages.

This is very true. If a message is touched most likely the message
description has to be changed as well. If the message hash then changes
the tools can warn about it. The small thing now only is the matter of
actually implementing the hash and changing the script to work on them..

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-18 09:23:52

by Pavel Machek

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

Hi!

> > I don't think that he wants to unify all the printk's in the system. I don't
> > think that reporting all errors "in the same way as an ATA error" makes any
> > sense. That would just lead to very stupid and unnatural messages for all
> > errors that are not like "ATA errors". Annotation of existing errors is a much
> > more flexible and feasible solution to that problem.
>
> Please don't misinterpret. I don't want to make other errors parse
> like an ATA error, I want to make the plumbing be parallel. I want
> one umbrella mechanism for reporting things that are more important
> than just-another-printk().
>
> Because frankly, "parse dmesg" is a pretty crappy way to have to
> monitor your system for failures, and I am tired of explaining to
> people why we still do that.

"parse dmesg" does not work for monitoring your system for failures;
dmesg buffer can overflow.

If something fails, you should get errno returned for userspace, and
that's where you should be doing the monitoring.

So... what parts don't return enough information to userspace so that
you need to parse dmesg? Lets fix them.
Pavel
--
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

2008-08-18 10:40:12

by Jan Kara

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Mon 18-08-08 11:23:20, Pavel Machek wrote:
> Hi!
>
> > > I don't think that he wants to unify all the printk's in the system. I don't
> > > think that reporting all errors "in the same way as an ATA error" makes any
> > > sense. That would just lead to very stupid and unnatural messages for all
> > > errors that are not like "ATA errors". Annotation of existing errors is a much
> > > more flexible and feasible solution to that problem.
> >
> > Please don't misinterpret. I don't want to make other errors parse
> > like an ATA error, I want to make the plumbing be parallel. I want
> > one umbrella mechanism for reporting things that are more important
> > than just-another-printk().
> >
> > Because frankly, "parse dmesg" is a pretty crappy way to have to
> > monitor your system for failures, and I am tired of explaining to
> > people why we still do that.
>
> "parse dmesg" does not work for monitoring your system for failures;
> dmesg buffer can overflow.
>
> If something fails, you should get errno returned for userspace, and
> that's where you should be doing the monitoring.
Yes, but there are far to few errno's to identify the problem. Imagine
how many different causes can result in EIO. Or have you ever tried to find
out why the crappy filesystem doesn't want to mount without looking into
kernel messages - the returned errno is always the same :). So I don't
think errno is a solution...

> So... what parts don't return enough information to userspace so that
> you need to parse dmesg? Lets fix them.

Honza
--
Jan Kara <[email protected]>
SUSE Labs, CR

2008-08-18 17:51:44

by Tim Hockin

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Mon, Aug 18, 2008 at 2:23 AM, Pavel Machek <[email protected]> wrote:
> Hi!
>
>> > I don't think that he wants to unify all the printk's in the system. I don't
>> > think that reporting all errors "in the same way as an ATA error" makes any
>> > sense. That would just lead to very stupid and unnatural messages for all
>> > errors that are not like "ATA errors". Annotation of existing errors is a much
>> > more flexible and feasible solution to that problem.
>>
>> Please don't misinterpret. I don't want to make other errors parse
>> like an ATA error, I want to make the plumbing be parallel. I want
>> one umbrella mechanism for reporting things that are more important
>> than just-another-printk().
>>
>> Because frankly, "parse dmesg" is a pretty crappy way to have to
>> monitor your system for failures, and I am tired of explaining to
>> people why we still do that.
>
> "parse dmesg" does not work for monitoring your system for failures;
> dmesg buffer can overflow.
>
> If something fails, you should get errno returned for userspace, and
> that's where you should be doing the monitoring.
>
> So... what parts don't return enough information to userspace so that
> you need to parse dmesg? Lets fix them.

If I get a DMA timeout on my disk, I want to know about it. If I get
an OOM kill, I want to know about it. Etc.

I *don't* want every application to participate in system monitoring,
and that's what it seems you're suggesting. I want a monitoring
daemon which is notified of important system events. We like to
report these things in various ways, including squirting them out onto
the network.

I *don't* want to run regexes against dmesg or /var/log/messages or
/var/log/kernel every N seconds, that's just a gross hack. I really
want first-class notifications of significant events. I don't mind
having to do parsing of events - as I said before, they can even be
loosely structured strings. They just need to be more important than
a plain old printk(), and preferably come through a different channel.

I understand that many users will not want this level of monitoring,
and that's why it should be flexible enough to devolve into printk().
But we have thousands of systems. I need a better view of what is
happening.

Tim

2008-08-25 16:04:35

by Martin Schwidefsky

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Wed, 2008-08-13 at 14:33 +1000, Rusty Russell wrote:
> On Thursday 31 July 2008 02:56:57 Martin Schwidefsky wrote:
> > From: Michael Holzheu <[email protected]>
> > From: Martin Schwidefsky <[email protected]>
> >
> > Introduce a new family of printk macros which prefixes each kmsg message
> > with a component name and allows to tag the printk with a message id.
>
> Can you hash the format string to generate the id? 6 hex digits should be
> enough, and your tool can check for clashes. As it's bad form to have
> identical strings for different semantics anyway, this seems to make sense.

If we go with hashes there is one more thing: kmsg(0, <string>)
The variant where we manually assign the message ids knows about the
"special" id 0. There is no documentation required for id 0 and none is
wanted. If we replace the manual ids with hashes this will get lost. You
could argue that a kmsg with id 0 is a normal printk so why not just use
printk? What is lost is the information that this printk has been found
to be not important enough to be documented.

--
blue skies,
Martin.

"Reality continues to ruin my life." - Calvin.

2008-08-26 11:55:42

by Rusty Russell

[permalink] [raw]
Subject: Re: [patch 1/3] kmsg: Kernel message catalog macros.

On Tuesday 26 August 2008 01:56:30 Martin Schwidefsky wrote:
> On Wed, 2008-08-13 at 14:33 +1000, Rusty Russell wrote:
> > Can you hash the format string to generate the id? 6 hex digits should
> > be enough, and your tool can check for clashes. As it's bad form to have
> > identical strings for different semantics anyway, this seems to make
> > sense.
>
> If we go with hashes there is one more thing: kmsg(0, <string>)
> The variant where we manually assign the message ids knows about the
> "special" id 0. There is no documentation required for id 0 and none is
> wanted. If we replace the manual ids with hashes this will get lost. You
> could argue that a kmsg with id 0 is a normal printk so why not just use
> printk? What is lost is the information that this printk has been found
> to be not important enough to be documented.

Hmm, #define KERN_IGNORE KERN_DEBUG?

Rusty.