[PATCH] reduce syslog clutter (take 2)

[PATCH] reduce syslog clutter (take 2)

[Tilman Schmidt]

[-- Attachment #1: Type: text/plain, Size: 1988 bytes --]

The current versions of the err() / info() / warn() syslog macros
insert __FILE__ at the beginning of the message, which expands to
the complete path name of the source file within the kernel tree.

With the following patch, when used in a module, they'll insert the
module name instead, which is significantly shorter and also tends to
be more useful to users trying to make sense of a particular message.

This patch replaces the one posted on 24 Feb 2006 10:50:52 +0100
which caused compile errors in non-modular drivers. It applies to
kernel 2.6.16-rc5 after the patch labeled
"add macros notice(), dev_notice() (take 2)".

Signed-off-by: Tilman Schmidt <tilman@imap.cc>
---

 usb.h |   14 ++++++++++----
 1 files changed, 10 insertions(+), 4 deletions(-)

--- linux-2.6.16-rc5-patch-splitpoint/include/linux/usb.h	2006-03-08 12:36:03.000000000 +0100
+++ linux-2.6.16-rc5-patch-splitpoint2/include/linux/usb.h	2006-03-08 12:43:07.000000000 +0100
@@ -1199,14 +1199,20 @@
 #define dbg(format, arg...) do {} while (0)
 #endif

+#if defined(CONFIG_MODULES) && defined(THIS_MODULE)
+#define KMSG_LOCATION_PREFIX THIS_MODULE ? THIS_MODULE->name : __FILE__
+#else
+#define KMSG_LOCATION_PREFIX __FILE__
+#endif
+
 #define err(format, arg...) printk(KERN_ERR "%s: " format "\n" , \
-	__FILE__ , ## arg)
+	KMSG_LOCATION_PREFIX , ## arg)
 #define info(format, arg...) printk(KERN_INFO "%s: " format "\n" , \
-	__FILE__ , ## arg)
+	KMSG_LOCATION_PREFIX , ## arg)
 #define warn(format, arg...) printk(KERN_WARNING "%s: " format "\n" , \
-	__FILE__ , ## arg)
+	KMSG_LOCATION_PREFIX , ## arg)
 #define notice(format, arg...) printk(KERN_NOTICE "%s: " format "\n" , \
-	__FILE__ , ## arg)
+	KMSG_LOCATION_PREFIX , ## arg)


 #endif  /* __KERNEL__ */

-- 
Tilman Schmidt                          E-Mail: tilman@imap.cc
Bonn, Germany
Diese Nachricht besteht zu 100% aus wiederverwerteten Bits.
Ungeöffnet mindestens haltbar bis: (siehe Rückseite)


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 253 bytes --]

Re: [PATCH] reduce syslog clutter (take 2)

[Randy.Dunlap]

On Wed, 08 Mar 2006 23:54:23 +0100 Tilman Schmidt wrote:

> The current versions of the err() / info() / warn() syslog macros
> insert __FILE__ at the beginning of the message, which expands to
> the complete path name of the source file within the kernel tree.
> 
> With the following patch, when used in a module, they'll insert the
> module name instead, which is significantly shorter and also tends to
> be more useful to users trying to make sense of a particular message.
> 
> This patch replaces the one posted on 24 Feb 2006 10:50:52 +0100
> which caused compile errors in non-modular drivers. It applies to
> kernel 2.6.16-rc5 after the patch labeled
> "add macros notice(), dev_notice() (take 2)".
> 
> Signed-off-by: Tilman Schmidt <tilman@imap.cc>
> ---
> 
>  usb.h |   14 ++++++++++----
>  1 files changed, 10 insertions(+), 4 deletions(-)
> 
> --- linux-2.6.16-rc5-patch-splitpoint/include/linux/usb.h	2006-03-08 12:36:03.000000000 +0100
> +++ linux-2.6.16-rc5-patch-splitpoint2/include/linux/usb.h	2006-03-08 12:43:07.000000000 +0100
> @@ -1199,14 +1199,20 @@
>  #define dbg(format, arg...) do {} while (0)
>  #endif
> 
> +#if defined(CONFIG_MODULES) && defined(THIS_MODULE)
> +#define KMSG_LOCATION_PREFIX THIS_MODULE ? THIS_MODULE->name : __FILE__

Can we get parens around the expression, please?

and does it make sense to test
#if defined(THIS_MODULE)
#define KMSG_LOCATION_PREFIX (THIS_MODULE ? ...

If that does make sense (the double testing of THIS_MODULE),
please explain why it does.

> +#else
> +#define KMSG_LOCATION_PREFIX __FILE__
> +#endif
> +
>  #define err(format, arg...) printk(KERN_ERR "%s: " format "\n" , \
> -	__FILE__ , ## arg)
> +	KMSG_LOCATION_PREFIX , ## arg)
>  #define info(format, arg...) printk(KERN_INFO "%s: " format "\n" , \
> -	__FILE__ , ## arg)
> +	KMSG_LOCATION_PREFIX , ## arg)
>  #define warn(format, arg...) printk(KERN_WARNING "%s: " format "\n" , \
> -	__FILE__ , ## arg)
> +	KMSG_LOCATION_PREFIX , ## arg)
>  #define notice(format, arg...) printk(KERN_NOTICE "%s: " format "\n" , \
> -	__FILE__ , ## arg)
> +	KMSG_LOCATION_PREFIX , ## arg)
> 
> 
>  #endif  /* __KERNEL__ */


---
~Randy

Re: [PATCH] reduce syslog clutter (take 2)

[Tilman Schmidt]

[-- Attachment #1: Type: text/plain, Size: 2314 bytes --]

Randy.Dunlap wrote:

>> +#if defined(CONFIG_MODULES) && defined(THIS_MODULE)
>> +#define KMSG_LOCATION_PREFIX THIS_MODULE ? THIS_MODULE->name : __FILE__
>
> Can we get parens around the expression, please?

Will do.

> and does it make sense to test
> #if defined(THIS_MODULE)
> #define KMSG_LOCATION_PREFIX (THIS_MODULE ? ...

Unfortunately, it does.

> If that does make sense (the double testing of THIS_MODULE),
> please explain why it does.

We have the following cases:

- compiling without module support, source file not including linux/module.h
  -> !defined(CONFIG_MODULES) && !defined(THIS_MODULE)
   -> compiling the expression (THIS_MODULE ? THIS_MODULE->name : __FILE__)
      fails with undefined symbol THIS_MODULE

- compiling with module support, source file not including linux/module.h
  -> defined(CONFIG_MODULES) && !defined(THIS_MODULE)
   -> compiling the expression (THIS_MODULE ? THIS_MODULE->name : __FILE__)
      fails with undefined symbol THIS_MODULE

- compiling without module support, source file including linux/module.h
  -> !defined(CONFIG_MODULES) && defined(THIS_MODULE)
   -> compiling the expression (THIS_MODULE ? THIS_MODULE->name : __FILE__)
      fails because THIS_MODULE is defined as a NULL pointer to
      struct module which in this case is an incomplete type (*sigh*)

- compiling with module support, source file including linux/module.h,
  not compiling as a module
  -> defined(CONFIG_MODULES) && defined(THIS_MODULE)
     && THIS_MODULE == ((struct module *)0)
   -> compiling the expression (THIS_MODULE ? THIS_MODULE->name : __FILE__)
      succeeds (hooray), but THIS_MODULE is a NULL pointer, though this
      time the type it points to is at least completely defined

- compiling with module support, source file including linux/module.h,
  compiling as a module
  -> defined(CONFIG_MODULES) && defined(THIS_MODULE)
     && THIS_MODULE == &__this_module
   -> compiling the expression (THIS_MODULE ? THIS_MODULE->name : __FILE__)
      succeeds and THIS_MODULE can actualy be dereferenced

I would like the code to compile and run successfully in all these cases.

--
Tilman Schmidt                    E-Mail: tilman@imap.cc
Bonn, Germany
Diese Nachricht besteht zu 100% aus wiederverwerteten Bits.
Ungeöffnet mindestens haltbar bis: (siehe Rückseite)

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 250 bytes --]

Re: [PATCH] reduce syslog clutter (take 2)

[Andrew Morton]

Tilman Schmidt <tilman@imap.cc> wrote:
>
> The current versions of the err() / info() / warn() syslog macros
>  insert __FILE__ at the beginning of the message, which expands to
>  the complete path name of the source file within the kernel tree.
> 
>  With the following patch, when used in a module, they'll insert the
>  module name instead, which is significantly shorter and also tends to
>  be more useful to users trying to make sense of a particular message.

Personally, I prefer to see filenames.  Or function names.  Sometimes it's
rather unobvious how to go from module name to filename, due to a) multiple
.o files being linked together, b) subsystems which insist on #including .c
files in .c files (usb...) and c) the module system's cute habit of
replacing underscores with dashes in module names.

Re: [PATCH] reduce syslog clutter (take 2)

[Randy.Dunlap]

On Thu, 9 Mar 2006 03:02:57 -0800 Andrew Morton wrote:

> Tilman Schmidt <tilman@imap.cc> wrote:
> >
> > The current versions of the err() / info() / warn() syslog macros
> >  insert __FILE__ at the beginning of the message, which expands to
> >  the complete path name of the source file within the kernel tree.
> > 
> >  With the following patch, when used in a module, they'll insert the
> >  module name instead, which is significantly shorter and also tends to
> >  be more useful to users trying to make sense of a particular message.
> 
> Personally, I prefer to see filenames.  Or function names.  Sometimes it's
> rather unobvious how to go from module name to filename, due to a) multiple
> .o files being linked together, b) subsystems which insist on #including .c
> files in .c files (usb...) and c) the module system's cute habit of
> replacing underscores with dashes in module names.

True, just using module->name or whatever means that we would
(often?) have to do a lookup to see what source file it was in.

---
~Randy

Re: [PATCH] reduce syslog clutter (take 2)

[Tilman Schmidt]

[-- Attachment #1: Type: text/plain, Size: 2017 bytes --]

On 09.03.2006 17:34, Randy.Dunlap wrote:

> On Thu, 9 Mar 2006 03:02:57 -0800 Andrew Morton wrote:
> 
>>Tilman Schmidt <tilman@imap.cc> wrote:
>>
>>>The current versions of the err() / info() / warn() syslog macros
>>> insert __FILE__ at the beginning of the message, which expands to
>>> the complete path name of the source file within the kernel tree.
>>>
>>> With the following patch, when used in a module, they'll insert the
>>> module name instead, which is significantly shorter and also tends to
>>> be more useful to users trying to make sense of a particular message.
>>
>>Personally, I prefer to see filenames.  Or function names.  Sometimes it's
>>rather unobvious how to go from module name to filename, due to a) multiple
>>.o files being linked together, b) subsystems which insist on #including .c
>>files in .c files (usb...) and c) the module system's cute habit of
>>replacing underscores with dashes in module names.
> 
> True, just using module->name or whatever means that we would
> (often?) have to do a lookup to see what source file it was in.

That would be a valid point for debugging messages. However, we are
talking about messages to users here. I maintain that the additional 20
characters in:

Feb 21 00:12:13 gx110 kernel: drivers/isdn/gigaset/i4l.c:
ISDN_CMD_SETL3: invalid protocol 42

as opposed to:

Feb 21 00:12:13 gx110 kernel: gigaset: ISDN_CMD_SETL3: invalid protocol 42

do not provide any useful information for that clientele. They just push
the actual interesting information farther to the right, in this case
even causing a line wrap.

If I want to include the function name in the message I can (and indeed
I quite frequently do), but this only makes the clutter worse if the
macros force the source path on me regardless.

-- 
Tilman Schmidt                          E-Mail: tilman@imap.cc
Bonn, Germany
Diese Nachricht besteht zu 100% aus wiederverwerteten Bits.
Ungeöffnet mindestens haltbar bis: (siehe Rückseite)


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 253 bytes --]

Re: [PATCH] reduce syslog clutter (take 2)

[Tilman Schmidt]

[-- Attachment #1: Type: text/plain, Size: 2108 bytes --]

On 09.03.2006 19:58, Jesper Juhl wrote:

> On 3/9/06, Tilman Schmidt <tilman@imap.cc> wrote:
> 
>>On 09.03.2006 17:34, Randy.Dunlap wrote:
>>
>>>On Thu, 9 Mar 2006 03:02:57 -0800 Andrew Morton wrote:
>>>
>>>>Tilman Schmidt <tilman@imap.cc> wrote:
>>>>
>>>>>The current versions of the err() / info() / warn() syslog macros
>>>>>insert __FILE__ at the beginning of the message, which expands to
>>>>>the complete path name of the source file within the kernel tree.
>>>>>
>>>>>With the following patch, when used in a module, they'll insert the
>>>>>module name instead, which is significantly shorter and also tends to
>>>>>be more useful to users trying to make sense of a particular message.
>>>>
>>>>Personally, I prefer to see filenames.  Or function names.  Sometimes it's
>>>>rather unobvious how to go from module name to filename, due to a) multiple
>>>>.o files being linked together, b) subsystems which insist on #including .c
>>>>files in .c files (usb...) and c) the module system's cute habit of
>>>>replacing underscores with dashes in module names.
>>>
>>>True, just using module->name or whatever means that we would
>>>(often?) have to do a lookup to see what source file it was in.
>>
>>That would be a valid point for debugging messages. However, we are
>>talking about messages to users here. I maintain that the additional 20
>>characters in:
>>
>>Feb 21 00:12:13 gx110 kernel: drivers/isdn/gigaset/i4l.c:
>>ISDN_CMD_SETL3: invalid protocol 42
>>
>>as opposed to:
>>
>>Feb 21 00:12:13 gx110 kernel: gigaset: ISDN_CMD_SETL3: invalid protocol 42
>>
>>do not provide any useful information for that clientele. They just push
> 
> The filename may not be useful to the user, but the instant the user decides to
> submit a bugreport to LKML or elsewhere it becomes useful.

Then why does the majority of kernel messages not include a filename?

-- 
Tilman Schmidt                          E-Mail: tilman@imap.cc
Bonn, Germany
Diese Nachricht besteht zu 100% aus wiederverwerteten Bits.
Ungeöffnet mindestens haltbar bis: (siehe Rückseite)


[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 253 bytes --]

Re: [PATCH] reduce syslog clutter (take 2)

[Andrew Morton]

"Jesper Juhl" <jesper.juhl@gmail.com> wrote:
>
> > Feb 21 00:12:13 gx110 kernel: gigaset: ISDN_CMD_SETL3: invalid protocol 42
>  >
>  > do not provide any useful information for that clientele. They just push
> 
>  The filename may not be useful to the user, but the instant the user decides to
>  submit a bugreport to LKML or elsewhere it becomes useful.

But OTOH, there's a difference between messages-to-developers (usually "the
code went wrong") and messages-to-users (hopefully usually "the hardware
went wrong" or "you went wrong").

So I guess the change is a good one for end-user informational messages. 
And end-users are the party who should be served, more than developers.

Re: [PATCH] reduce syslog clutter (take 2)

[Pete Zaitcev]

On Thu, 9 Mar 2006 13:03:27 -0800, Andrew Morton <akpm@osdl.org> wrote:
> "Jesper Juhl" <jesper.juhl@gmail.com> wrote:
> >
> > > Feb 21 00:12:13 gx110 kernel: gigaset: ISDN_CMD_SETL3: invalid protocol 42
> >  >
> >  > do not provide any useful information for that clientele. They just push
> > 
> >  The filename may not be useful to the user, but the instant the user decides to
> >  submit a bugreport to LKML or elsewhere it becomes useful.
> 
> But OTOH, there's a difference between messages-to-developers (usually "the
> code went wrong") and messages-to-users (hopefully usually "the hardware
> went wrong" or "you went wrong").

Symbol names are generally unique. As a USB stack developer, I never saw
the file name being useful for anything in the error message, let alone
the full path! Always hated them, but never bothered to break spears
over the issue. We have better things to do. I just quietly remove
debugging printouts from the code I touch.

-- Pete

Re: [PATCH] reduce syslog clutter (take 2)

[Greg KH]

On Thu, Mar 09, 2006 at 01:18:47PM -0800, Pete Zaitcev wrote:
> On Thu, 9 Mar 2006 13:03:27 -0800, Andrew Morton <akpm@osdl.org> wrote:
> > "Jesper Juhl" <jesper.juhl@gmail.com> wrote:
> > >
> > > > Feb 21 00:12:13 gx110 kernel: gigaset: ISDN_CMD_SETL3: invalid protocol 42
> > >  >
> > >  > do not provide any useful information for that clientele. They just push
> > > 
> > >  The filename may not be useful to the user, but the instant the user decides to
> > >  submit a bugreport to LKML or elsewhere it becomes useful.
> > 
> > But OTOH, there's a difference between messages-to-developers (usually "the
> > code went wrong") and messages-to-users (hopefully usually "the hardware
> > went wrong" or "you went wrong").
> 
> Symbol names are generally unique. As a USB stack developer, I never saw
> the file name being useful for anything in the error message, let alone
> the full path! Always hated them, but never bothered to break spears
> over the issue. We have better things to do. I just quietly remove
> debugging printouts from the code I touch.

There's a bit of history here.  The dbg(), err(), info() macros came
from the USB core, back in 2.2 days.  Then the whole path of the file
was not part of __FILE__, but only the single .c file.

With 2.5, __FILE__ changed as part of the build process changes, and we
added dev_dbg(), dev_info(), and dev_err(), which are a _much_ better
way to output information from a driver.  It provides the exact driver
and device that is being talked about, and not just a file.

So, ideally I'd like to get rid of the USB macros completly, and use the
dev_* forms instead.  But there are a few places in the USB code that do
not have a valid device and so they can't be dropped entirely.

Either way, I don't think we need to be making them "prettier" at this
point in time, but fixing the real problem of using them in the first
place...

I'll drop this patch for now, and only take the part that adds the new
dev_* macro.  Is that ok for everyone?

And if anyone wants to notify the kernel-janitors that this would be a
good thing to do for the USB subsytem, feel free, I'll gladly accept
those patches.

thanks,

greg k-h