BUG: dst underflow (again)

As requested, I updated my kernel to see if the "BUG: dst underflow..." 
messages disappeared.  Alas, they didn't.  dmesg and .config from 
2.6.9-final attached.

Let me know what additional debugging information I can provide, if any. 
  The symbol addresses in the dmesg output are all inside the ipv6 module.

Thanks,

	Jeff

In article [off-list ref] (at Fri, 22 Oct 2004 02:39:09 -0400), Jeff Garzik [off-list ref] says:

As requested, I updated my kernel to see if the "BUG: dst underflow..." 
messages disappeared.  Alas, they didn't.  dmesg and .config from 
2.6.9-final attached.

Okay, thanks, but hmm...
(We haven't met this issue... I really want to know tow to reproduce...)

Let me know what additional debugging information I can provide, if any. 
  The symbol addresses in the dmesg output are all inside the ipv6 module.

Would you enable CONFIG_KALLSYMS_ALL, please?

Thanks.

--yoshfuji

On Fri, Oct 22, 2004 at 03:51:59PM +0900, YOSHIFUJI Hideaki / ?$B5HF#1QL@ wrote:

quoted

As requested, I updated my kernel to see if the "BUG: dst underflow..." 
messages disappeared.  Alas, they didn't.  dmesg and .config from 
2.6.9-final attached.

Okay, thanks, but hmm...
(We haven't met this issue... I really want to know tow to reproduce...)

FWIW, I'm seeing loads of these on the kernel that comes with Fedora
Core 2, also in the ipv6.ko module.  I have 6to4 enabled, if that matters
anything.

% dmesg | grep BUG | sort | uniq
BUG: dst underflow -1: 3bcf9a80 at 42350024
BUG: dst underflow 0: 3bcf9a80 at 423486d2
BUG: dst underflow 0: 3bcf9a80 at 4235823d
% cat /sys/module/ipv6/sections/.text
0x42345000

0x42350024 - 0x42345000 = 0xb024, corresponds to:
	0000affa <ip6_dst_check>

0x423486d2 - 0x42345000 = 0x36d2, corresponds to:
	0000339d <ip6_push_pending_frames>

0x4235823d - 0x42345000 = 0x1323d, corresponds to:
	00012c0d <udpv6_sendmsg>	(god, that's one big function btw)


--L

Jeff/Lennert 

Could you turn off netfilter and see if this continues to happen?

Know how to reproduce this? ;->

cheers,
jamal

On Fri, 2004-10-22 at 03:59, Lennert Buytenhek wrote:

On Fri, Oct 22, 2004 at 03:51:59PM +0900, YOSHIFUJI Hideaki / ?$B5HF#1QL@ wrote:

quoted

quoted

As requested, I updated my kernel to see if the "BUG: dst underflow..." 
messages disappeared.  Alas, they didn't.  dmesg and .config from 
2.6.9-final attached.

Okay, thanks, but hmm...
(We haven't met this issue... I really want to know tow to reproduce...)

FWIW, I'm seeing loads of these on the kernel that comes with Fedora
Core 2, also in the ipv6.ko module.  I have 6to4 enabled, if that matters
anything.

% dmesg | grep BUG | sort | uniq
BUG: dst underflow -1: 3bcf9a80 at 42350024
BUG: dst underflow 0: 3bcf9a80 at 423486d2
BUG: dst underflow 0: 3bcf9a80 at 4235823d
% cat /sys/module/ipv6/sections/.text
0x42345000

0x42350024 - 0x42345000 = 0xb024, corresponds to:
	0000affa <ip6_dst_check>

0x423486d2 - 0x42345000 = 0x36d2, corresponds to:
	0000339d <ip6_push_pending_frames>

0x4235823d - 0x42345000 = 0x1323d, corresponds to:
	00012c0d <udpv6_sendmsg>	(god, that's one big function btw)


--L

On 04 Nov 2004 09:15:17 -0500
jamal [off-list ref] wrote:

Could you turn off netfilter and see if this continues to happen?

That's one possible angle, but let's look at the tracepoints
more closely.

BTW Lennert, the decoded addresses are extremely helpful. Thanks.

Jeff, could you similarly decode the ones that you seem to get?
That would be an incredibly useful datapoint.  If you've provided
this already, my bad and please point me at where you posted that.

quoted

BUG: dst underflow -1: 3bcf9a80 at 42350024
BUG: dst underflow 0: 3bcf9a80 at 423486d2
BUG: dst underflow 0: 3bcf9a80 at 4235823d

 ...

quoted

0x42350024 - 0x42345000 = 0xb024, corresponds to:
	0000affa <ip6_dst_check>

0x423486d2 - 0x42345000 = 0x36d2, corresponds to:
	0000339d <ip6_push_pending_frames>

0x4235823d - 0x42345000 = 0x1323d, corresponds to:
	00012c0d <udpv6_sendmsg>	(god, that's one big function btw)

The last one is the most interesting.  The only dst_release() call
that occurs in udpv6_sendmsg() is when xfrm_lookup() returns
an error.  The semantics of that function are a complete mess
(when it errors, it sometimes releases the DST, sometimes does not)
and I'll fix that up.

But let me ask, do you have any IPSEC policies in the kernel
when these BUGs trigger?  If so, I'm pretty sure I know what
the problem may be.

In article [off-list ref] (at Thu, 4 Nov 2004 22:18:01 -0800), "David S. Miller" [off-list ref] says:

quoted

quoted

	00012c0d <udpv6_sendmsg>	(god, that's one big function btw)

The last one is the most interesting.  The only dst_release() call
that occurs in udpv6_sendmsg() is when xfrm_lookup() returns
an error.  The semantics of that function are a complete mess
(when it errors, it sometimes releases the DST, sometimes does not)
and I'll fix that up.

Oh,yes, something like this?

Signed-off-by: Hideaki YOSHIFUJI <redacted>

===== net/ipv6/udp.c 1.76 vs edited =====

--- 1.76/net/ipv6/udp.c	2004-10-26 11:47:26 +09:00
+++ edited/net/ipv6/udp.c	2004-11-05 15:42:00 +09:00

@@ -631,7 +631,7 @@
 	struct ipv6_txoptions *opt = NULL;
 	struct ip6_flowlabel *flowlabel = NULL;
 	struct flowi *fl = &inet->cork.fl;
-	struct dst_entry *dst;
+	struct dst_entry *dst = NULL;
 	int addr_len = msg->msg_namelen;
 	int ulen = len;
 	int hlimit = -1;

@@ -797,10 +797,8 @@
 	if (final_p)
 		ipv6_addr_copy(&fl->fl6_dst, final_p);
 
-	if ((err = xfrm_lookup(&dst, fl, sk, 0)) < 0) {
-		dst_release(dst);
+	if ((err = xfrm_lookup(&dst, fl, sk, 0)) < 0)
 		goto out;
-	}
 
 	if (hlimit < 0) {
 		if (ipv6_addr_is_multicast(&fl->fl6_dst))

@@ -846,6 +844,7 @@
 		err = np->recverr ? net_xmit_errno(err) : 0;
 	release_sock(sk);
 out:
+	dst_release(dst);
 	fl6_sock_release(flowlabel);
 	if (!err) {
 		UDP6_INC_STATS_USER(UDP_MIB_OUTDATAGRAMS);

-- 
Hideaki YOSHIFUJI @ USAGI Project <yoshfuji@linux-ipv6.org>
GPG FP: 9022 65EB 1ECF 3AD1 0BDF  80D8 4807 F894 E062 0EEA

David S. Miller wrote:

Jeff, could you similarly decode the ones that you seem to get?
That would be an incredibly useful datapoint.  If you've provided
this already, my bad and please point me at where you posted that.

I've compiled IPv6 into my router's kernel image, so next time I reboot, 
I should be able to get at symbol info out of the BUGs a bit more easily.

But let me ask, do you have any IPSEC policies in the kernel
when these BUGs trigger?  If so, I'm pretty sure I know what
the problem may be.

I know this question wasn't directed at me, but, I do always compile 
ipsec stuff into my kernel, in addition to netfilter.  The relevant 
options are attached for the curious.

	Jeff


P.S.  Jamal--  I cannot disable netfilter for a period of time long 
enough to cause the BUGs to be produced, since that disables my NAT'ing.

On Fri, 05 Nov 2004 02:05:41 -0500
Jeff Garzik [off-list ref] wrote:

David S. Miller wrote:

quoted

Jeff, could you similarly decode the ones that you seem to get?
That would be an incredibly useful datapoint.  If you've provided
this already, my bad and please point me at where you posted that.

I've compiled IPv6 into my router's kernel image, so next time I reboot, 
I should be able to get at symbol info out of the BUGs a bit more easily.

Thanks a lot.

quoted

But let me ask, do you have any IPSEC policies in the kernel
when these BUGs trigger?  If so, I'm pretty sure I know what
the problem may be.

I know this question wasn't directed at me, but, I do always compile 
ipsec stuff into my kernel, in addition to netfilter.  The relevant 
options are attached for the curious.

Yes, but do you actually install any IPSEC rules into your system?

The only way xfrm_lookup() can ever fall (and call that BUG'ing
dst_release() in udpv6_sendmsg()) is if you have at least some
IPSEC policies configured.

On Fri, 05 Nov 2004 15:53:55 +0900 (JST)
YOSHIFUJI Hideaki / $B5HF#1QL@(B [off-list ref] wrote:

In article [off-list ref] (at Thu, 4 Nov 2004 22:18:01 -0800), "David S. Miller" [off-list ref] says:

quoted

quoted

quoted

	00012c0d <udpv6_sendmsg>	(god, that's one big function btw)

The last one is the most interesting.  The only dst_release() call
that occurs in udpv6_sendmsg() is when xfrm_lookup() returns
an error.  The semantics of that function are a complete mess
(when it errors, it sometimes releases the DST, sometimes does not)
and I'll fix that up.

Oh,yes, something like this?

Something, but not quite.  :-)  This change you propose
adds a leak, you have to modify xfrm_lookup() as well.

I'm mid-way through such changes, but it looks something
like this (BTW, note the addrconf.c leak I noticed today
as well):

===== net/ipv6/addrconf.c 1.115 vs edited =====

--- 1.115/net/ipv6/addrconf.c	2004-10-25 21:11:35 -07:00
+++ edited/net/ipv6/addrconf.c	2004-11-04 13:10:26 -08:00

@@ -509,6 +509,7 @@
 	rt = addrconf_dst_alloc(idev, addr, 0);
 	if (IS_ERR(rt)) {
 		err = PTR_ERR(rt);
+		rt = NULL;
 		goto out;
 	}
 

@@ -572,6 +573,8 @@
 	if (unlikely(err == 0))
 		notifier_call_chain(&inet6addr_chain, NETDEV_UP, ifa);
 	else {
+		if (rt)
+			dst_free(&rt->u.dst);
 		kfree(ifa);
 		ifa = ERR_PTR(err);
 	}

===== net/ipv6/datagram.c 1.19 vs edited =====

--- 1.19/net/ipv6/datagram.c	2004-08-27 09:35:00 -07:00
+++ edited/net/ipv6/datagram.c	2004-11-04 16:43:24 -08:00

@@ -174,10 +174,8 @@
 	if (final_p)
 		ipv6_addr_copy(&fl.fl6_dst, final_p);
 
-	if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0) {
-		dst_release(dst);
+	if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0)
 		goto out;
-	}
 
 	/* source address lookup done in ip6_dst_lookup */
 

===== net/ipv6/icmp.c 1.59 vs edited =====

--- 1.59/net/ipv6/icmp.c	2004-09-14 22:32:09 -07:00
+++ edited/net/ipv6/icmp.c	2004-11-04 16:44:01 -08:00

@@ -373,7 +373,7 @@
 	if (err)
 		goto out;
 	if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0)
-		goto out_dst_release;
+		goto out;
 
 	if (hlimit < 0) {
 		if (ipv6_addr_is_multicast(&fl.fl6_dst))

@@ -461,7 +461,7 @@
 	if (err)
 		goto out;
 	if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0)
-		goto out_dst_release;
+		goto out;
 
 	if (hlimit < 0) {
 		if (ipv6_addr_is_multicast(&fl.fl6_dst))

===== net/ipv6/ip6_tunnel.c 1.25 vs edited =====

--- 1.25/net/ipv6/ip6_tunnel.c	2004-09-13 13:03:39 -07:00
+++ edited/net/ipv6/ip6_tunnel.c	2004-11-04 16:49:24 -08:00

@@ -759,9 +759,14 @@
 
 	t->recursion--;
 	return 0;
+
 tx_err_link_failure:
 	stats->tx_carrier_errors++;
 	dst_link_failure(skb);
+	if (opt)
+		kfree(opt);
+	goto tx_err;
+
 tx_err_dst_release:
 	dst_release(dst);
 	if (opt)

===== net/ipv6/ndisc.c 1.104 vs edited =====

--- 1.104/net/ipv6/ndisc.c	2004-11-03 11:56:07 -08:00
+++ edited/net/ipv6/ndisc.c	2004-11-04 16:49:48 -08:00

@@ -408,10 +408,8 @@
 		return;
 
 	err = xfrm_lookup(&dst, &fl, NULL, 0);
-	if (err < 0) {
-		dst_release(dst);
+	if (err < 0)
 		return;
-	}
 
 	if (inc_opt) {
 		if (dev->addr_len)

@@ -499,10 +497,8 @@
 		return;
 
 	err = xfrm_lookup(&dst, &fl, NULL, 0);
-	if (err < 0) {
-		dst_release(dst);
+	if (err < 0)
 		return;
-	}
 
 	len = sizeof(struct icmp6hdr) + sizeof(struct in6_addr);
 	send_llinfo = dev->addr_len && !ipv6_addr_any(saddr);

@@ -575,10 +571,8 @@
 		return;
 
 	err = xfrm_lookup(&dst, &fl, NULL, 0);
-	if (err < 0) {
-		dst_release(dst);
+	if (err < 0)
 		return;
-	}
 
 	len = sizeof(struct icmp6hdr);
 	if (dev->addr_len)

@@ -1302,10 +1296,8 @@
 	dst = &rt->u.dst;
 
 	err = xfrm_lookup(&dst, &fl, NULL, 0);
-	if (err) {
-		dst_release(dst);
+	if (err)
 		return;
-	}
 
 	rt = (struct rt6_info *) dst;
 

===== net/ipv6/raw.c 1.73 vs edited =====

--- 1.73/net/ipv6/raw.c	2004-10-25 19:47:26 -07:00
+++ edited/net/ipv6/raw.c	2004-11-04 16:50:05 -08:00

@@ -743,10 +743,8 @@
 	if (final_p)
 		ipv6_addr_copy(&fl.fl6_dst, final_p);
 
-	if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0) {
-		dst_release(dst);
+	if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0)
 		goto out;
-	}
 
 	if (hlimit < 0) {
 		if (ipv6_addr_is_multicast(&fl.fl6_dst))

===== net/ipv6/tcp_ipv6.c 1.100 vs edited =====

--- 1.100/net/ipv6/tcp_ipv6.c	2004-11-01 16:48:28 -08:00
+++ edited/net/ipv6/tcp_ipv6.c	2004-11-04 16:52:43 -08:00

@@ -680,10 +680,8 @@
 	if (final_p)
 		ipv6_addr_copy(&fl.fl6_dst, final_p);
 
-	if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0) {
-		dst_release(dst);
+	if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0)
 		goto failure;
-	}
 
 	if (saddr == NULL) {
 		saddr = &fl.fl6_src;

@@ -1047,10 +1045,8 @@
 	/* sk = NULL, but it is safe for now. RST socket required. */
 	if (!ip6_dst_lookup(NULL, &buff->dst, &fl)) {
 
-		if ((xfrm_lookup(&buff->dst, &fl, NULL, 0)) < 0) {
-			dst_release(buff->dst);
+		if ((xfrm_lookup(&buff->dst, &fl, NULL, 0)) < 0)
 			return;
-		}
 
 		ip6_xmit(NULL, buff, &fl, NULL, 0);
 		TCP_INC_STATS_BH(TCP_MIB_OUTSEGS);

@@ -1114,10 +1110,9 @@
 	fl.fl_ip_sport = t1->source;
 
 	if (!ip6_dst_lookup(NULL, &buff->dst, &fl)) {
-		if ((xfrm_lookup(&buff->dst, &fl, NULL, 0)) < 0) {
-			dst_release(buff->dst);
+		if ((xfrm_lookup(&buff->dst, &fl, NULL, 0)) < 0)
 			return;
-		}
+
 		ip6_xmit(NULL, buff, &fl, NULL, 0);
 		TCP_INC_STATS_BH(TCP_MIB_OUTSEGS);
 		return;

@@ -1378,7 +1373,7 @@
 
 	newsk = tcp_create_openreq_child(sk, req, skb);
 	if (newsk == NULL)
-		goto out;
+		goto out_release;
 
 	/* Charge newly allocated IPv6 socket */
 #ifdef INET_REFCNT_DEBUG

@@ -1457,11 +1452,12 @@
 
 out_overflow:
 	NET_INC_STATS_BH(LINUX_MIB_LISTENOVERFLOWS);
+out_release:
+	dst_release(dst);
 out:
 	NET_INC_STATS_BH(LINUX_MIB_LISTENDROPS);
 	if (opt && opt != np->opt)
 		sock_kfree_s(sk, opt, opt->tot_len);
-	dst_release(dst);
 	return NULL;
 }
 

@@ -1784,7 +1780,6 @@
 
 		if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0) {
 			sk->sk_err_soft = -err;
-			dst_release(dst);
 			return err;
 		}
 

@@ -1838,7 +1833,6 @@
 
 		if ((err = xfrm_lookup(&dst, &fl, sk, 0)) < 0) {
 			sk->sk_route_caps = 0;
-			dst_release(dst);
 			return err;
 		}
 

===== net/xfrm/xfrm_policy.c 1.57 vs edited =====

--- 1.57/net/xfrm/xfrm_policy.c	2004-10-25 20:23:46 -07:00
+++ edited/net/xfrm/xfrm_policy.c	2004-11-04 16:39:23 -08:00

@@ -745,8 +745,8 @@
 	switch (policy->action) {
 	case XFRM_POLICY_BLOCK:
 		/* Prohibit the flow */
-		xfrm_pol_put(policy);
-		return -EPERM;
+		err = -EPERM;
+		goto error;
 
 	case XFRM_POLICY_ALLOW:
 		if (policy->xfrm_nr == 0) {

@@ -762,8 +762,8 @@
 		 */
 		dst = xfrm_find_bundle(fl, policy, family);
 		if (IS_ERR(dst)) {
-			xfrm_pol_put(policy);
-			return PTR_ERR(dst);
+			err = PTR_ERR(dst);
+			goto error;
 		}
 
 		if (dst)

David S. Miller wrote:

On Fri, 05 Nov 2004 02:05:41 -0500
Jeff Garzik [off-list ref] wrote:

quoted

I know this question wasn't directed at me, but, I do always compile 
ipsec stuff into my kernel, in addition to netfilter.  The relevant 
options are attached for the curious.

Yes, but do you actually install any IPSEC rules into your system?

Unless FC2 initscripts do something weird (I've never configured 
IPSEC...  only the policies that the kernel boots with (presumably the 
null set?).

	Jeff

BTW to netdev, there is IMHO no excuse not to test IPv6 ;-)

Plugging...  Check out
	http://linux.yyz.us/ipv6-fc2-howto.html
for starting points.  Quick and easy IPv6 "6to4 automatic tunneling" 
setup for FC1/FC2, with pointers to Deb/Mac/Win instructions.

	Jeff

In article [off-list ref] (at Thu, 4 Nov 2004 23:16:18 -0800), "David S. Miller" [off-list ref] says:

I'm mid-way through such changes, but it looks something
like this (BTW, note the addrconf.c leak I noticed today
as well):

Ok, I leave it to you.

--yoshfuji

On Fri, Nov 05, 2004 at 02:38:19AM -0500, Jeff Garzik wrote:

BTW to netdev, there is IMHO no excuse not to test IPv6 ;-)

:-)

RIPE hands out IPv6 address space in chunks of /32, and it will only
allocate such a /32 for you if you plan on assigning more than 200 /48's
in two years.

They specify that you should assign a /64 to a customer if they only
need a single subnet, otherwise you should assign a /48.  In order to
assign 200 /48's in two years, you have to assign 200 address blocks
to people who need at least 2 subnets, so that means you have to assign
at least 400 subnets' worth of address space.

If you take the canonical IPv6 subnet to be a /64 and the canonical
IPv4 subnet to be a /24, that means you have to assign a block of IPv6
address space that roughly corresponds to a IPv4 /15 in two years in
order to get IPv6 address space at all.

I politely told RIPE that I don't think we'll be assigning that much
address space any time soon, and the result of that was that our address
space request was simply denied ("because it does not comply with current
policy.")

As a result of all this nonsense, the ISPs in the Netherlands (and
elsewhere) that do supply IPv6 connectivity to their customers resort
to the immensely wasteful practise of giving each and every single
customer an entire /48 because otherwise they will not have assigned
enough address space in two years and risk the wrath of RIPE.

(And there's no way in hell you'll get people to peer with you if you
start sending them 2002:xxxx:xxxx::/48 routes :-)


cheers,
Lennert

On Thu, Nov 04, 2004 at 10:18:01PM -0800, David S. Miller wrote:

BTW Lennert, the decoded addresses are extremely helpful. Thanks.

I'm glad.

But let me ask, do you have any IPSEC policies in the kernel
when these BUGs trigger?  If so, I'm pretty sure I know what
the problem may be.

IPSEC.. not that I know of.  So unless my distro does stuff behind
my back, no.  How do I make sure?


--L

Lennert Buytenhek wrote:

On Thu, Nov 04, 2004 at 10:18:01PM -0800, David S. Miller wrote:

quoted

BTW Lennert, the decoded addresses are extremely helpful. Thanks.

I'm glad.

quoted

But let me ask, do you have any IPSEC policies in the kernel
when these BUGs trigger?  If so, I'm pretty sure I know what
the problem may be.

IPSEC.. not that I know of.  So unless my distro does stuff behind
my back, no.  How do I make sure?

setkey -DP