login
Search
From: Michael Holzheu <holzheu@de.ibm.com> From: Martin Schwidefsky <schwidefsky@de.ibm.com> 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 <holzheu@de.ibm.com> Signed-off-by: Martin Schwidefsky <schwidefsky@de.ibm.com> --- 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) || ...
What if __KMSG_CHECKER is enabled? What does __KMSG_CHECK resolve to then? And what sets __KMSG_CHECKER? thanks, greg k-h --
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. --
On Wed, Jul 30, 2008 at 18:56, Martin Schwidefsky Care to use dev_name(), bus_id will be removed soon. Thanks, Kay --
Hm, just use dev_printk() instead, it handles all of these kinds of changes automatically. thanks, greg k-h --
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. --
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 --
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 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. --
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 --
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. --
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 Ugly is a beholder problem. Either printk or dev_printk could reorder the output. --
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 ...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. --
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 --
No, there are more printks in the system then just dev_printk. The kmsg interface
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
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.
--
On Sun 10-08-08 02:03:41, Martin Schwidefsky wrote: 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 <jack@suse.cz> SUSE Labs, CR --
Yes, will do. Thanks. -- blue skies, Martin. "Reality continues to ruin my life." - Calvin. --
On Wed, Jul 30, 2008 at 9:56 AM, Martin Schwidefsky We've been talking about doing something like this, just this week. AKPM 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 --
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 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. --
On Thu, Aug 14, 2008 at 10:04 AM, Martin Schwidefsky
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
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);
Do you see *every* printk() becoming a kmsg? Just printk() in drivers?
Or just some hand-chosen printk()s ?
Tim
--
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__ 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 <joe@perches.com> --- 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 ...
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 --
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 --
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. --
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 --
"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 --
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 Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR --
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 --
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 --
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.
--
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. --
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 --
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 --
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. --
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. --
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 Tim --
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 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. --
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. --
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. --
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 Sounds doable to me. -- blue skies, Martin. "Reality continues to ruin my life." - Calvin. --
On Sat, Aug 16, 2008 at 10:49 AM, Martin Schwidefsky 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 --
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.) 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.) 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; <>< --
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. --
Is the suggestion that in case of a clash just change the message string 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. --
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. --
On Sun, Aug 17, 2008 at 10:28 AM, Martin Schwidefsky 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. --
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; <>< --
The kmsg id is just that, an index into the table of message for a That is what we are trying to achieve as well. -- blue skies, Martin. "Reality continues to ruin my life." - Calvin. --
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. --
Hmm, #define KERN_IGNORE KERN_DEBUG? Rusty. --
Hmm, shouldn't KERN_xxx levels be independent of the special id 0? -- blue skies, Martin. "Reality continues to ruin my life." - Calvin. --
I don't know. Why should something be untranslatable? Rusty. --
Do we really want to require that every message printed with the kmsg macros has to be documented? I don't think this is a good idea. The special id 0 is there to tell the script not to bother with a particular message, e.g. the lovely "module <x> has been loaded" messages. The message still can be translated. -- blue skies, Martin. "Reality continues to ruin my life." - Calvin. --
