Net device error logging

This proposal extends the concept of Linux 2.5's dev_* logging macros to support network devices. This feature is intended to simplify error-log analysis by programs (such as health/configuration monitors) and by ordinary people who need clearer error reporting.

Two patches are appended. The first implements the feature described here. The second is provided by Scott Feldman, maintainer of the e1000 Ethernet driver, and demonstrates how he could modify that driver to take advantage of this feature.

BACKGROUND: dev_* MACROS
The existing dev_* macros (dev_dbg, dev_info, dev_warn, dev_err, dev_printk) are defined in linux/device.h in Linux 2.5. When used in place of printk, they enhance the standard printk message by prepending the driver name and bus ID of the device in question. These macros take the usual printk args, plus a pointer to the relevant struct device. The driver name and bus ID enable the log reader to find the device's information in sysfs.

netdev_* MACROS
Alan Cox suggested that the dev_* macros could serve as examples for logging macros in other parts of the kernel. This proposal defines analogous macros for network devices. These new macros are netdev_dbg, netdev_info, netdev_warn, netdev_err, and netdev_printk. These macros take the usual printk args, plus a pointer to the relevant struct net_device.

The enhanced printk message includes the device's interface name (e.g., "eth0"). It also includes the driver name and bus ID of the underlying device; this makes it easy to associate the message with the network device's sysfs info.

For example, changing

	printk(KERN_ERR "The EEPROM Checksum Is Not Valid\n");
to
	netdev_err(netdev, "The EEPROM Checksum Is Not Valid\n");

changes the message from
The EEPROM Checksum Is Not Valid
to something like
eth0 e1000 40:0b.0: The EEPROM Checksum Is Not Valid
You could find out more about the indicated device by looking in the directory /sysfs/bus/*/drivers/e1000/40:0b.0.

This proposal adds a new member, dev, to struct net_device that points to the underlying struct device. This pointer is typically set in the driver's probe function.

For simplicity, the netdev_* macros assume that netdev (the net_device arg) and netdev->name are non-null. The latter is true as soon as you call alloc_netdev() for the device.

Jim Keniston
IBM Linux Technology Center
-----

diff -Naur linux.org/include/linux/netdevice.h linux.netdev_printk.patched/include/linux/netdevice.h
@@ -28,7 +28,7 @@
 #include <linux/if.h>
 #include <linux/if_ether.h>
 #include <linux/if_packet.h>
-#include <linux/kobject.h>
+#include <linux/device.h>
 
 #include <asm/atomic.h>
 #include <asm/cache.h>

@@ -269,6 +269,7 @@
 	unsigned long		state;
 
 	struct net_device	*next;
+	struct device		*dev;		/* underlying device */
 	
 	/* The device initialization function. Called only once. */
 	int			(*init)(struct net_device *dev);

@@ -835,6 +836,32 @@
 extern void		dev_clear_fastroute(struct net_device *dev);
 #endif
 
+/* debugging and troubleshooting/diagnostic helpers. */
+/**
+ * netdev_printk() - Log message with interface name, driver name, bus ID.
+ * @level: severity level -- e.g., KERN_INFO
+ * @netdev: net_device pointer
+ * @format: as with printk
+ * @args: as with printk
+ */
+#define netdev_printk(level, netdev, format, arg...)	\
+	printk(level "%s %s %s: " format , (netdev)->name ,	\
+		((netdev)->dev ? (netdev)->dev->driver->name : "") ,	\
+		((netdev)->dev ? (netdev)->dev->bus_id : "") , ## arg)
+
+#ifdef DEBUG
+#define netdev_dbg(netdev, format, arg...)		\
+	netdev_printk(KERN_DEBUG , netdev , format , ## arg)
+#else
+#define netdev_dbg(netdev, format, arg...) do {} while (0)
+#endif
+
+#define netdev_err(netdev, format, arg...)		\
+	netdev_printk(KERN_ERR , netdev , format , ## arg)
+#define netdev_info(netdev, format, arg...)		\
+	netdev_printk(KERN_INFO , netdev , format , ## arg)
+#define netdev_warn(netdev, format, arg...)		\
+	netdev_printk(KERN_WARNING , netdev , format , ## arg)
 
 #endif /* __KERNEL__ */
 

diff -Naurp linux-2.5.68/drivers/net/e1000/e1000.h linux-2.5.68/drivers/net/e1000.ev/e1000.h
@@ -80,14 +80,6 @@ struct e1000_adapter;
 
 #include "e1000_hw.h"
 
-#if DBG
-#define E1000_DBG(args...) printk(KERN_DEBUG "e1000: " args)
-#else
-#define E1000_DBG(args...)
-#endif
-
-#define E1000_ERR(args...) printk(KERN_ERR "e1000: " args)
-
 #define E1000_MAX_INTR 10
 
 /* Supported Rx Buffer Sizes */

diff -Naurp linux-2.5.68/drivers/net/e1000/e1000_main.c linux-2.5.68/drivers/net/e1000.ev/e1000_main.c
@@ -375,7 +375,8 @@ e1000_probe(struct pci_dev *pdev,
 		pci_using_dac = 1;
 	} else {
 		if((i = pci_set_dma_mask(pdev, PCI_DMA_32BIT))) {
-			E1000_ERR("No usable DMA configuration, aborting\n");
+			printk(KERN_ERR
+			      "e1000: No usable DMA configuration, aborting\n");
 			return i;
 		}
 		pci_using_dac = 0;

@@ -393,6 +394,7 @@ e1000_probe(struct pci_dev *pdev,
 	SET_MODULE_OWNER(netdev);
 
 	pci_set_drvdata(pdev, netdev);
+	netdev->dev = &pdev->dev;
 	adapter = netdev->priv;
 	adapter->netdev = netdev;
 	adapter->pdev = pdev;

@@ -465,7 +467,7 @@ e1000_probe(struct pci_dev *pdev,
 	/* make sure the EEPROM is good */
 
 	if(e1000_validate_eeprom_checksum(&adapter->hw) < 0) {
-		printk(KERN_ERR "The EEPROM Checksum Is Not Valid\n");
+		netdev_err(netdev, "The EEPROM Checksum Is Not Valid\n");
 		goto err_eeprom;
 	}
 

@@ -505,7 +507,7 @@ e1000_probe(struct pci_dev *pdev,
 	netif_carrier_off(netdev);
 	netif_stop_queue(netdev);
 
-	printk(KERN_INFO "%s: %s\n", netdev->name, adapter->id_string);
+	netdev_info(netdev, "%s\n", adapter->id_string);
 	e1000_check_options(adapter);
 
 	/* Initial Wake on LAN setting

@@ -607,7 +609,7 @@ e1000_sw_init(struct e1000_adapter *adap
 	/* identify the MAC */
 
 	if (e1000_set_mac_type(hw)) {
-		E1000_ERR("Unknown MAC Type\n");
+		printk(KERN_ERR "Unknown MAC Type\n");
 		return -1;
 	}
 

@@ -1360,9 +1362,9 @@ e1000_watchdog(unsigned long data)
 			                           &adapter->link_speed,
 			                           &adapter->link_duplex);
 
-			printk(KERN_INFO
-			       "e1000: %s NIC Link is Up %d Mbps %s\n",
-			       netdev->name, adapter->link_speed,
+			netdev_info(netdev,
+			       "e1000: NIC Link is Up %d Mbps %s\n",
+			       adapter->link_speed,
 			       adapter->link_duplex == FULL_DUPLEX ?
 			       "Full Duplex" : "Half Duplex");
 

@@ -1375,9 +1377,7 @@ e1000_watchdog(unsigned long data)
 		if(netif_carrier_ok(netdev)) {
 			adapter->link_speed = 0;
 			adapter->link_duplex = 0;
-			printk(KERN_INFO
-			       "e1000: %s NIC Link is Down\n",
-			       netdev->name);
+			netdev_info(netdev, "e1000: NIC Link is Down\n");
 			netif_carrier_off(netdev);
 			netif_stop_queue(netdev);
 			mod_timer(&adapter->phy_info_timer, jiffies + 2 * HZ);

@@ -1774,7 +1774,7 @@ e1000_change_mtu(struct net_device *netd
 
 	if((max_frame < MINIMUM_ETHERNET_FRAME_SIZE) ||
 	   (max_frame > MAX_JUMBO_FRAME_SIZE)) {
-		E1000_ERR("Invalid MTU setting\n");
+		printk(KERN_ERR "Invalid MTU setting\n");
 		return -EINVAL;
 	}
 

@@ -1782,7 +1782,7 @@ e1000_change_mtu(struct net_device *netd
 		adapter->rx_buffer_len = E1000_RXBUFFER_2048;
 
 	} else if(adapter->hw.mac_type < e1000_82543) {
-		E1000_ERR("Jumbo Frames not supported on 82542\n");
+		printk(KERN_ERR "Jumbo Frames not supported on 82542\n");
 		return -EINVAL;
 
 	} else if(max_frame <= E1000_RXBUFFER_4096) {

@@ -2149,7 +2149,8 @@ e1000_clean_rx_irq(struct e1000_adapter 
 
 			/* All receives must fit into a single buffer */
 
-			E1000_DBG("Receive packet consumed multiple buffers\n");
+			netdev_dbg(netdev,
+			         "Receive packet consumed multiple buffers\n");
 
 			dev_kfree_skb_irq(skb);
 			rx_desc->status = 0;

diff -Naurp linux-2.5.68/drivers/net/e1000/e1000_osdep.h linux-2.5.68/drivers/net/e1000.ev/e1000_osdep.h
@@ -60,7 +60,7 @@ typedef enum {
 } boolean_t;
 
 #define ASSERT(x)	if(!(x)) BUG()
-#define MSGOUT(S, A, B)	printk(KERN_DEBUG S "\n", A, B)
+#define MSGOUT(S, A, B)	printk(S "\n", A, B)
 
 #if DBG
 #define DEBUGOUT(S)		printk(KERN_DEBUG S "\n")

I'm happy to discuss this. As I see it, there are at least 4 possibilities:
1. Standardize on the netif_msg_xxx (bit map) approach.
2. Standardize on simple reporting levels (if (debug >= 2)...).
3. Make the driver provide a filtering function, which can do #1, #2 or some
other driver-specific test.
4. Status quo: make the message-level test before calling netdev_xxx.

The people I've talked to tend to prefer either #1 or #4, although we haven't
talked much about #2 and #3. There's also the issue of whether all this should
be gated by the severity level -- e.g., always log a message that has a severity
in the range KERN_ERR - KERN_EMERG.

I think message filtering is a good idea. I also think the following features
would be useful:
a. Identify which device and driver the message refers to. b. Call net_ratelimit() in appropriate contexts.
c. Capture caller info (__FILE__ and/or __FUNCTION__).
d. Actually log the severity level. (I know, this is a syslogd issue.) e. Standardize certain messages so that all drivers log predictable, standard
messages (perhaps along with driver-specific info) under certain circumstances.
e. Capture the messages in a form that is more amenable to automated analysis
than is plain text.
f. Capture the messages in a form that lends itself to translation (in user space)
to other languages.

This can all be done. Most of it has already been implemented and/or suggested at
one time or another. Message filtering plus a, b, and e require the caller to
provide additional info. The other features have other tradeoffs. Our experience
with the dev_* macros is that at least some maintainers consider (a) worth the
tradeoff. If there's a demand for other features, we are happy to try to oblige.

Jim

Number one is the desired direction for net drivers.

this is already done in net drivers

this is questionable. The netif_xxx messages are _already_ designed to be used in order of increasing verbosity. If the user selects the more verbose class of messages, then rate-limiting may not be appropriate.

No need, in net drivers. All of them already print out network interface, which is all you need to know.

Yes, standardization of net driver messages is desired.

Jeff

[SNIP]

In some of them, but not in most of them. Looking at explicit calls to printk in drivers/net, I see that about 1 in 3 is tagged with what appears to be the interface name. 3/4 of the source files that call printk explicitly tag fewer than half their printks. It's pretty rare for a printk to be tagged with the driver name. We'd probably get a more promising picture if we took into account the various macros that wrap printk, and some untagged printks are continuations of tagged printks, but with over 8000 untagged printks in drivers/net, it's by no means an ideal situation. Maybe the "poorly behaved" drivers are no longer of interest?

1. Not nearly all of them do. (See above.)
2. Depending on the driver and how familar you are with your system's configuration, it may take some work to map the interface name to the driver.

Net-driver support for sysfs should eventually reach the point where you can find useful info in sysfs given the interface name, right? Until then, I still think messages should report the driver as well as the interface name. If you do this via netdev_xxx, then once we're at sysfs nirvana, you just redefine the netdev_xxx macros to drop the bus ID and driver name.

Jim