[PATCH net] bonding: make debugging output more succinct

[PATCH net] bonding: make debugging output more succinct

[Jarod Wilson]

Seeing bonding debug log data along the lines of "event: 5" is a bit spartan,
and often requires a lookup table if you don't remember what every event is.
Make use of netdev_cmd_to_name for an improved debugging experience, so for
the prior example, you'll see: "bond_netdev_event received NETDEV_REGISTER"
instead (both are prefixed with the device for which the event pertains).

There are also quite a few places that the netdev_dbg output could stand to
mention exactly which slave the message pertains to (gets messy if you have
multiple slaves all spewing at once to know which one they pertain to).

CC: Jay Vosburgh <j.vosburgh@gmail.com>
CC: Veaceslav Falico <vfalico@gmail.com>
CC: Andy Gospodarek <andy@greyhouse.net>
CC: "David S. Miller" <davem@davemloft.net>
CC: netdev@vger.kernel.org
Signed-off-by: Jarod Wilson <jarod@redhat.com>
---
 drivers/net/bonding/bond_main.c | 27 ++++++++++++++++++---------
 1 file changed, 18 insertions(+), 9 deletions(-)

diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
index 407f4095a37a..4acc352b316b 100644
--- a/drivers/net/bonding/bond_main.c
+++ b/drivers/net/bonding/bond_main.c
@@ -1515,7 +1515,8 @@ int bond_enslave(struct net_device *bond_dev, struct net_device *slave_dev,
 	new_slave->original_mtu = slave_dev->mtu;
 	res = dev_set_mtu(slave_dev, bond->dev->mtu);
 	if (res) {
-		netdev_dbg(bond_dev, "Error %d calling dev_set_mtu\n", res);
+		netdev_dbg(bond_dev, "Error %d calling dev_set_mtu for slave %s\n",
+			   res, slave_dev->name);
 		goto err_free;
 	}
 
@@ -1536,7 +1537,8 @@ int bond_enslave(struct net_device *bond_dev, struct net_device *slave_dev,
 		res = dev_set_mac_address(slave_dev, (struct sockaddr *)&ss,
 					  extack);
 		if (res) {
-			netdev_dbg(bond_dev, "Error %d calling set_mac_address\n", res);
+			netdev_dbg(bond_dev, "Error %d calling set_mac_address for slave %s\n",
+				   res, slave_dev->name);
 			goto err_restore_mtu;
 		}
 	}
@@ -1636,7 +1638,8 @@ int bond_enslave(struct net_device *bond_dev, struct net_device *slave_dev,
 
 	if (new_slave->link != BOND_LINK_DOWN)
 		new_slave->last_link_up = jiffies;
-	netdev_dbg(bond_dev, "Initial state of slave_dev is BOND_LINK_%s\n",
+	netdev_dbg(bond_dev, "%s: Initial state of slave_dev %s is BOND_LINK_%s\n",
+		   __func__, slave_dev->name,
 		   new_slave->link == BOND_LINK_DOWN ? "DOWN" :
 		   (new_slave->link == BOND_LINK_UP ? "UP" : "BACK"));
 
@@ -1679,7 +1682,8 @@ int bond_enslave(struct net_device *bond_dev, struct net_device *slave_dev,
 		bond_set_slave_inactive_flags(new_slave, BOND_SLAVE_NOTIFY_NOW);
 		break;
 	default:
-		netdev_dbg(bond_dev, "This slave is always active in trunk mode\n");
+		netdev_dbg(bond_dev, "This slave (%s) is always active in trunk mode\n",
+			   slave_dev->name);
 
 		/* always active in trunk mode */
 		bond_set_active_slave(new_slave);
@@ -1698,7 +1702,8 @@ int bond_enslave(struct net_device *bond_dev, struct net_device *slave_dev,
 #ifdef CONFIG_NET_POLL_CONTROLLER
 	if (bond->dev->npinfo) {
 		if (slave_enable_netpoll(new_slave)) {
-			netdev_info(bond_dev, "master_dev is using netpoll, but new slave device does not support netpoll\n");
+			netdev_info(bond_dev, "master_dev is using netpoll, but new slave device %s does not support netpoll\n",
+				    slave_dev->name);
 			res = -EBUSY;
 			goto err_detach;
 		}
@@ -1711,19 +1716,22 @@ int bond_enslave(struct net_device *bond_dev, struct net_device *slave_dev,
 	res = netdev_rx_handler_register(slave_dev, bond_handle_frame,
 					 new_slave);
 	if (res) {
-		netdev_dbg(bond_dev, "Error %d calling netdev_rx_handler_register\n", res);
+		netdev_dbg(bond_dev, "Error %d calling netdev_rx_handler_register for slave %s\n",
+			   res, slave_dev->name);
 		goto err_detach;
 	}
 
 	res = bond_master_upper_dev_link(bond, new_slave, extack);
 	if (res) {
-		netdev_dbg(bond_dev, "Error %d calling bond_master_upper_dev_link\n", res);
+		netdev_dbg(bond_dev, "Error %d calling bond_master_upper_dev_link for slave %s\n",
+			   res, slave_dev->name);
 		goto err_unregister;
 	}
 
 	res = bond_sysfs_slave_add(new_slave);
 	if (res) {
-		netdev_dbg(bond_dev, "Error %d calling bond_sysfs_slave_add\n", res);
+		netdev_dbg(bond_dev, "Error %d calling bond_sysfs_slave_add for slave %s\n",
+			   res, slave_dev->name);
 		goto err_upper_unlink;
 	}
 
@@ -3212,7 +3220,8 @@ static int bond_netdev_event(struct notifier_block *this,
 {
 	struct net_device *event_dev = netdev_notifier_info_to_dev(ptr);
 
-	netdev_dbg(event_dev, "event: %lx\n", event);
+	netdev_dbg(event_dev, "%s received %s\n",
+		   __func__, netdev_cmd_to_name(event));
 
 	if (!(event_dev->priv_flags & IFF_BONDING))
 		return NOTIFY_DONE;
-- 
2.20.1

Re: [PATCH net] bonding: make debugging output more succinct

[Joe Perches]

On Fri, 2019-05-24 at 09:56 -0400, Jarod Wilson wrote:
> Seeing bonding debug log data along the lines of "event: 5" is a bit spartan,
> and often requires a lookup table if you don't remember what every event is.
> Make use of netdev_cmd_to_name for an improved debugging experience, so for
> the prior example, you'll see: "bond_netdev_event received NETDEV_REGISTER"
> instead (both are prefixed with the device for which the event pertains).
> 
> There are also quite a few places that the netdev_dbg output could stand to
> mention exactly which slave the message pertains to (gets messy if you have
> multiple slaves all spewing at once to know which one they pertain to).
[]
> diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
[]
> @@ -1515,7 +1515,8 @@ int bond_enslave(struct net_device *bond_dev, struct net_device *slave_dev,
>  	new_slave->original_mtu = slave_dev->mtu;
>  	res = dev_set_mtu(slave_dev, bond->dev->mtu);
>  	if (res) {
> -		netdev_dbg(bond_dev, "Error %d calling dev_set_mtu\n", res);
> +		netdev_dbg(bond_dev, "Error %d calling dev_set_mtu for slave %s\n",
> +			   res, slave_dev->name);

Perhaps better to add and use helper mechanisms like:

#define slave_dbg(bond_dev, slave_dev, fmt, ...)				\
	netdev_dbg(bond_dev, "(slave %s) " fmt, (slave_dev)->name, ##__VA_ARGS__)

So this might be
		slave_dbg(bond_dev, slave_dev, "Error %d calling dev_set_mtu\n",
			  res);
etc...

So there would be a unified style to grep in the logs.

Re: [PATCH net] bonding: make debugging output more succinct

[Jarod Wilson]

On 5/24/19 11:19 AM, Joe Perches wrote:
> On Fri, 2019-05-24 at 09:56 -0400, Jarod Wilson wrote:
>> Seeing bonding debug log data along the lines of "event: 5" is a bit spartan,
>> and often requires a lookup table if you don't remember what every event is.
>> Make use of netdev_cmd_to_name for an improved debugging experience, so for
>> the prior example, you'll see: "bond_netdev_event received NETDEV_REGISTER"
>> instead (both are prefixed with the device for which the event pertains).
>>
>> There are also quite a few places that the netdev_dbg output could stand to
>> mention exactly which slave the message pertains to (gets messy if you have
>> multiple slaves all spewing at once to know which one they pertain to).
> []
>> diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
> []
>> @@ -1515,7 +1515,8 @@ int bond_enslave(struct net_device *bond_dev, struct net_device *slave_dev,
>>   	new_slave->original_mtu = slave_dev->mtu;
>>   	res = dev_set_mtu(slave_dev, bond->dev->mtu);
>>   	if (res) {
>> -		netdev_dbg(bond_dev, "Error %d calling dev_set_mtu\n", res);
>> +		netdev_dbg(bond_dev, "Error %d calling dev_set_mtu for slave %s\n",
>> +			   res, slave_dev->name);
> 
> Perhaps better to add and use helper mechanisms like:
> 
> #define slave_dbg(bond_dev, slave_dev, fmt, ...)				\
> 	netdev_dbg(bond_dev, "(slave %s) " fmt, (slave_dev)->name, ##__VA_ARGS__)
> 
> So this might be
> 		slave_dbg(bond_dev, slave_dev, "Error %d calling dev_set_mtu\n",
> 			  res);
> etc...
> 
> So there would be a unified style to grep in the logs.

I do kind of like that idea. Might also need slave_info and friends as 
well if you really want to get consistent, and eliminate bond_dev as an 
arg to it, since you can figure that out from slave_dev. I'd be game to 
take that little project on. Might be worth peeling out the 
netdev_cmd_to_name() bit from this for consideration right now, since 
it's not quite part of that same conversion.

-- 
Jarod Wilson
jarod@redhat.com

Re: [PATCH net] bonding: make debugging output more succinct

[David Miller]

From: Jarod Wilson <jarod@redhat.com>
Date: Fri, 7 Jun 2019 11:02:34 -0400

> On 6/7/19 10:59 AM, Jarod Wilson wrote:
>> Seeing bonding debug log data along the lines of "event: 5" is a bit
>> spartan,
>> and often requires a lookup table if you don't remember what every
>> event is.
>> Make use of netdev_cmd_to_name for an improved debugging experience,
>> so for
>> the prior example, you'll see: "bond_netdev_event received
>> NETDEV_REGISTER"
>> instead (both are prefixed with the device for which the event
>> pertains).
>> There are also quite a few places that the netdev_dbg output could
>> stand to
>> mention exactly which slave the message pertains to (gets messy if you
>> have
>> multiple slaves all spewing at once to know which one they pertain
>> to).
> 
> Argh. Please drop this one, detritus in my git tree when I hit git
> send-email caused this earlier iteration of patch 1 of the set this is
> threaded with to go out.

Ok.

Re: [PATCH net] bonding: make debugging output more succinct

[Jarod Wilson]

On 6/7/19 10:59 AM, Jarod Wilson wrote:
> Seeing bonding debug log data along the lines of "event: 5" is a bit spartan,
> and often requires a lookup table if you don't remember what every event is.
> Make use of netdev_cmd_to_name for an improved debugging experience, so for
> the prior example, you'll see: "bond_netdev_event received NETDEV_REGISTER"
> instead (both are prefixed with the device for which the event pertains).
> 
> There are also quite a few places that the netdev_dbg output could stand to
> mention exactly which slave the message pertains to (gets messy if you have
> multiple slaves all spewing at once to know which one they pertain to).

Argh. Please drop this one, detritus in my git tree when I hit git 
send-email caused this earlier iteration of patch 1 of the set this is 
threaded with to go out.

-- 
Jarod Wilson
jarod@redhat.com

[PATCH net] bonding: make debugging output more succinct

[Jarod Wilson]

Seeing bonding debug log data along the lines of "event: 5" is a bit spartan,
and often requires a lookup table if you don't remember what every event is.
Make use of netdev_cmd_to_name for an improved debugging experience, so for
the prior example, you'll see: "bond_netdev_event received NETDEV_REGISTER"
instead (both are prefixed with the device for which the event pertains).

There are also quite a few places that the netdev_dbg output could stand to
mention exactly which slave the message pertains to (gets messy if you have
multiple slaves all spewing at once to know which one they pertain to).

CC: Jay Vosburgh <j.vosburgh@gmail.com>
CC: Veaceslav Falico <vfalico@gmail.com>
CC: Andy Gospodarek <andy@greyhouse.net>
CC: "David S. Miller" <davem@davemloft.net>
CC: netdev@vger.kernel.org
Signed-off-by: Jarod Wilson <jarod@redhat.com>
---
 drivers/net/bonding/bond_main.c | 27 ++++++++++++++++++---------
 1 file changed, 18 insertions(+), 9 deletions(-)

diff --git a/drivers/net/bonding/bond_main.c b/drivers/net/bonding/bond_main.c
index 407f4095a37a..4acc352b316b 100644
--- a/drivers/net/bonding/bond_main.c
+++ b/drivers/net/bonding/bond_main.c
@@ -3212,7 +3220,8 @@ static int bond_netdev_event(struct notifier_block *this,
 {
 	struct net_device *event_dev = netdev_notifier_info_to_dev(ptr);
 
-	netdev_dbg(event_dev, "event: %lx\n", event);
+	netdev_dbg(event_dev, "%s received %s\n",
+		   __func__, netdev_cmd_to_name(event));
 
 	if (!(event_dev->priv_flags & IFF_BONDING))
 		return NOTIFY_DONE;
-- 
2.20.1