[libvirt] [PATCH 0/3] networking logging improvements

1/3 was originally part of 2/3, but I decided I should split it out since it changes something other than logging (although it should still be a NOP). 2/3 changes what's logged when a domain interface is connected to / disconnected from a network, and 3/3 changes what is logged during 802.1QbX associate/disassociate operations. All of these logging changed have proven useful to me when debugging 802.1QbX problems on a downstream version of libvirt (0.10.2 in RHEL6), so I thought I'd share the joy :-) Laine Stump (3): network: consolidate connection count updates for device pool network: consolidated info log for all network allocate/free operations util: clean up and expand 802.1QbX negotiation logging src/network/bridge_driver.c | 91 +++++++++++++++++++--------------------- src/util/virnetdevvportprofile.c | 60 ++++++++++++++++++++++---- 2 files changed, 95 insertions(+), 56 deletions(-) -- 2.5.0

networkReleaseActualDevice() and networkNotifyActualDevice() both were updating the individual devices' connections count in two separate places (unlike networkAllocateActualDevice() which does it in a single unified place after success:). The code is correct, but prone to confusion / later breakage. All of these updates are anyway located at the end of if/else clauses that are (with the exception of a single VIR_DEBUG() in each case) immediately followed by the success: label anyway, so this patch replaces the duplicated ++/-- instructions with a single ++/-- inside a qualifying "if (dev)" down below success:. (NB: if dev != NULL, by definition we are using a device (either pci or netdev, doesn't matter for these purposes) from the network's pool) The VIR_DEBUG args (which will be replaced in a followup patch anyway) were all adjusted to account for the connection count being out of date at the time. --- src/network/bridge_driver.c | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/src/network/bridge_driver.c b/src/network/bridge_driver.c index c19696c..dcd38ed 100644 --- a/src/network/bridge_driver.c +++ b/src/network/bridge_driver.c @@ -1,7 +1,7 @@ /* * bridge_driver.c: core driver methods for managing network * - * Copyright (C) 2006-2015 Red Hat, Inc. + * Copyright (C) 2006-2016 Red Hat, Inc. * Copyright (C) 2006 Daniel P. Berrange * * This library is free software; you can redistribute it and/or @@ -4389,10 +4389,8 @@ networkNotifyActualDevice(virDomainDefPtr dom, goto error; } - /* we are now assured of success, so mark the allocation */ - dev->connections++; VIR_DEBUG("Using physical device %s, connections %d", - dev->device.dev, dev->connections); + dev->device.dev, dev->connections + 1); } else /* if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) */ { virDomainHostdevDefPtr hostdev; @@ -4444,8 +4442,6 @@ networkNotifyActualDevice(virDomainDefPtr dom, goto error; } - /* we are now assured of success, so mark the allocation */ - dev->connections++; VIR_DEBUG("Using physical device %04x:%02x:%02x.%x, connections %d", dev->device.pci.domain, dev->device.pci.bus, dev->device.pci.slot, dev->device.pci.function, @@ -4454,6 +4450,8 @@ networkNotifyActualDevice(virDomainDefPtr dom, success: netdef->connections++; + if (dev) + dev->connections++; VIR_DEBUG("Using network %s, %d connections", netdef->name, netdef->connections); @@ -4562,9 +4560,8 @@ networkReleaseActualDevice(virDomainDefPtr dom, goto error; } - dev->connections--; VIR_DEBUG("Releasing physical device %s, connections %d", - dev->device.dev, dev->connections); + dev->device.dev, dev->connections - 1); } else /* if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) */ { virDomainHostdevDefPtr hostdev; @@ -4598,16 +4595,18 @@ networkReleaseActualDevice(virDomainDefPtr dom, goto error; } - dev->connections--; VIR_DEBUG("Releasing physical device %04x:%02x:%02x.%x, connections %d", dev->device.pci.domain, dev->device.pci.bus, dev->device.pci.slot, dev->device.pci.function, - dev->connections); + dev->connections - 1); } success: if (iface->data.network.actual) { netdef->connections--; + if (dev) + dev->connections--; + VIR_DEBUG("Releasing network %s, %d connections", netdef->name, netdef->connections); -- 2.5.0

On 02/11/2016 04:37 PM, Laine Stump wrote:
networkReleaseActualDevice() and networkNotifyActualDevice() both were updating the individual devices' connections count in two separate places (unlike networkAllocateActualDevice() which does it in a single unified place after success:). The code is correct, but prone to confusion / later breakage. All of these updates are anyway located at the end of if/else clauses that are (with the exception of a single VIR_DEBUG() in each case) immediately followed by the success: label anyway, so this patch replaces the duplicated ++/-- instructions with a single ++/-- inside a qualifying "if (dev)" down below success:. (NB: if dev != NULL, by definition we are using a device (either pci or netdev, doesn't matter for these purposes) from the network's pool)
The VIR_DEBUG args (which will be replaced in a followup patch anyway) were all adjusted to account for the connection count being out of date at the time. --- src/network/bridge_driver.c | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-)
ACK John

There are three functions that deal with allocating and freeing devices from a networks netdev/pci device pool: network(Allocate|Notify|Release)ActualDevice(). These functions also maintain a counter of the number of domains currently using a network (regardless of whether or not that network uses a device pool). Each of these functions had multiple log messages (output using VIR_DEBUG) that were in slightly different formats and gave varying amounts of information. This patch creates a single function to log the pertinent information in a consistent manner for all three of these functions. Along with assuring that all the functions produce a consistent form of output (and making it simpler to change), it adds the MAC address of the domain interface involved in the operation, making it possible to verify which interface of which domain the operation is being done for (assuming that all MAC addresses are unique, of course). All of these messages are raised from DEBUG to INFO, since they don't happen that often (once per interface per domain/libvirtd start or domain stop), and can be very informative and helpful - eliminating the need to log debug level messages makes it much easier to sort these out. --- src/network/bridge_driver.c | 80 ++++++++++++++++++++++----------------------- 1 file changed, 39 insertions(+), 41 deletions(-) diff --git a/src/network/bridge_driver.c b/src/network/bridge_driver.c index dcd38ed..c305f8e 100644 --- a/src/network/bridge_driver.c +++ b/src/network/bridge_driver.c @@ -3863,6 +3863,40 @@ int networkRegister(void) * driver, we will need to present these functions via a second * "backend" function table. */ +static void +networkLogAllocation(virNetworkDefPtr netdef, + virDomainNetType actualType, + virNetworkForwardIfDefPtr dev, + virDomainNetDefPtr iface, + bool inUse) +{ + char macStr[VIR_MAC_STRING_BUFLEN]; + const char *verb = inUse ? "using" : "releasing"; + + if (!dev) { + VIR_INFO("MAC %s %s network %s (%d connections)", + virMacAddrFormat(&iface->mac, macStr), verb, + netdef->name, netdef->connections); + } else { + /* mark the allocation */ + dev->connections++; + if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) { + VIR_INFO("MAC %s %s network %s (%d connections) " + "physical device %04x:%02x:%02x.%x (%d connections)", + virMacAddrFormat(&iface->mac, macStr), verb, + netdef->name, netdef->connections, + dev->device.pci.domain, dev->device.pci.bus, + dev->device.pci.slot, dev->device.pci.function, + dev->connections); + } else { + VIR_INFO("MAC %s %s network %s (%d connections) " + "physical device %s (%d connections)", + virMacAddrFormat(&iface->mac, macStr), verb, + netdef->name, netdef->connections, + dev->device.dev, dev->connections); + } + } +} /* networkAllocateActualDevice: * @dom: domain definition that @iface belongs to @@ -4236,23 +4270,8 @@ networkAllocateActualDevice(virDomainDefPtr dom, if (netdef) { netdef->connections++; - VIR_DEBUG("Using network %s, %d connections", - netdef->name, netdef->connections); - - if (dev) { - /* mark the allocation */ + if (dev) dev->connections++; - if (actualType != VIR_DOMAIN_NET_TYPE_HOSTDEV) { - VIR_DEBUG("Using physical device %s, %d connections", - dev->device.dev, dev->connections); - } else { - VIR_DEBUG("Using physical device %04x:%02x:%02x.%x, connections %d", - dev->device.pci.domain, dev->device.pci.bus, - dev->device.pci.slot, dev->device.pci.function, - dev->connections); - } - } - /* finally we can call the 'plugged' hook script if any */ if (networkRunHook(network, dom, iface, VIR_HOOK_NETWORK_OP_IFACE_PLUGGED, @@ -4263,6 +4282,7 @@ networkAllocateActualDevice(virDomainDefPtr dom, dev->connections--; goto error; } + networkLogAllocation(netdef, actualType, dev, iface, true); } ret = 0; @@ -4388,10 +4408,6 @@ networkNotifyActualDevice(virDomainDefPtr dom, netdef->name, actualDev); goto error; } - - VIR_DEBUG("Using physical device %s, connections %d", - dev->device.dev, dev->connections + 1); - } else /* if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) */ { virDomainHostdevDefPtr hostdev; @@ -4441,20 +4457,12 @@ networkNotifyActualDevice(virDomainDefPtr dom, dev->device.pci.slot, dev->device.pci.function); goto error; } - - VIR_DEBUG("Using physical device %04x:%02x:%02x.%x, connections %d", - dev->device.pci.domain, dev->device.pci.bus, - dev->device.pci.slot, dev->device.pci.function, - dev->connections); } success: netdef->connections++; if (dev) dev->connections++; - VIR_DEBUG("Using network %s, %d connections", - netdef->name, netdef->connections); - /* finally we can call the 'plugged' hook script if any */ if (networkRunHook(network, dom, iface, VIR_HOOK_NETWORK_OP_IFACE_PLUGGED, VIR_HOOK_SUBOP_BEGIN) < 0) { @@ -4464,6 +4472,7 @@ networkNotifyActualDevice(virDomainDefPtr dom, netdef->connections--; goto error; } + networkLogAllocation(netdef, actualType, dev, iface, true); ret = 0; cleanup: @@ -4475,6 +4484,7 @@ networkNotifyActualDevice(virDomainDefPtr dom, } + /* networkReleaseActualDevice: * @dom: domain definition that @iface belongs to * @iface: a domain's NetDef (interface definition) @@ -4559,10 +4569,6 @@ networkReleaseActualDevice(virDomainDefPtr dom, netdef->name, actualDev); goto error; } - - VIR_DEBUG("Releasing physical device %s, connections %d", - dev->device.dev, dev->connections - 1); - } else /* if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) */ { virDomainHostdevDefPtr hostdev; @@ -4594,11 +4600,6 @@ networkReleaseActualDevice(virDomainDefPtr dom, hostdev->source.subsys.u.pci.addr.function); goto error; } - - VIR_DEBUG("Releasing physical device %04x:%02x:%02x.%x, connections %d", - dev->device.pci.domain, dev->device.pci.bus, - dev->device.pci.slot, dev->device.pci.function, - dev->connections - 1); } success: @@ -4606,13 +4607,10 @@ networkReleaseActualDevice(virDomainDefPtr dom, netdef->connections--; if (dev) dev->connections--; - - VIR_DEBUG("Releasing network %s, %d connections", - netdef->name, netdef->connections); - /* finally we can call the 'unplugged' hook script if any */ networkRunHook(network, dom, iface, VIR_HOOK_NETWORK_OP_IFACE_UNPLUGGED, VIR_HOOK_SUBOP_BEGIN); + networkLogAllocation(netdef, actualType, dev, iface, false); } ret = 0; cleanup: -- 2.5.0

On 02/11/2016 04:37 PM, Laine Stump wrote:
There are three functions that deal with allocating and freeing devices from a networks netdev/pci device pool: network(Allocate|Notify|Release)ActualDevice(). These functions also maintain a counter of the number of domains currently using a network (regardless of whether or not that network uses a device pool). Each of these functions had multiple log messages (output using VIR_DEBUG) that were in slightly different formats and gave varying amounts of information.
This patch creates a single function to log the pertinent information in a consistent manner for all three of these functions. Along with assuring that all the functions produce a consistent form of output (and making it simpler to change), it adds the MAC address of the domain interface involved in the operation, making it possible to verify which interface of which domain the operation is being done for (assuming that all MAC addresses are unique, of course).
All of these messages are raised from DEBUG to INFO, since they don't happen that often (once per interface per domain/libvirtd start or domain stop), and can be very informative and helpful - eliminating the need to log debug level messages makes it much easier to sort these out. --- src/network/bridge_driver.c | 80 ++++++++++++++++++++++----------------------- 1 file changed, 39 insertions(+), 41 deletions(-)
diff --git a/src/network/bridge_driver.c b/src/network/bridge_driver.c index dcd38ed..c305f8e 100644 --- a/src/network/bridge_driver.c +++ b/src/network/bridge_driver.c @@ -3863,6 +3863,40 @@ int networkRegister(void) * driver, we will need to present these functions via a second * "backend" function table. */
^^^ looks like the above error message needs to move below this function. You could add a quick comment here, too
+static void +networkLogAllocation(virNetworkDefPtr netdef, + virDomainNetType actualType, + virNetworkForwardIfDefPtr dev, + virDomainNetDefPtr iface, + bool inUse) +{ + char macStr[VIR_MAC_STRING_BUFLEN]; + const char *verb = inUse ? "using" : "releasing"; + + if (!dev) { + VIR_INFO("MAC %s %s network %s (%d connections)", + virMacAddrFormat(&iface->mac, macStr), verb, + netdef->name, netdef->connections); + } else { + /* mark the allocation */ + dev->connections++;
^^ Isn't this a duplicate [1]? Probably don't want these two lines
+ if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) { + VIR_INFO("MAC %s %s network %s (%d connections) " + "physical device %04x:%02x:%02x.%x (%d connections)", + virMacAddrFormat(&iface->mac, macStr), verb, + netdef->name, netdef->connections, + dev->device.pci.domain, dev->device.pci.bus, + dev->device.pci.slot, dev->device.pci.function, + dev->connections); + } else { + VIR_INFO("MAC %s %s network %s (%d connections) " + "physical device %s (%d connections)", + virMacAddrFormat(&iface->mac, macStr), verb, + netdef->name, netdef->connections, + dev->device.dev, dev->connections); + } + } +}
/* networkAllocateActualDevice: * @dom: domain definition that @iface belongs to @@ -4236,23 +4270,8 @@ networkAllocateActualDevice(virDomainDefPtr dom,
if (netdef) { netdef->connections++; - VIR_DEBUG("Using network %s, %d connections", - netdef->name, netdef->connections); - - if (dev) { - /* mark the allocation */ + if (dev) dev->connections++;
[1] ?
- if (actualType != VIR_DOMAIN_NET_TYPE_HOSTDEV) { - VIR_DEBUG("Using physical device %s, %d connections", - dev->device.dev, dev->connections); - } else { - VIR_DEBUG("Using physical device %04x:%02x:%02x.%x, connections %d", - dev->device.pci.domain, dev->device.pci.bus, - dev->device.pci.slot, dev->device.pci.function, - dev->connections); - } - } - /* finally we can call the 'plugged' hook script if any */ if (networkRunHook(network, dom, iface, VIR_HOOK_NETWORK_OP_IFACE_PLUGGED, @@ -4263,6 +4282,7 @@ networkAllocateActualDevice(virDomainDefPtr dom, dev->connections--; goto error; } + networkLogAllocation(netdef, actualType, dev, iface, true);
If the Hook fails, then there's no messages printed... Whether that matters (they used to be regardless).
}
ret = 0; @@ -4388,10 +4408,6 @@ networkNotifyActualDevice(virDomainDefPtr dom, netdef->name, actualDev); goto error; } - - VIR_DEBUG("Using physical device %s, connections %d", - dev->device.dev, dev->connections + 1); - } else /* if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) */ { virDomainHostdevDefPtr hostdev;
@@ -4441,20 +4457,12 @@ networkNotifyActualDevice(virDomainDefPtr dom, dev->device.pci.slot, dev->device.pci.function); goto error; } - - VIR_DEBUG("Using physical device %04x:%02x:%02x.%x, connections %d", - dev->device.pci.domain, dev->device.pci.bus, - dev->device.pci.slot, dev->device.pci.function, - dev->connections); }
success: netdef->connections++; if (dev) dev->connections++; - VIR_DEBUG("Using network %s, %d connections", - netdef->name, netdef->connections); - /* finally we can call the 'plugged' hook script if any */ if (networkRunHook(network, dom, iface, VIR_HOOK_NETWORK_OP_IFACE_PLUGGED, VIR_HOOK_SUBOP_BEGIN) < 0) { @@ -4464,6 +4472,7 @@ networkNotifyActualDevice(virDomainDefPtr dom, netdef->connections--; goto error; } + networkLogAllocation(netdef, actualType, dev, iface, true);
Another that may not print if Hook fails...
ret = 0; cleanup: @@ -4475,6 +4484,7 @@ networkNotifyActualDevice(virDomainDefPtr dom, }
+ /* networkReleaseActualDevice: * @dom: domain definition that @iface belongs to * @iface: a domain's NetDef (interface definition) @@ -4559,10 +4569,6 @@ networkReleaseActualDevice(virDomainDefPtr dom, netdef->name, actualDev); goto error; } - - VIR_DEBUG("Releasing physical device %s, connections %d", - dev->device.dev, dev->connections - 1); - } else /* if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) */ { virDomainHostdevDefPtr hostdev;
@@ -4594,11 +4600,6 @@ networkReleaseActualDevice(virDomainDefPtr dom, hostdev->source.subsys.u.pci.addr.function); goto error; } - - VIR_DEBUG("Releasing physical device %04x:%02x:%02x.%x, connections %d", - dev->device.pci.domain, dev->device.pci.bus, - dev->device.pci.slot, dev->device.pci.function, - dev->connections - 1); }
success: @@ -4606,13 +4607,10 @@ networkReleaseActualDevice(virDomainDefPtr dom, netdef->connections--; if (dev) dev->connections--; - - VIR_DEBUG("Releasing network %s, %d connections", - netdef->name, netdef->connections); - /* finally we can call the 'unplugged' hook script if any */ networkRunHook(network, dom, iface, VIR_HOOK_NETWORK_OP_IFACE_UNPLUGGED, VIR_HOOK_SUBOP_BEGIN);
Existing... no status check like there are on other calls...
+ networkLogAllocation(netdef, actualType, dev, iface, false);
And this one prints regardless... Your call on how to proceed - that is not printing if Hook fails is desired. ACK as long as the connections++ is removed from networkLogAllocation John
} ret = 0; cleanup:

On 02/12/2016 04:39 PM, John Ferlan wrote:
On 02/11/2016 04:37 PM, Laine Stump wrote:
There are three functions that deal with allocating and freeing devices from a networks netdev/pci device pool: network(Allocate|Notify|Release)ActualDevice(). These functions also maintain a counter of the number of domains currently using a network (regardless of whether or not that network uses a device pool). Each of these functions had multiple log messages (output using VIR_DEBUG) that were in slightly different formats and gave varying amounts of information.
This patch creates a single function to log the pertinent information in a consistent manner for all three of these functions. Along with assuring that all the functions produce a consistent form of output (and making it simpler to change), it adds the MAC address of the domain interface involved in the operation, making it possible to verify which interface of which domain the operation is being done for (assuming that all MAC addresses are unique, of course).
All of these messages are raised from DEBUG to INFO, since they don't happen that often (once per interface per domain/libvirtd start or domain stop), and can be very informative and helpful - eliminating the need to log debug level messages makes it much easier to sort these out. --- src/network/bridge_driver.c | 80 ++++++++++++++++++++++----------------------- 1 file changed, 39 insertions(+), 41 deletions(-)
diff --git a/src/network/bridge_driver.c b/src/network/bridge_driver.c index dcd38ed..c305f8e 100644 --- a/src/network/bridge_driver.c +++ b/src/network/bridge_driver.c @@ -3863,6 +3863,40 @@ int networkRegister(void) * driver, we will need to present these functions via a second * "backend" function table. */ ^^^ looks like the above error message needs to move below this function. You could add a quick comment here, too
+static void +networkLogAllocation(virNetworkDefPtr netdef, + virDomainNetType actualType, + virNetworkForwardIfDefPtr dev, + virDomainNetDefPtr iface, + bool inUse) +{ + char macStr[VIR_MAC_STRING_BUFLEN]; + const char *verb = inUse ? "using" : "releasing"; + + if (!dev) { + VIR_INFO("MAC %s %s network %s (%d connections)", + virMacAddrFormat(&iface->mac, macStr), verb, + netdef->name, netdef->connections); + } else { + /* mark the allocation */ + dev->connections++; ^^ Isn't this a duplicate [1]? Probably don't want these two lines
Yikes! Don't know how I overlooked that. Thanks!
+ if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) { + VIR_INFO("MAC %s %s network %s (%d connections) " + "physical device %04x:%02x:%02x.%x (%d connections)", + virMacAddrFormat(&iface->mac, macStr), verb, + netdef->name, netdef->connections, + dev->device.pci.domain, dev->device.pci.bus, + dev->device.pci.slot, dev->device.pci.function, + dev->connections); + } else { + VIR_INFO("MAC %s %s network %s (%d connections) " + "physical device %s (%d connections)", + virMacAddrFormat(&iface->mac, macStr), verb, + netdef->name, netdef->connections, + dev->device.dev, dev->connections); + } + } +}
/* networkAllocateActualDevice: * @dom: domain definition that @iface belongs to @@ -4236,23 +4270,8 @@ networkAllocateActualDevice(virDomainDefPtr dom,
if (netdef) { netdef->connections++; - VIR_DEBUG("Using network %s, %d connections", - netdef->name, netdef->connections); - - if (dev) { - /* mark the allocation */ + if (dev) dev->connections++; [1] ?
- if (actualType != VIR_DOMAIN_NET_TYPE_HOSTDEV) { - VIR_DEBUG("Using physical device %s, %d connections", - dev->device.dev, dev->connections); - } else { - VIR_DEBUG("Using physical device %04x:%02x:%02x.%x, connections %d", - dev->device.pci.domain, dev->device.pci.bus, - dev->device.pci.slot, dev->device.pci.function, - dev->connections); - } - } - /* finally we can call the 'plugged' hook script if any */ if (networkRunHook(network, dom, iface, VIR_HOOK_NETWORK_OP_IFACE_PLUGGED, @@ -4263,6 +4282,7 @@ networkAllocateActualDevice(virDomainDefPtr dom, dev->connections--; goto error; } + networkLogAllocation(netdef, actualType, dev, iface, true); If the Hook fails, then there's no messages printed... Whether that matters (they used to be regardless).
Since nothing is allocated from the network when the hook fails, it makes sense to not log the message in that case. In the past we were actually *incorrectly* logging a message stating that a new interface had been connected to the network when this was in fact not true.
}
ret = 0; @@ -4388,10 +4408,6 @@ networkNotifyActualDevice(virDomainDefPtr dom, netdef->name, actualDev); goto error; } - - VIR_DEBUG("Using physical device %s, connections %d", - dev->device.dev, dev->connections + 1); - } else /* if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) */ { virDomainHostdevDefPtr hostdev;
@@ -4441,20 +4457,12 @@ networkNotifyActualDevice(virDomainDefPtr dom, dev->device.pci.slot, dev->device.pci.function); goto error; } - - VIR_DEBUG("Using physical device %04x:%02x:%02x.%x, connections %d", - dev->device.pci.domain, dev->device.pci.bus, - dev->device.pci.slot, dev->device.pci.function, - dev->connections); }
success: netdef->connections++; if (dev) dev->connections++; - VIR_DEBUG("Using network %s, %d connections", - netdef->name, netdef->connections); - /* finally we can call the 'plugged' hook script if any */ if (networkRunHook(network, dom, iface, VIR_HOOK_NETWORK_OP_IFACE_PLUGGED, VIR_HOOK_SUBOP_BEGIN) < 0) { @@ -4464,6 +4472,7 @@ networkNotifyActualDevice(virDomainDefPtr dom, netdef->connections--; goto error; } + networkLogAllocation(netdef, actualType, dev, iface, true);
Another that may not print if Hook fails...
Same response here, although this does point out that the hook run when an interface is newly connected to a network is the same as the hook that is run when libvirtd is restarted and we're just repopulating the network status with existing allocations. I don't know if that's what's wanted/expected or not, but most probably it *shouldn't* be that way (consider, for a moment, a hook that is used for some sort of setup that can only be done once - it would fail if the hook was re-run when libvirtd was restarted). Instead we should probably have a different hook state for the "restart libvirtd" case, similar to "reconnect" for the qemu hook.
ret = 0; cleanup: @@ -4475,6 +4484,7 @@ networkNotifyActualDevice(virDomainDefPtr dom, }
+ /* networkReleaseActualDevice: * @dom: domain definition that @iface belongs to * @iface: a domain's NetDef (interface definition) @@ -4559,10 +4569,6 @@ networkReleaseActualDevice(virDomainDefPtr dom, netdef->name, actualDev); goto error; } - - VIR_DEBUG("Releasing physical device %s, connections %d", - dev->device.dev, dev->connections - 1); - } else /* if (actualType == VIR_DOMAIN_NET_TYPE_HOSTDEV) */ { virDomainHostdevDefPtr hostdev;
@@ -4594,11 +4600,6 @@ networkReleaseActualDevice(virDomainDefPtr dom, hostdev->source.subsys.u.pci.addr.function); goto error; } - - VIR_DEBUG("Releasing physical device %04x:%02x:%02x.%x, connections %d", - dev->device.pci.domain, dev->device.pci.bus, - dev->device.pci.slot, dev->device.pci.function, - dev->connections - 1); }
success: @@ -4606,13 +4607,10 @@ networkReleaseActualDevice(virDomainDefPtr dom, netdef->connections--; if (dev) dev->connections--; - - VIR_DEBUG("Releasing network %s, %d connections", - netdef->name, netdef->connections); - /* finally we can call the 'unplugged' hook script if any */ networkRunHook(network, dom, iface, VIR_HOOK_NETWORK_OP_IFACE_UNPLUGGED, VIR_HOOK_SUBOP_BEGIN);
Existing... no status check like there are on other calls...
There's nothing to be done if it fails, and the interface really is disconnected whether or not the hook succeeds.
+ networkLogAllocation(netdef, actualType, dev, iface, false); And this one prints regardless...
The resources are still freed regardless of whether or not the hook fails, so the log message should still be logged.
Your call on how to proceed - that is not printing if Hook fails is desired.
Well, virHookCall() does log an error in any case that it fails, so that would be seen in the logs. It would probably be useful to log more complete info in failure cases. The intent of this patch is to get the info logs correct when an interface is successfully connected/disconnected though - I think any beefing up of error logs can be done separately.
ACK as long as the connections++ is removed from networkLogAllocation
Done, and pushing. Thanks!

The existing log messages for this have several problems; there are two lines of log when one will suffice, they duplicate the function name in log message (when it's already included by VIR_DEBUG), they're missing some useful bits, they get logged even when the call is a NOP. This patch cleans up the problems with those existing logs, and also adds a new VIR_INFO-level log down at the function that is actually creating and sending the netlink message that logs *everything* going into the netlink message (which turns out to be much more useful in practice for me; I didn't want to eliminate the logs at the existing location though, in case they are useful in some scenario I'm unfamiliar with; anyway those logs are remaining at debug level, so it shouldn't be a bother to anyone). --- src/util/virnetdevvportprofile.c | 60 ++++++++++++++++++++++++++++++++++------ 1 file changed, 51 insertions(+), 9 deletions(-) diff --git a/src/util/virnetdevvportprofile.c b/src/util/virnetdevvportprofile.c index 8a6b601..8100656 100644 --- a/src/util/virnetdevvportprofile.c +++ b/src/util/virnetdevvportprofile.c @@ -653,6 +653,40 @@ virNetDevVPortProfileOpSetLink(const char *ifname, int ifindex, uint32_t dst_pid = 0; struct nl_msg *nl_msg; struct nlattr *vfports = NULL, *vfport; + char macStr[VIR_MAC_STRING_BUFLEN]; + char hostUUIDStr[VIR_UUID_STRING_BUFLEN]; + char instanceUUIDStr[VIR_UUID_STRING_BUFLEN]; + const char *opName; + + switch (op) { + case PORT_REQUEST_PREASSOCIATE: + opName = "PREASSOCIATE"; + break; + case PORT_REQUEST_PREASSOCIATE_RR: + opName = "PREASSOCIATE_RR"; + break; + case PORT_REQUEST_ASSOCIATE: + opName = "ASSOCIATE"; + break; + case PORT_REQUEST_DISASSOCIATE: + opName = "DISASSOCIATE"; + break; + default: + opName = "(unknown)"; + break; + } + VIR_INFO("%s: ifname: %s ifindex: %d vf: %d vlanid: %d mac: %s " + "profileId: %s instanceId: %s hostUUID: %s", + opName, ifname ? ifname : "(unspecified)", + ifindex, vf, vlanid, + macaddr ? virMacAddrFormat(macaddr, macStr) : "(unspecified)", + profileId ? profileId : "(unspecified)", + (instanceId + ? virUUIDFormat(instanceId, instanceUUIDStr) + : "(unspecified)"), + (hostUUID + ? virUUIDFormat(hostUUID, hostUUIDStr) + : "(unspecified)")); nl_msg = nlmsg_alloc_simple(RTM_SETLINK, NLM_F_REQUEST); if (!nl_msg) { @@ -1197,11 +1231,16 @@ virNetDevVPortProfileAssociate(const char *macvtap_ifname, bool setlink_only) { int rc = 0; + char uuidStr[VIR_UUID_STRING_BUFLEN]; + char macStr[VIR_MAC_STRING_BUFLEN]; - VIR_DEBUG("Associating port profile '%p' on link device '%s'", - virtPort, (macvtap_ifname ? macvtap_ifname : linkdev)); - - VIR_DEBUG("%s: VM OPERATION: %s", __FUNCTION__, virNetDevVPortProfileOpTypeToString(vmOp)); + VIR_DEBUG("profile:'%p' vmOp: %s device: %s@%s mac: %s uuid: %s", + virtPort, virNetDevVPortProfileOpTypeToString(vmOp), + (macvtap_ifname ? macvtap_ifname : ""), linkdev, + (macvtap_macaddr + ? virMacAddrFormat(macvtap_macaddr, macStr) + : "(unspecified)"), + vmuuid ? virUUIDFormat(vmuuid, uuidStr) : "(unspecified)"); if (!virtPort || vmOp == VIR_NETDEV_VPORT_PROFILE_OP_NO_OP) return 0; @@ -1259,11 +1298,14 @@ virNetDevVPortProfileDisassociate(const char *macvtap_ifname, virNetDevVPortProfileOp vmOp) { int rc = 0; - - VIR_DEBUG("Disassociating port profile id '%p' on link device '%s' ", - virtPort, macvtap_ifname); - - VIR_DEBUG("%s: VM OPERATION: %s", __FUNCTION__, virNetDevVPortProfileOpTypeToString(vmOp)); + char macStr[VIR_MAC_STRING_BUFLEN]; + + VIR_DEBUG("profile:'%p' vmOp: %s device: %s@%s mac: %s", + virtPort, virNetDevVPortProfileOpTypeToString(vmOp), + (macvtap_ifname ? macvtap_ifname : ""), linkdev, + (macvtap_macaddr + ? virMacAddrFormat(macvtap_macaddr, macStr) + : "(unspecified)")); if (!virtPort) return 0; -- 2.5.0

On 02/11/2016 04:37 PM, Laine Stump wrote:
The existing log messages for this have several problems; there are two lines of log when one will suffice, they duplicate the function name in log message (when it's already included by VIR_DEBUG), they're missing some useful bits, they get logged even when the call is a NOP.
This patch cleans up the problems with those existing logs, and also adds a new VIR_INFO-level log down at the function that is actually creating and sending the netlink message that logs *everything* going into the netlink message (which turns out to be much more useful in practice for me; I didn't want to eliminate the logs at the existing location though, in case they are useful in some scenario I'm unfamiliar with; anyway those logs are remaining at debug level, so it shouldn't be a bother to anyone). --- src/util/virnetdevvportprofile.c | 60 ++++++++++++++++++++++++++++++++++------ 1 file changed, 51 insertions(+), 9 deletions(-)
Less noise than pesky VIR_LOG_DEBUG that's for sure.... Hey if they're useful, then they're useful. Duplicitous for those wanting to wade through numerous _DEBUG level messages... ACK John
participants (2)
-
John Ferlan
-
Laine Stump