[PATCH] Net device error logging

[PATCH] Net device error logging

[Jim Keniston]

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

The enclosed patch, updated for v2.6.0-test6, implements the previously
discussed netdev_* error-logging macros for network drivers.  Please apply.

RECAP (from previous posts):
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 arg, which is a NETIF_MSG_* message level, can be used to
implement verbosity control.
- Standard message prefixes: verbose (interface name, driver name, bus ID)
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_fatal(netdev, PROBE, "The EEPROM Checksum Is Not Valid\n");
or
        netdev_err(netdev, ALL, "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.

SAMPLE DRIVERS
As examples of how the netdev_* macros could be used, patches for the
v2.6.0-test6 e100, e1000, and tg3 drivers are available on request.

LINUX v2.4 SUPPORT
Since there is no v2.6-style struct device underlying the net_device,
the v2.4.22 version of netdev_printk always logs the interface name
as the message prefix:

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

Full patch for v2.4.22 available on request.

Jim Keniston
IBM Linux Technology Center

[-- Attachment #2: netdev-2.6.0-test6.patch --]
[-- Type: text/plain, Size: 5765 bytes --]

diff -Naur linux.org/include/linux/netdevice.h linux.netdev.patched/include/linux/netdevice.h
--- linux.org/include/linux/netdevice.h	Tue Sep 30 16:21:21 2003
+++ linux.netdev.patched/include/linux/netdevice.h	Tue Sep 30 16:21:21 2003
@@ -467,6 +467,9 @@
 	struct divert_blk	*divert;
 #endif /* CONFIG_NET_DIVERT */
 
+	/* NETIF_MSG_* flags to control the types of events we log */
+	int msg_enable;
+
 	/* class/net/name entry */
 	struct class_device	class_dev;
 };
@@ -746,6 +749,7 @@
 	NETIF_MSG_PKTDATA	= 0x1000,
 	NETIF_MSG_HW		= 0x2000,
 	NETIF_MSG_WOL		= 0x4000,
+	NETIF_MSG_ALL		= -1,		/* always log message */
 };
 
 #define netif_msg_drv(p)	((p)->msg_enable & NETIF_MSG_DRV)
@@ -904,6 +908,40 @@
 extern void		dev_clear_fastroute(struct net_device *dev);
 #endif
 
+/* debugging and troubleshooting/diagnostic helpers. */
+/**
+ * netdev_printk() - Log message with interface name, gated by message level
+ * @sevlevel: severity level -- e.g., KERN_INFO
+ * @netdev: net_device pointer
+ * @msglevel: a standard message-level flag with the NETIF_MSG_ prefix removed.
+ *	Unless msglevel is NETIF_MSG_ALL, log the message only if that flag
+ *	is set in netdev->msg_enable.
+ * @format: as with printk
+ * @args: as with printk
+ */
+extern int __netdev_printk(const char *sevlevel,
+	const struct net_device *netdev, int msglevel, const char *format, ...);
+#define netdev_printk(sevlevel, netdev, msglevel, format, arg...)	\
+	__netdev_printk(sevlevel , netdev , NETIF_MSG_##msglevel ,	\
+	format , ## arg)
+
+#ifdef DEBUG
+#define netdev_dbg(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_DEBUG , netdev , msglevel , format , ## arg)
+#else
+#define netdev_dbg(netdev, msglevel, format, arg...) do {} while (0)
+#endif
+
+#define netdev_err(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_ERR , netdev , msglevel , format , ## arg)
+#define netdev_info(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_INFO , netdev , msglevel , format , ## arg)
+#define netdev_warn(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_WARNING , netdev , msglevel , format , ## arg)
+
+/* report fatal error unconditionally; msglevel ignored for now */
+#define netdev_fatal(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_ERR , netdev , ALL , format , ## arg)
 
 #endif /* __KERNEL__ */
 
diff -Naur linux.org/net/core/dev.c linux.netdev.patched/net/core/dev.c
--- linux.org/net/core/dev.c	Tue Sep 30 16:21:21 2003
+++ linux.netdev.patched/net/core/dev.c	Tue Sep 30 16:21:21 2003
@@ -3036,3 +3036,75 @@
 }
 
 subsys_initcall(net_dev_init);
+
+static spinlock_t netdev_printk_lock = SPIN_LOCK_UNLOCKED;
+/**
+ * __netdev_printk() - Log message with interface name, gated by message level
+ * @sevlevel: severity level -- e.g., KERN_INFO
+ * @netdev: net_device pointer
+ * @msglevel: a standard message-level flag such as NETIF_MSG_PROBE.
+ *	Unless msglevel is NETIF_MSG_ALL, log the message only if
+ *	that flag is set in netdev->msg_enable.
+ * @format: as with printk
+ * @args: as with printk
+ *
+ * Does the work for the netdev_printk macro.
+ * For a lot of network drivers, the probe function looks like
+ *	...
+ *	netdev = alloc_netdev(...);	// or alloc_etherdev(...)
+ *	SET_NETDEV_DEV(netdev, dev);
+ *	...
+ *	register_netdev(netdev);
+ *	...
+ * netdev_printk and its wrappers (e.g., netdev_err) can be used as
+ * soon as you have a valid net_device pointer -- e.g., from alloc_netdev,
+ * alloc_etherdev, or init_etherdev.  (Before that, use dev_printk and
+ * its wrappers to report device errors.)  It's common for an interface to
+ * have a name like "eth%d" until the device is successfully configured,
+ * and the call to register_netdev changes it to a "real" name like "eth0".
+ *
+ * If the interface's reg_state is NETREG_REGISTERED, we assume that it has
+ * been successfully set up in sysfs, and we prepend only the interface name
+ * to the message -- e.g., "eth0: NIC Link is Down".  The interface
+ * name can be used to find eth0's driver, bus ID, etc. in sysfs.
+ *
+ * For any other value of reg_state, we prepend the driver name and bus ID
+ * as well as the (possibly incomplete) interface name -- e.g.,
+ * "eth%d (e100 0000:00:03.0): Failed to map PCI address..."
+ *
+ * Probe functions that alloc and register in one step (via init_etherdev),
+ * or otherwise register the device before the probe completes successfully,
+ * may need to take other steps to ensure that the failing device is clearly
+ * identified.
+ */
+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)) {
+		static char msg[512];	/* protected by netdev_printk_lock */
+		unsigned long flags;
+		va_list args;
+		struct device *dev = netdev->class_dev.dev;
+		
+		spin_lock_irqsave(&netdev_printk_lock, flags);
+		va_start(args, format);
+		vsnprintf(msg, 512, format, args);
+		va_end(args);
+
+		if (!sevlevel) {
+			sevlevel = "";
+		}
+
+		if (netdev->reg_state == NETREG_REGISTERED || !dev) {
+			printk("%s%s: %s", sevlevel, netdev->name, msg);
+		} else {
+			printk("%s%s (%s %s): %s", sevlevel, netdev->name,
+				dev->driver->name, dev->bus_id, msg);
+		}
+		spin_unlock_irqrestore(&netdev_printk_lock, flags);
+	}
+	return 0;
+}
diff -Naur linux.org/net/netsyms.c linux.netdev.patched/net/netsyms.c
--- linux.org/net/netsyms.c	Tue Sep 30 16:21:21 2003
+++ linux.netdev.patched/net/netsyms.c	Tue Sep 30 16:21:21 2003
@@ -210,6 +210,7 @@
 EXPORT_SYMBOL(net_ratelimit);
 EXPORT_SYMBOL(net_random);
 EXPORT_SYMBOL(net_srandom);
+EXPORT_SYMBOL(__netdev_printk);
 
 /* Needed by smbfs.o */
 EXPORT_SYMBOL(__scm_destroy);

Re: [PATCH] Net device error logging

[acme]

net/netsyms.c is gone, please export that symbol just after its 
implementation. 
 
- Arnaldo 
 
 

Re: [PATCH] Net device error logging

[Joe Perches]

On Thu, 2003-10-02 at 14:19, Jim Keniston wrote:
> The enclosed patch, updated for v2.6.0-test6, implements the previously
> discussed netdev_* error-logging macros for network drivers.  Please apply.

While I agree with the completely with the concept and nearly completely
with the implementation, can I suggest that this should be done in the
2.7 series?

Re: [PATCH] Net device error logging

[Jim Keniston]

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

acme@conectiva.com.br wrote:
>
> net/netsyms.c is gone, please export that symbol just after its
> implementation.

Done.  The enclosed patch works with v2.6.0-test6-bk8.

Joe Perches wrote:
> ...
> While I agree with the completely with the concept and nearly completely
> with the implementation,

... Thanks...

> can I suggest that this should be done in the
> 2.7 series?

I would like to see it in v2.6 because it's in demand now [1] and its
impact is negligible on drivers that don't use it [2].

[1] Scott Feldman has indicated that he wants to incorporate netdev_*
calls into the e1000 driver (along the lines of the patches we published
previously) and the e100-3.0.0 driver (where the only change needed is
a redefinition of that driver's DPRINTK macro).

[2] For drivers that haven't converted to netdev_*, no changes are
needed.  struct net_device grows a bit (adding the msg_enable member),
but a driver that has a msg_enable member in its private struct can
continue to use it.

Jim Keniston

[-- Attachment #2: netdev-bk8.patch --]
[-- Type: text/plain, Size: 5510 bytes --]

diff -Naur linux.org/include/linux/netdevice.h linux.netdev.patched/include/linux/netdevice.h
--- linux.org/include/linux/netdevice.h	Mon Oct  6 16:13:12 2003
+++ linux.netdev.patched/include/linux/netdevice.h	Mon Oct  6 16:13:12 2003
@@ -467,6 +467,9 @@
 	struct divert_blk	*divert;
 #endif /* CONFIG_NET_DIVERT */
 
+	/* NETIF_MSG_* flags to control the types of events we log */
+	int msg_enable;
+
 	/* class/net/name entry */
 	struct class_device	class_dev;
 };
@@ -746,6 +749,7 @@
 	NETIF_MSG_PKTDATA	= 0x1000,
 	NETIF_MSG_HW		= 0x2000,
 	NETIF_MSG_WOL		= 0x4000,
+	NETIF_MSG_ALL		= -1,		/* always log message */
 };
 
 #define netif_msg_drv(p)	((p)->msg_enable & NETIF_MSG_DRV)
@@ -904,6 +908,40 @@
 extern void		dev_clear_fastroute(struct net_device *dev);
 #endif
 
+/* debugging and troubleshooting/diagnostic helpers. */
+/**
+ * netdev_printk() - Log message with interface name, gated by message level
+ * @sevlevel: severity level -- e.g., KERN_INFO
+ * @netdev: net_device pointer
+ * @msglevel: a standard message-level flag with the NETIF_MSG_ prefix removed.
+ *	Unless msglevel is NETIF_MSG_ALL, log the message only if that flag
+ *	is set in netdev->msg_enable.
+ * @format: as with printk
+ * @args: as with printk
+ */
+extern int __netdev_printk(const char *sevlevel,
+	const struct net_device *netdev, int msglevel, const char *format, ...);
+#define netdev_printk(sevlevel, netdev, msglevel, format, arg...)	\
+	__netdev_printk(sevlevel , netdev , NETIF_MSG_##msglevel ,	\
+	format , ## arg)
+
+#ifdef DEBUG
+#define netdev_dbg(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_DEBUG , netdev , msglevel , format , ## arg)
+#else
+#define netdev_dbg(netdev, msglevel, format, arg...) do {} while (0)
+#endif
+
+#define netdev_err(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_ERR , netdev , msglevel , format , ## arg)
+#define netdev_info(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_INFO , netdev , msglevel , format , ## arg)
+#define netdev_warn(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_WARNING , netdev , msglevel , format , ## arg)
+
+/* report fatal error unconditionally; msglevel ignored for now */
+#define netdev_fatal(netdev, msglevel, format, arg...)		\
+	netdev_printk(KERN_ERR , netdev , ALL , format , ## arg)
 
 #endif /* __KERNEL__ */
 
diff -Naur linux.org/net/core/dev.c linux.netdev.patched/net/core/dev.c
--- linux.org/net/core/dev.c	Mon Oct  6 16:13:12 2003
+++ linux.netdev.patched/net/core/dev.c	Mon Oct  6 16:13:12 2003
@@ -3028,6 +3028,79 @@
 
 subsys_initcall(net_dev_init);
 
+static spinlock_t netdev_printk_lock = SPIN_LOCK_UNLOCKED;
+/**
+ * __netdev_printk() - Log message with interface name, gated by message level
+ * @sevlevel: severity level -- e.g., KERN_INFO
+ * @netdev: net_device pointer
+ * @msglevel: a standard message-level flag such as NETIF_MSG_PROBE.
+ *	Unless msglevel is NETIF_MSG_ALL, log the message only if
+ *	that flag is set in netdev->msg_enable.
+ * @format: as with printk
+ * @args: as with printk
+ *
+ * Does the work for the netdev_printk macro.
+ * For a lot of network drivers, the probe function looks like
+ *	...
+ *	netdev = alloc_netdev(...);	// or alloc_etherdev(...)
+ *	SET_NETDEV_DEV(netdev, dev);
+ *	...
+ *	register_netdev(netdev);
+ *	...
+ * netdev_printk and its wrappers (e.g., netdev_err) can be used as
+ * soon as you have a valid net_device pointer -- e.g., from alloc_netdev,
+ * alloc_etherdev, or init_etherdev.  (Before that, use dev_printk and
+ * its wrappers to report device errors.)  It's common for an interface to
+ * have a name like "eth%d" until the device is successfully configured,
+ * and the call to register_netdev changes it to a "real" name like "eth0".
+ *
+ * If the interface's reg_state is NETREG_REGISTERED, we assume that it has
+ * been successfully set up in sysfs, and we prepend only the interface name
+ * to the message -- e.g., "eth0: NIC Link is Down".  The interface
+ * name can be used to find eth0's driver, bus ID, etc. in sysfs.
+ *
+ * For any other value of reg_state, we prepend the driver name and bus ID
+ * as well as the (possibly incomplete) interface name -- e.g.,
+ * "eth%d (e100 0000:00:03.0): Failed to map PCI address..."
+ *
+ * Probe functions that alloc and register in one step (via init_etherdev),
+ * or otherwise register the device before the probe completes successfully,
+ * may need to take other steps to ensure that the failing device is clearly
+ * identified.
+ */
+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)) {
+		static char msg[512];	/* protected by netdev_printk_lock */
+		unsigned long flags;
+		va_list args;
+		struct device *dev = netdev->class_dev.dev;
+		
+		spin_lock_irqsave(&netdev_printk_lock, flags);
+		va_start(args, format);
+		vsnprintf(msg, 512, format, args);
+		va_end(args);
+
+		if (!sevlevel) {
+			sevlevel = "";
+		}
+
+		if (netdev->reg_state == NETREG_REGISTERED || !dev) {
+			printk("%s%s: %s", sevlevel, netdev->name, msg);
+		} else {
+			printk("%s%s (%s %s): %s", sevlevel, netdev->name,
+				dev->driver->name, dev->bus_id, msg);
+		}
+		spin_unlock_irqrestore(&netdev_printk_lock, flags);
+	}
+	return 0;
+}
+
+EXPORT_SYMBOL(__netdev_printk);
 EXPORT_SYMBOL(__dev_get);
 EXPORT_SYMBOL(__dev_get_by_flags);
 EXPORT_SYMBOL(__dev_get_by_index);

Re: [PATCH] Net device error logging

[Jim Keniston]

Joe Perches wrote:
> 
> On Mon, 2003-10-06 at 16:52, Jim Keniston wrote:
> > I would like to see it in v2.6 because it's in demand now [1] and its
> > impact is negligible on drivers that don't use it [2].
> 
> It does add another static buffer, not too good for embedded.

Yes, my proposed implementation incurs a one-time cost in RAM
(512 bytes, which could probably be dialed down some).  But
putting more code into the macro (as in your proposal) costs ROM.
I plugged in your version of netdev_printk below (with the
msglevel test added back in to the macro) and rebuilt.  On my
system, the code size of tg3.o grew from 49548 to 50496 (948 bytes),
and e1000.o grew from 61813 to 63357 (1544 bytes).

Linux coding style seems to favor big macros and inline functions,
but I'd think embedded systems would be more interested in
economizing on ROM than on RAM.

> The current implementation makes it more difficult to add __FILE__,
> __LINE__, __FUNCTION__ if anyone wanted to add even more debugging
> content.

Somewhat.  If you don't mind having the __FILE__:__LINE__:__FUNCTION__
info between the interface name and the rest of the message, you can just
stuff them into the arg list -- e.g:
#define netdev_printk(sevlevel, netdev, msglevel, format, arg...	\
	__netdev_printk(sevlevel , netdev , NETIF_MSG_##msglevel ,	\
	"%s:%d:%s: " format , __FILE__ , __LINE__ , __FUNCTION__ , ## arg)

Otherwise you have to modify __netdev_printk() to explicitly incorporate
these values into the message prefix.  Not hard to do.

This issue begs questions such as:
1. Is __netdev_printk's message-prefix format the right one?  If not,
what should it be?
2. Should we support some sort of configurable prefix format?  E.g.,
In my driver, I want the prefix to give the driver name, interface
name, and source file and line number, so...
	netdev->msg_prefix = "%D:%I: %F:%L: ";
3. Should netdev_* instead be used to enforce the "right" format?

> 
> I'd rather use stack space like so:
> 
> static int netdev_printk_prefix(char* message, size_t size, const struct netdevice * netdev)
> {
>         if (netdev->reg_state == NETREG_REGISTERED || !netdev->class_dev.dev)
>                 return snprintf(message, size, "%s: ", netdev->name);
>         return snprintf(msg_header, sizeof(msg_header), "%s (%s %s): ", netdev->name,
>                         netdev->class_dev.dev->driver->name, netdev->class_dev.dev->bus_id);
> }
> 
> #define netdev_printk(sevlevel, netdev, msglevel, format, arg...)       \
> do {    \
>         char msg_header[64];    \
>         netdev_printk_prefix(msg_header, sizeof(msg_header), netdev);   \
>         printk("%s" "%s" format , sevlevel , msg_header , ## arg);      \
> } while (0);
> 
> This still allows __FILE__, etc to be added.

As mentioned above, you need to test NETIF_MSG_##msglevel for a fair comparison.
Also, including 'static int netdev_printk_prefix' in netdevice.h gets me a lot
of messages of the form
   include/linux/netdevice.h:930: warning: `netdev_printk_prefix' defined but not used
when I build.  An obvious solution is to make netdev_printk_prefix extern, but then
it's no more accessible than __netdev_printk() is now.

Jim

Re: [PATCH] Net device error logging

[Larry Kessler]

On Tuesday 07 October 2003 12:31, Jim Keniston wrote:
> 1. Is __netdev_printk's message-prefix format the right one?  If not,
> what should it be?

IMO, yes its the right format, since it identifies which device, and in a
consistent way similar to dev_printk().  What's more important than re-opening
this debate is making the current version available in the base so drivers can
start being modified to use it.  The message-prefix could change, if
experience indicates a benefit for consumers of printk messages.  

> 2. Should we support some sort of configurable prefix format?  E.g.,
> In my driver, I want the prefix to give the driver name, interface
> name, and source file and line number, so...
> 	netdev->msg_prefix = "%D:%I: %F:%L: ";
 
There are cases where a configurable prefix makes sense, but the goal here for
netdev_printk() was clearly stated from the beginning (id which device...no more, 
no less).  

> 3. Should netdev_* instead be used to enforce the "right" format?

Yes, for reasons already stated.