[PATCH 1/4] Net device error logging, revised

This patch extends the concept of Linux 2.6's dev_* logging macros to
support network devices.  Analogous netdev_* macros are defined.  This
feature is part of an effort to simplify error-log analysis by providing
more consistent and informative messages.

This is a modification of a proposal from May.  The changes reflect
suggestions made on LKML, at the Kernel Summit, and at OLS.

Calls to the netdev_* macros (netdev_printk and wrappers such as
netdev_err) are intended to replace calls to printk in network device
drivers.  These macros have the following characteristics:
- Same format + args as the corresponding printk call.
- Approximately the same amount of text as the corresponding printk call.
- The first arg is a pointer to the net_device struct.
- The second (optional) arg, which is a NETIF_MSG_* message level, can be
used to implement verbosity control.
- Standard message prefixes: verbose (see below) during probe, or just the
interface name once the device is registered.
- The current implementation just calls printk.  However, the netdev_*
interface (and availability of the net_device pointer) opens the door
for logging additional information (via printk, via evlog/netlink, etc.)
as desired, with no change to driver code.

Examples:
        netdev_err(netdev, RX_ERR, "No mem: dropped packet\n");
logs a message such as the following if the NETIF_MSG_RX_ERR bit is set
in netdev->msg_enable.
        eth2: No mem: dropped packet

        netdev_err(netdev,, "The EEPROM Checksum Is Not Valid\n");
unconditionally logs a message such as:
        eth%d (e1000 0000:00:03.0): The EEPROM Checksum Is Not Valid
The message's prefix includes the driver name and bus ID because the
message is logged at probe time, before netdev is registered.

Note that the netdev_* interface can be used in v2.4 drivers as well,
but in a v2.4 implementation, the message prefix would always be just
the interface name.

Three other patches are included in subsequent emails.  These patch
the e100, e1000, and tg3 Ethernet drivers to use the netdev_* macros.
(For e100 and e1000, they also add the necessary scaffolding for verbosity
control via the NETIF_MSG_* message levels).

Jim Keniston
IBM Linux Technology Center
-----

Here's a patch to modify the v2.6.0-test4 e100 driver to use netdev_*
macros and support verbosity control via the NETIF_MSG_* message levels.

Jim Keniston
IBM Linux Technology Center

Here's a patch to modify the v2.6.0-test4 tg3 driver to use netdev_* macros.

Jim Keniston
IBM Linux Technology Center

Here's a patch to modify the v2.6.0-test4 e1000 driver to use netdev_*
macros and support verbosity control via the NETIF_MSG_* message levels.

Jim Keniston
IBM Linux Technology Center

On Mon, Aug 25, 2003 at 02:31:19PM -0700, Jim Keniston wrote:

+int __netdev_printk(const char *sevlevel, const struct net_device *netdev,
+	int msglevel, const char *format, ...)
+{
+	if (!netdev || !format) {
+		return -EINVAL;
+	}
+	if (msglevel == NETIF_MSG_ALL || (netdev->msg_enable & msglevel)) {
+		char msg[512];

512 bytes on the stack?  Any way to prevent this from happening?  With
the push to make the stack even smaller in 2.7, people will not like
this.

thanks,

greg k-h

Greg KH wrote:

On Mon, Aug 25, 2003 at 02:31:19PM -0700, Jim Keniston wrote:

quoted

+int __netdev_printk(const char *sevlevel, const struct net_device *netdev,
+     int msglevel, const char *format, ...)
+{
+     if (!netdev || !format) {
+             return -EINVAL;
+     }
+     if (msglevel == NETIF_MSG_ALL || (netdev->msg_enable & msglevel)) {
+             char msg[512];

512 bytes on the stack?  Any way to prevent this from happening?  With
the push to make the stack even smaller in 2.7, people will not like
this.

thanks,

greg k-h

The following options come to mind:
1. Keep the msg buffer, but make it smaller.  Around 120 bytes would probably be
big enough for the vast majority of messages.  (printk() uses a 1024-byte buffer,
but it's static -- see #2.)

2. Use a big, static buffer, protected by a spinlock.  printk() does this.

3. Do the whole thing in a macro, as in previous proposals.  The size of the macro
expansion could be reduced somewhat by doing the encode-prefix step in a function --
something like:

#define netdev_printk(sevlevel, netdev, msglevel, format, arg...)	\
do {									\
if (NETIF_MSG_##msglevel == NETIF_MSG_ALL || ((netdev)->msg_enable & NETIF_MSG_##msglevel)) {	\
	char pfx[40];							\
	printk(sevlevel "%s: " format , make_netdev_msg_prefix(pfx, netdev) , ## arg);	\
}} while (0)

This would make your code bigger, but not that much bigger for the common case where
the msglevel is omitted (and the 'if(...)' is optimized out).

Jim

Jim Keniston wrote:

#define netdev_printk(sevlevel, netdev, msglevel, format, arg...)	\
do {									\
if (NETIF_MSG_##msglevel == NETIF_MSG_ALL || ((netdev)->msg_enable & NETIF_MSG_##msglevel)) {	\
	char pfx[40];							\
	printk(sevlevel "%s: " format , make_netdev_msg_prefix(pfx, netdev) , ## arg);	\
}} while (0)

This would make your code bigger, but not that much bigger for the common case where
the msglevel is omitted (and the 'if(...)' is optimized out).

"NETIF_MSG_" is silly and should be eliminated.
A separate "NETIF_MSG_ALL" test is not needed, because msg_enable is a 
bitmask.  A msg_enable of 0xffffffff will naturally create a NETIF_MSG_ALL.

Also, whatever mechanism is created, it needs to preserve the feature of 
the existing system:

	if (a quick bitmask test)
		do something

And preferably "do something" is not inlined, because printk'ing -- 
although it may appear in a fast path during debugging -- cannot be 
considered a fast path itself.

	Jeff

Jeff Garzik wrote:

Jim Keniston wrote:

quoted

#define netdev_printk(sevlevel, netdev, msglevel, format, arg...)     \
do {                                                                  \
if (NETIF_MSG_##msglevel == NETIF_MSG_ALL || ((netdev)->msg_enable & NETIF_MSG_##msglevel)) { \
      char pfx[40];                                                   \
      printk(sevlevel "%s: " format , make_netdev_msg_prefix(pfx, netdev) , ## arg);  \
}} while (0)

This would make your code bigger, but not that much bigger for the common case where
the msglevel is omitted (and the 'if(...)' is optimized out).

"NETIF_MSG_" is silly and should be eliminated.

From this, I infer that you think that the option to "omit" the msglevel arg --

e.g.,
	netdev_err(dev,, "NIC is fried!\n");	/* always logged */
-- is silly.  No big deal.  Its sole purpose is to help keep netdev_* calls terse.

A separate "NETIF_MSG_ALL" test is not needed, because msg_enable is a
bitmask.  A msg_enable of 0xffffffff will naturally create a NETIF_MSG_ALL.

But how do you code a netdev_* call where you ALWAYS want the message (including
netdev_printk-style prefix) logged, regardless of the value of msg_enable?  That's
what NETIF_MSG_ALL is for (and why it might be better called NETIF_MSG_ALWAYS)...
	netdev_err(dev, ALL, "NIC is fried!\n");	/* always logged */
or
	netdev_err(dev, ALWAYS, "NIC is fried!\n");	/* always logged */

Also, whatever mechanism is created, it needs to preserve the feature of
the existing system:

        if (a quick bitmask test)
                do something

And preferably "do something" is not inlined, because printk'ing --
although it may appear in a fast path during debugging -- cannot be
considered a fast path itself.

        Jeff

Sorry, I'm not sure what you're getting at here.  netdev_* doesn't prevent
people from using the existing netif_msg_* macros; it just provides shorthand
for the (usual) case where "do something" is "printk".

Jim

Jim Keniston wrote:

Jeff Garzik wrote:

quoted

"NETIF_MSG_" is silly and should be eliminated.

quoted

From this, I infer that you think that the option to "omit" the msglevel arg --

e.g.,
	netdev_err(dev,, "NIC is fried!\n");	/* always logged */
-- is silly.  No big deal.  Its sole purpose is to help keep netdev_* calls terse.

yes

quoted

A separate "NETIF_MSG_ALL" test is not needed, because msg_enable is a
bitmask.  A msg_enable of 0xffffffff will naturally create a NETIF_MSG_ALL.

But how do you code a netdev_* call where you ALWAYS want the message (including
netdev_printk-style prefix) logged, regardless of the value of msg_enable?  That's
what NETIF_MSG_ALL is for (and why it might be better called NETIF_MSG_ALWAYS)...

I understand the purpose of NETIF_MSG_ALL; re-read what I said.  You 
don't need a separate _test_, as your implementation includes.  Defining 
NETIF_MSG_ALL to 0xffffffff will naturally create the effect you seek.

quoted

Also, whatever mechanism is created, it needs to preserve the feature of
the existing system:

       if (a quick bitmask test)
               do something

And preferably "do something" is not inlined, because printk'ing --
although it may appear in a fast path during debugging -- cannot be
considered a fast path itself.

Sorry, I'm not sure what you're getting at here.  netdev_* doesn't prevent
people from using the existing netif_msg_* macros; it just provides shorthand
for the (usual) case where "do something" is "printk".

I would prefer to be more ambitious.  If we're gonna go in and change 
every printk in a driver, we might as well do it right, and (a) make 
sure the driver does msg_enable, and (b) make the source code a bit more 
clean by hiding the "if (test bitmap)" test in your netdev_xxx stuff.

	Jeff

Jeff Garzik wrote:

Jim Keniston wrote:

quoted

Jeff Garzik wrote:

...

quoted

quoted

A separate "NETIF_MSG_ALL" test is not needed, because msg_enable is a
bitmask.  A msg_enable of 0xffffffff will naturally create a NETIF_MSG_ALL.

But how do you code a netdev_* call where you ALWAYS want the message (including
netdev_printk-style prefix) logged, regardless of the value of msg_enable?  That's
what NETIF_MSG_ALL is for (and why it might be better called NETIF_MSG_ALWAYS)...

I understand the purpose of NETIF_MSG_ALL; re-read what I said.  You
don't need a separate _test_, as your implementation includes.  Defining
NETIF_MSG_ALL to 0xffffffff will naturally create the effect you seek.

So the test becomes
	if (netdev->msg_enable & msglevel) { /* log message */ }
If netdev->msg_enable == 0, the message is suppressed even if msglevel == NETIF_MSG_ALL.
I had intended that "ALL" would override the msg_enable setting (even 0), but we can do
it this way as well.

...

        Jeff

Jim

The following options come to mind:
1. Keep the msg buffer, but make it smaller.  Around 120 bytes would probably be
big enough for the vast majority of messages.  (printk() uses a 1024-byte buffer,
but it's static -- see #2.)

2. Use a big, static buffer, protected by a spinlock.  printk() does this.

3. Do the whole thing in a macro, as in previous proposals.  The size of the macro
expansion could be reduced somewhat by doing the encode-prefix step in a function --
something like:

#define netdev_printk(sevlevel, netdev, msglevel, format, arg...)	\
do {									\
if (NETIF_MSG_##msglevel == NETIF_MSG_ALL || ((netdev)->msg_enable & NETIF_MSG_##msglevel)) {	\
	char pfx[40];							\
	printk(sevlevel "%s: " format , make_netdev_msg_prefix(pfx, netdev) , ## arg);	\
}} while (0)

This would make your code bigger, but not that much bigger for the common case where
the msglevel is omitted (and the 'if(...)' is optimized out).

Is there some way to tack copy and prepend what you want onto the format
string, and add additional arguments to the call to printk?  That way you
wouldn't need space for the potentially large resulting string, but only
enough room for the expanded format string.

Stephen Hemminger wrote:

quoted

The following options come to mind:
1. Keep the msg buffer, but make it smaller.  Around 120 bytes would probably be
big enough for the vast majority of messages.  (printk() uses a 1024-byte buffer,
but it's static -- see #2.)

2. Use a big, static buffer, protected by a spinlock.  printk() does this.

3. Do the whole thing in a macro, as in previous proposals.  The size of the macro
expansion could be reduced somewhat by doing the encode-prefix step in a function --
something like:

[more on #3 snipped]

Is there some way to tack copy and prepend what you want onto the format
string, and add additional arguments to the call to printk?  That way you
wouldn't need space for the potentially large resulting string, but only
enough room for the expanded format string.

Interesting idea.  I pondered this for a while.  But even if you postulate 
a varargs version of printk (which doesn't exist), it's not really
feasible to do this in a function.  There's no way for a function to
prepend args to a va_list.  That means you'd have to encode the text of
the prefix as part of the format string, and that would require you to
allocate room for prefix+format, which is still a lot of stack.  Also,
the fact that the interface name itself may contain "%d" or some such
makes it even messier.

Greg K-H thinks #2 is a reasonable solution (you're about to serialize on printk's
lock anyway), so I'll go with that.

Thanks.
Jim

This patch extends the concept of Linux 2.6's dev_* logging macros to
support network devices.  This is a modification of a patch posted
last month, and addresses the issues raised since then, namely:

1. To minimize stack usage, the msg[] buffer in __netdev_printk() has been
made static and protected by a spinlock.  (The spinlock shouldn't be a big
performance hit because we're about to serialize on printk's lock anyway.)

2. It is no longer possible to omit the msglevel arg.  For example,
        netdev_err(dev,, "NIC fried!\n");
no longer works.  This must be expressed as
        netdev_err(dev, ALL, "NIC fried!\n");
or (see #3 below) something like
        netdev_fatal(dev, HW, "NIC fried!\n");

3. A new macro, netdev_fatal, is included.  Given the call
        netdev_fatal(dev, HW, "NIC fried!\n");
the indicated message is always logged: the msglevel arg (HW, in this
case) is NOT consulted.  In fact, the msglevel arg to netdev_fatal
is ignored in this implementation.  (As previously discussed, in some
future implementation, the msglevel could be logged to help indicate
the circumstances under which the event was logged.)

4. It was suggested that the netdev_* macros should support message
filtering via simple message levels -- e.g.,
        if (dev->msg_enable > 5) printk(KERN_INFO "Received a packet.\n");
-- in addition to (or instead of) via the NETIF_MSG_* bit masks.  But
Jeff Garzik reiterated his desire to standardize on NETIF_MSG_*, so
I'm leaving things unchanged in that respect.

5. It was suggested that netdev_dbg is not flexible enough to handle all
debugging situations.  This is probably true.  Because of the special
nature of debugging messages, I'd expect the developer to use other
approaches in debug code if netdev_dbg doesn't fill the bill.  But the
netdev_dbg approach appears to be reasonably useful.  (For comparison,
there are currently 188 calls to dev_dbg in Linux drivers.)  No change
here.

6. Certain comments seemed to imply that you should be able to
suppress all messages (even those with a msglevel of ALL) by setting the
msg_enable field to 0.  I chose not to support this, because it seemed
counterintuitive and inconsistent with existing practice.

Jim Keniston
IBM Linux Technology Center