[patch net-next v2] ipv6: log autoconfiguration failures

[patch net-next v2] ipv6: log autoconfiguration failures

[Denys Vlasenko]

If ipv6 auto-configuration does not work, currently it's hard
to track what's going on. This change adds log messages
(at debug level) on every code path where ipv6 autoconf fails.

v2: fixed indentation in multi-line log output statements.

Signed-off-by: Denys Vlasenko <dvlasenk@redhat.com>
---
 net/ipv6/addrconf.c | 45 ++++++++++++++++++++++++++++++++++++---------
 1 file changed, 36 insertions(+), 9 deletions(-)

diff --git a/net/ipv6/addrconf.c b/net/ipv6/addrconf.c
index 3c3425e..c09c5f4 100644
--- a/net/ipv6/addrconf.c
+++ b/net/ipv6/addrconf.c
@@ -1694,8 +1694,11 @@ static void addrconf_leave_anycast(struct inet6_ifaddr *ifp)
 
 static int addrconf_ifid_eui48(u8 *eui, struct net_device *dev)
 {
-	if (dev->addr_len != ETH_ALEN)
+	if (dev->addr_len != ETH_ALEN) {
+		pr_debug("IPv6 addrconf: %s: address length %d != %s\n",
+			 dev->name, dev->addr_len, "ETH_ALEN");
 		return -1;
+	}
 	memcpy(eui, dev->dev_addr, 3);
 	memcpy(eui + 5, dev->dev_addr + 3, 3);
 
@@ -1725,8 +1728,11 @@ static int addrconf_ifid_eui48(u8 *eui, struct net_device *dev)
 
 static int addrconf_ifid_eui64(u8 *eui, struct net_device *dev)
 {
-	if (dev->addr_len != IEEE802154_ADDR_LEN)
+	if (dev->addr_len != IEEE802154_ADDR_LEN) {
+		pr_debug("IPv6 addrconf: %s: address length %d != %s\n",
+			 dev->name, dev->addr_len, "IEEE802154_ADDR_LEN");
 		return -1;
+	}
 	memcpy(eui, dev->dev_addr, 8);
 	eui[0] ^= 2;
 	return 0;
@@ -1736,8 +1742,11 @@ static int addrconf_ifid_ieee1394(u8 *eui, struct net_device *dev)
 {
 	union fwnet_hwaddr *ha;
 
-	if (dev->addr_len != FWNET_ALEN)
+	if (dev->addr_len != FWNET_ALEN) {
+		pr_debug("IPv6 addrconf: %s: address length %d != %s\n",
+			 dev->name, dev->addr_len, "FWNET_ALEN");
 		return -1;
+	}
 
 	ha = (union fwnet_hwaddr *)dev->dev_addr;
 
@@ -1749,8 +1758,11 @@ static int addrconf_ifid_ieee1394(u8 *eui, struct net_device *dev)
 static int addrconf_ifid_arcnet(u8 *eui, struct net_device *dev)
 {
 	/* XXX: inherit EUI-64 from other interface -- yoshfuji */
-	if (dev->addr_len != ARCNET_ALEN)
+	if (dev->addr_len != ARCNET_ALEN) {
+		pr_debug("IPv6 addrconf: %s: address length %d != %s\n",
+			 dev->name, dev->addr_len, "ARCNET_ALEN");
 		return -1;
+	}
 	memset(eui, 0, 7);
 	eui[7] = *(u8 *)dev->dev_addr;
 	return 0;
@@ -1758,17 +1770,25 @@ static int addrconf_ifid_arcnet(u8 *eui, struct net_device *dev)
 
 static int addrconf_ifid_infiniband(u8 *eui, struct net_device *dev)
 {
-	if (dev->addr_len != INFINIBAND_ALEN)
+	if (dev->addr_len != INFINIBAND_ALEN) {
+		pr_debug("IPv6 addrconf: %s: address length %d != %s\n",
+			 dev->name, dev->addr_len, "INFINIBAND_ALEN");
 		return -1;
+	}
 	memcpy(eui, dev->dev_addr + 12, 8);
 	eui[0] |= 2;
 	return 0;
 }
 
-static int __ipv6_isatap_ifid(u8 *eui, __be32 addr)
+static int __ipv6_isatap_ifid(u8 *eui, struct net_device *dev)
 {
-	if (addr == 0)
+	__be32 addr = *(__be32 *)dev->dev_addr;
+
+	if (addr == 0) {
+		pr_debug("IPv6 addrconf: %s: bad dev_addr %pM\n",
+			 dev->name, dev->dev_addr);
 		return -1;
+	}
 	eui[0] = (ipv4_is_zeronet(addr) || ipv4_is_private_10(addr) ||
 		  ipv4_is_loopback(addr) || ipv4_is_linklocal_169(addr) ||
 		  ipv4_is_private_172(addr) || ipv4_is_test_192(addr) ||
@@ -1785,13 +1805,14 @@ static int __ipv6_isatap_ifid(u8 *eui, __be32 addr)
 static int addrconf_ifid_sit(u8 *eui, struct net_device *dev)
 {
 	if (dev->priv_flags & IFF_ISATAP)
-		return __ipv6_isatap_ifid(eui, *(__be32 *)dev->dev_addr);
+		return __ipv6_isatap_ifid(eui, dev);
+	pr_debug("IPv6 addrconf: %s: IFF_ISATAP is unset\n", dev->name);
 	return -1;
 }
 
 static int addrconf_ifid_gre(u8 *eui, struct net_device *dev)
 {
-	return __ipv6_isatap_ifid(eui, *(__be32 *)dev->dev_addr);
+	return __ipv6_isatap_ifid(eui, dev);
 }
 
 static int addrconf_ifid_ip6tnl(u8 *eui, struct net_device *dev)
@@ -1825,6 +1846,8 @@ static int ipv6_generate_eui64(u8 *eui, struct net_device *dev)
 	case ARPHRD_TUNNEL6:
 		return addrconf_ifid_ip6tnl(eui, dev);
 	}
+	pr_debug("IPv6 addrconf: %s: dev->type %d is not supported\n",
+		 dev->name, dev->type);
 	return -1;
 }
 
@@ -1842,6 +1865,10 @@ static int ipv6_inherit_eui64(u8 *eui, struct inet6_dev *idev)
 		}
 	}
 	read_unlock_bh(&idev->lock);
+	if (err)
+		pr_debug("IPv6 addrconf: "
+			 "%s: no link-local address to inherit\n",
+			 idev->dev->name);
 	return err;
 }
 
-- 
1.8.1.4

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[Hannes Frederic Sowa]

On Wed, Dec 11, 2013 at 12:45:14PM +0100, Denys Vlasenko wrote:
> If ipv6 auto-configuration does not work, currently it's hard
> to track what's going on. This change adds log messages
> (at debug level) on every code path where ipv6 autoconf fails.
> 
> v2: fixed indentation in multi-line log output statements.

Have you seen lots of those problems? Some of those seem like very
serious problems and maybe could also deserve a pr_warn or pr_err.

I hope these are one-time errors, so I don't think counters would
be helpful.

> Signed-off-by: Denys Vlasenko <dvlasenk@redhat.com>
> ---
>  net/ipv6/addrconf.c | 45 ++++++++++++++++++++++++++++++++++++---------
>  1 file changed, 36 insertions(+), 9 deletions(-)
> 
> diff --git a/net/ipv6/addrconf.c b/net/ipv6/addrconf.c
> index 3c3425e..c09c5f4 100644
> --- a/net/ipv6/addrconf.c
> +++ b/net/ipv6/addrconf.c
> @@ -1694,8 +1694,11 @@ static void addrconf_leave_anycast(struct inet6_ifaddr *ifp)
>  
>  static int addrconf_ifid_eui48(u8 *eui, struct net_device *dev)
>  {
> -	if (dev->addr_len != ETH_ALEN)
> +	if (dev->addr_len != ETH_ALEN) {
> +		pr_debug("IPv6 addrconf: %s: address length %d != %s\n",
> +			 dev->name, dev->addr_len, "ETH_ALEN");

I like __stringify(ETH_ALEN) instead of "ETH_ALEN" a bit more but no need
to change the patch because of that. ;)

> @@ -1842,6 +1865,10 @@ static int ipv6_inherit_eui64(u8 *eui, struct inet6_dev *idev)
>  		}
>  	}
>  	read_unlock_bh(&idev->lock);
> +	if (err)
> +		pr_debug("IPv6 addrconf: "
> +			 "%s: no link-local address to inherit\n",
> +			 idev->dev->name);

Another nit:
String literals should not be wrapped to ease grepping for them in the source.

Thanks,

  Hannes

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[David Miller]

From: Hannes Frederic Sowa <hannes@stressinduktion.org>
Date: Wed, 11 Dec 2013 20:21:38 +0100

> On Wed, Dec 11, 2013 at 12:45:14PM +0100, Denys Vlasenko wrote:
>> If ipv6 auto-configuration does not work, currently it's hard
>> to track what's going on. This change adds log messages
>> (at debug level) on every code path where ipv6 autoconf fails.
>> 
>> v2: fixed indentation in multi-line log output statements.
> 
> Have you seen lots of those problems? Some of those seem like very
> serious problems and maybe could also deserve a pr_warn or pr_err.
> 
> I hope these are one-time errors, so I don't think counters would
> be helpful.

I still think that statitics would better serve this issue.

For one thing, the event would always be counted, whereas with
pr_debug() someone has to turn on dynamic debugging in order
to see the message.

You can make them part of the per-inet6_dev MIB, and therefore
implicitly letting the admin know what interface the events
occurred on.

I would even prefer an approach involving signalling netlink
events in such circumstances with more detailed information.

Thanks.

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[Hannes Frederic Sowa]

On Wed, Dec 11, 2013 at 03:54:52PM -0500, David Miller wrote:
> From: Hannes Frederic Sowa <hannes@stressinduktion.org>
> Date: Wed, 11 Dec 2013 20:21:38 +0100
> 
> > On Wed, Dec 11, 2013 at 12:45:14PM +0100, Denys Vlasenko wrote:
> >> If ipv6 auto-configuration does not work, currently it's hard
> >> to track what's going on. This change adds log messages
> >> (at debug level) on every code path where ipv6 autoconf fails.
> >> 
> >> v2: fixed indentation in multi-line log output statements.
> > 
> > Have you seen lots of those problems? Some of those seem like very
> > serious problems and maybe could also deserve a pr_warn or pr_err.
> > 
> > I hope these are one-time errors, so I don't think counters would
> > be helpful.
> 
> I still think that statitics would better serve this issue.
> 
> For one thing, the event would always be counted, whereas with
> pr_debug() someone has to turn on dynamic debugging in order
> to see the message.

I proposed switching some of these to pr_warn/err. pr_debugs get used very
seldomly, I agree.

> You can make them part of the per-inet6_dev MIB, and therefore
> implicitly letting the admin know what interface the events
> occurred on.

If such an error happens I would try to recreate the interface (in case of
virtual ones), thus erasing the statistics.

> I would even prefer an approach involving signalling netlink
> events in such circumstances with more detailed information.

That sounds good. But I would like to hear how often these problems
really occur first. Maybe Denys has some numbers? If that happens a lot
I would like to check if the notifier_chains are correctly setup so that
interfaces correclty notify ipv6 to retry link local address generation.

Greetings,

  Hannes

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[Denys Vlasenko]

On 12/11/2013 08:21 PM, Hannes Frederic Sowa wrote:
> On Wed, Dec 11, 2013 at 12:45:14PM +0100, Denys Vlasenko wrote:
>> If ipv6 auto-configuration does not work, currently it's hard
>> to track what's going on. This change adds log messages
>> (at debug level) on every code path where ipv6 autoconf fails.
>>
>> v2: fixed indentation in multi-line log output statements.
> 
> Have you seen lots of those problems? Some of those seem like very
> serious problems and maybe could also deserve a pr_warn or pr_err.

I personally wasn't bitten by this problem, but our admins were.

They say that when they notice that ipv6 auconf didn't work
(i.e. they see no auconfigured addresses on the interfaces),
they usually see no useful messages in dmesg or /var/log/messages,
which makes them to try to fix the problem blind.

I can easily imagine their frustration. Kernel _knows_ why
it didn't work, and it's not expected to normally pappen,
why didn't it tell anything about it?

-- 
vda

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[Denys Vlasenko]

On 12/11/2013 09:54 PM, David Miller wrote:
> From: Hannes Frederic Sowa <hannes@stressinduktion.org>
> Date: Wed, 11 Dec 2013 20:21:38 +0100
> 
>> On Wed, Dec 11, 2013 at 12:45:14PM +0100, Denys Vlasenko wrote:
>>> If ipv6 auto-configuration does not work, currently it's hard
>>> to track what's going on. This change adds log messages
>>> (at debug level) on every code path where ipv6 autoconf fails.
>>>
>>> v2: fixed indentation in multi-line log output statements.
>>
>> Have you seen lots of those problems? Some of those seem like very
>> serious problems and maybe could also deserve a pr_warn or pr_err.
>>
>> I hope these are one-time errors, so I don't think counters would
>> be helpful.
> 
> I still think that statitics would better serve this issue.
> 
> You can make them part of the per-inet6_dev MIB, and therefore
> implicitly letting the admin know what interface the events
> occurred on.

Putting myself in admin's boots...

Admins want to know why ipv6 autoconf didn't work, not so much
how many times it didn't work. This requires a text message.

> For one thing, the event would always be counted, whereas with
> pr_debug() someone has to turn on dynamic debugging in order
> to see the message.

Point taken wrt pr_debug being too gentle.
I should have used pr_warn or at least pr_info...

-- 
vda

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[David Miller]

From: Denys Vlasenko <dvlasenk@redhat.com>
Date: Thu, 12 Dec 2013 12:17:42 +0100

> I can easily imagine their frustration. Kernel _knows_ why
> it didn't work, and it's not expected to normally pappen,
> why didn't it tell anything about it?

Packets are dropped silently, ARP fails and entries go stale silently,
none of this is logged with kernel messages, why is ipv6 autoconf so
unique and important to justify different behavior?

Give it statistics just like we have for every other kind of similar
event.

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[David Miller]

From: Denys Vlasenko <dvlasenk@redhat.com>
Date: Thu, 12 Dec 2013 12:28:16 +0100

> Admins want to know why ipv6 autoconf didn't work, not so much
> how many times it didn't work. This requires a text message.

Again, they don't get this for ARP, or any other similar event.  Why
is ipv6 autoconf so damn special that it demands unique treatment?

I do not want each subsystem to decide their own custom way to
notify people that some interesting event happened.  That's the
worst possible user experience.

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[Vlad Yasevich]

On 12/12/2013 12:22 PM, David Miller wrote:
> From: Denys Vlasenko <dvlasenk@redhat.com>
> Date: Thu, 12 Dec 2013 12:17:42 +0100
> 
>> I can easily imagine their frustration. Kernel _knows_ why
>> it didn't work, and it's not expected to normally pappen,
>> why didn't it tell anything about it?
> 
> Packets are dropped silently, ARP fails and entries go stale silently,
> none of this is logged with kernel messages, why is ipv6 autoconf so
> unique and important to justify different behavior?

But most of the changes from V2 report an actual error condition in
the kernel: addr_len is not set correctly for the device type.
These changes are worth keeping and not just as pr_debug.  Having
a counter of these failures will not provide much useful data if you
happen to have multiple such device and where one happens to work and
the other doesn't (very unlikely, I know).

> 
> Give it statistics just like we have for every other kind of similar
> event.

The fact that link-local address could not be generated for a specific
device type does not lend itself well to counting.  There is no way
from to tell from the counter which device does not support IPv6 autoconfig.

-vlad

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[David Miller]

From: Vlad Yasevich <vyasevich@gmail.com>
Date: Thu, 12 Dec 2013 12:58:18 -0500

> On 12/12/2013 12:22 PM, David Miller wrote:
>> Give it statistics just like we have for every other kind of similar
>> event.
> 
> The fact that link-local address could not be generated for a specific
> device type does not lend itself well to counting.  There is no way
> from to tell from the counter which device does not support IPv6 autoconfig.

If the statistic is per-device, which I recommended it be implemented as,
you indeed can.

And I do not buy the argument that this is "useless" because the admin
is just going to kill the interface and create a new one.  When you
notice there is a problem, you look at the statistics before doing
that!

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[Hannes Frederic Sowa]

On Thu, Dec 12, 2013 at 01:24:41PM -0500, David Miller wrote:
> From: Vlad Yasevich <vyasevich@gmail.com>
> Date: Thu, 12 Dec 2013 12:58:18 -0500
> 
> > On 12/12/2013 12:22 PM, David Miller wrote:
> >> Give it statistics just like we have for every other kind of similar
> >> event.
> > 
> > The fact that link-local address could not be generated for a specific
> > device type does not lend itself well to counting.  There is no way
> > from to tell from the counter which device does not support IPv6 autoconfig.
> 
> If the statistic is per-device, which I recommended it be implemented as,
> you indeed can.
> 
> And I do not buy the argument that this is "useless" because the admin
> is just going to kill the interface and create a new one.  When you
> notice there is a problem, you look at the statistics before doing
> that!

Granted.

IMHO both ways are fine with a slight opionion to counters being overkill. ;)

Re: [patch net-next v2] ipv6: log autoconfiguration failures

[David Miller]

From: Hannes Frederic Sowa <hannes@stressinduktion.org>
Date: Thu, 12 Dec 2013 20:00:42 +0100

> IMHO both ways are fine with a slight opionion to counters being
> overkill. ;)

Counters don't scroll out of the log last time I checked too :)