Hey everyone! fiiinally got back home, a week ago, and got time to debug a strange issue here. The report i had from a few users was "intermittent connectivity", with "waves" of traffic, with random pauses lasting from a few seconds to a minute or so.
I initially dismissed as interference, or even OS problems, but turns out they were right! and sadly, batman seems to be in the way
From what i've seen, watching "batctl tg -w" on every node along the way, i could determine the window of time where the traffic gets lost: from the moment when there's a TT change on one side of the network, to the moment that change is propagated to the other side.
By ordex's advice, i ran some "batctl ll tt ; batctl l" along the way and i'm sending the pastebin results at the end of this mail.
Some (hopefully) useful context follows, and a batctl vd graph is attached
The IPv6 of tdorado is pinged (to rule out DAT interactions) from labanda-este (works fine always) and from labanda-oeste (suffers the issue, as well as all nodes "behind" it, i.e. casapuente & alfredo). both labandas are tl-wdr3500 connected by 2.4ghz, 5ghz, and an ethernet cable. The ethernet carries only batadv packets (eth0.1 is added to bat0); there's no "lan backbone" (the eth0.2 that appears under br-lan is not connected to anything)
root@tdorado:~# opkg list kmod-batman-adv # same in all nodes kmod-batman-adv - 3.8.3+2013.2.0-2 root@tdorado:~# ip a s br-lan 6: br-lan: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP link/ether 64:70:02:3d:a0:f7 brd ff:ff:ff:ff:ff:ff inet6 2a00:1508:1:f004:6670:2ff:fe3d:a0f7/64 scope global dynamic valid_lft 6985sec preferred_lft 6985sec root@tdorado:~# batctl tl -n |grep f7 * 64:70:02:3d:a0:f7 [.....] 1.140 root@tdorado:~# batctl o |head -n 1 [B.A.T.M.A.N. adv 2013.2.0, MainIF/MAC: wlan0-1/66:70:02:3d:a0:f9 (bat0)]
labanda-este http://pastebin.com/R1kHQCQG
labanda-oeste http://pastebin.com/b1Uc23VZ
Both ping6s were started at the same time, so the seq numbers are synchronized, and can be used as timestamps.
the "gap" in labanda-oeste is between seq=73 and seq=89 in labanda-oeste there were no messages or traffic for 25secs, and then the "TT inconsistency" came up, resolved, and seq=89 succeded, traffic restored. at that time, seq=74, labanda-este got a TT update: [ 23161800] Deleting tdorado from global tt entry 44:d8:84:b0:d2:f5: tt removed by changes and (AFAIU) dropped traffic coming from labanda-oeste until labanda-oeste finally got the TT update and increased the ttvn to 129
does any of this make sense? I imagine a tcpdump would help, so i'll try getting one, but maybe this debug was enough to get an insight?
As you can imagine, any further pointer will be greatly appreciated,
I hope you're having a great week, ...and that i'm not ruining it as always :D
Gui
On 06/23/2013 06:51 PM, Gui Iribarren wrote:
Hey everyone! fiiinally got back home, a week ago, and got time to debug a strange issue here. The report i had from a few users was "intermittent connectivity", with "waves" of traffic, with random pauses lasting from a few seconds to a minute or so.
I initially dismissed as interference, or even OS problems, but turns out they were right! and sadly, batman seems to be in the way
From what i've seen, watching "batctl tg -w" on every node along the way, i could determine the window of time where the traffic gets lost: from the moment when there's a TT change on one side of the network, to the moment that change is propagated to the other side.
By ordex's advice, i ran some "batctl ll tt ; batctl l" along the way and i'm sending the pastebin results at the end of this mail.
Some (hopefully) useful context follows, and a batctl vd graph is attached
The IPv6 of tdorado is pinged (to rule out DAT interactions) from labanda-este (works fine always) and from labanda-oeste (suffers the issue, as well as all nodes "behind" it, i.e. casapuente & alfredo). both labandas are tl-wdr3500 connected by 2.4ghz, 5ghz, and an ethernet cable. The ethernet carries only batadv packets (eth0.1 is added to bat0); there's no "lan backbone" (the eth0.2 that appears under br-lan is not connected to anything)
root@tdorado:~# opkg list kmod-batman-adv # same in all nodes kmod-batman-adv - 3.8.3+2013.2.0-2 root@tdorado:~# ip a s br-lan 6: br-lan: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc noqueue state UP link/ether 64:70:02:3d:a0:f7 brd ff:ff:ff:ff:ff:ff inet6 2a00:1508:1:f004:6670:2ff:fe3d:a0f7/64 scope global dynamic valid_lft 6985sec preferred_lft 6985sec root@tdorado:~# batctl tl -n |grep f7
- 64:70:02:3d:a0:f7 [.....] 1.140
root@tdorado:~# batctl o |head -n 1 [B.A.T.M.A.N. adv 2013.2.0, MainIF/MAC: wlan0-1/66:70:02:3d:a0:f9 (bat0)]
labanda-este http://pastebin.com/R1kHQCQG
labanda-oeste http://pastebin.com/b1Uc23VZ
Both ping6s were started at the same time, so the seq numbers are synchronized, and can be used as timestamps.
the "gap" in labanda-oeste is between seq=73 and seq=89 in labanda-oeste there were no messages or traffic for 25secs, and then the "TT inconsistency" came up, resolved, and seq=89 succeded, traffic restored. at that time, seq=74, labanda-este got a TT update: [ 23161800] Deleting tdorado from global tt entry 44:d8:84:b0:d2:f5: tt removed by changes and (AFAIU) dropped traffic coming from labanda-oeste until labanda-oeste finally got the TT update and increased the ttvn to 129
To clarify, what i mean is that during the time window that packets from labanda-oeste get lost, i see this
root@labanda-este:~# batctl tg |grep tdorado_eth0 * tdorado_eth0 ( 0) via tdorado ( 77) (0xe574) [...]
root@labanda-oeste:~# batctl tg|grep tdorado_eth0 * tdorado_eth0 ( 75) via tdorado ( 76) (0x03db) [...]
and traffic is restored the instant oeste gets ttvn=77 / crc=0xe574
finally, i must add that running a "batctl ping tdorado" from labanda-oeste in parallel shows no loss during the whole scenario.
does any of this make sense? I imagine a tcpdump would help, so i'll try getting one, but maybe this debug was enough to get an insight?
As you can imagine, any further pointer will be greatly appreciated,
I hope you're having a great week, ...and that i'm not ruining it as always :D
Gui
On Sun, Jun 23, 2013 at 07:28:08PM -0300, Gui Iribarren wrote:
On 06/23/2013 06:51 PM, Gui Iribarren wrote:
the "gap" in labanda-oeste is between seq=73 and seq=89 in labanda-oeste there were no messages or traffic for 25secs, and then the "TT inconsistency" came up, resolved, and seq=89 succeded, traffic restored. at that time, seq=74, labanda-este got a TT update: [ 23161800] Deleting tdorado from global tt entry 44:d8:84:b0:d2:f5: tt removed by changes and (AFAIU) dropped traffic coming from labanda-oeste until labanda-oeste finally got the TT update and increased the ttvn to 129
As we clarified on IRC, BLA2 is not involved at all. From what I can see I'd say that a node in the middle is dropping the traffic due to a wrong re-routing operation. if you could reproduce the issue, it would be nice if you could get the tt log on all the nodes along the path. In this way we can clearly see who is doing what.
Cheers,
On 06/24/2013 04:02 AM, Antonio Quartulli wrote:
On Sun, Jun 23, 2013 at 07:28:08PM -0300, Gui Iribarren wrote:
On 06/23/2013 06:51 PM, Gui Iribarren wrote:
the "gap" in labanda-oeste is between seq=73 and seq=89 in labanda-oeste there were no messages or traffic for 25secs, and then the "TT inconsistency" came up, resolved, and seq=89 succeded, traffic restored. at that time, seq=74, labanda-este got a TT update: [ 23161800] Deleting tdorado from global tt entry 44:d8:84:b0:d2:f5: tt removed by changes and (AFAIU) dropped traffic coming from labanda-oeste until labanda-oeste finally got the TT update and increased the ttvn to 129
As we clarified on IRC, BLA2 is not involved at all. From what I can see I'd say that a node in the middle is dropping the traffic due to a wrong re-routing operation. if you could reproduce the issue, it would be nice if you could get the tt log on all the nodes along the path. In this way we can clearly see who is doing what.
(11:58:09 AM) gui_: ah, ordex, btw, there's no "in the middle" :( (11:58:29 AM) ordex: what do you mean? (11:58:41 AM) ordex: does it happen with two nodes only? (11:58:44 AM) gui_: labanda-este is a direct neighbor of tdorado (11:58:49 AM) gui_: i mean the path is (11:58:53 AM) gui_: oeste -> este -> tdorado
And, finally, to throw some spice into the mix, i downgraded kmod-batman-adv just in labanda-este (my key suspect) twice, and... i can reproduce this issue with 3.8.3+2013.2.0-2 and 3.8.3+2013.1.0-3 but not with 3.8.3+2012.4.0-1
both labanda-oeste and tdorado are still running 2013.2.0. Downgrading labanda-este to 2012.4.0 was enough to solve the issue.
so it looks like a regression introduced between 2012.4.0 and 2013.1.0
yet, it is pretty obscure to me what is actually happening, (and why only in this scenario) so i'll try to get some dumps as promised, but since my current internet connection depends on this link, i was a bit in a hurry to get it back to stable :P
Cheers!
Gui
On Tue, Jun 25, 2013 at 01:14:09AM -0300, Gui Iribarren wrote:
On 06/24/2013 04:02 AM, Antonio Quartulli wrote:
On Sun, Jun 23, 2013 at 07:28:08PM -0300, Gui Iribarren wrote:
On 06/23/2013 06:51 PM, Gui Iribarren wrote:
the "gap" in labanda-oeste is between seq=73 and seq=89 in labanda-oeste there were no messages or traffic for 25secs, and then the "TT inconsistency" came up, resolved, and seq=89 succeded, traffic restored. at that time, seq=74, labanda-este got a TT update: [ 23161800] Deleting tdorado from global tt entry 44:d8:84:b0:d2:f5: tt removed by changes and (AFAIU) dropped traffic coming from labanda-oeste until labanda-oeste finally got the TT update and increased the ttvn to 129
As we clarified on IRC, BLA2 is not involved at all. From what I can see I'd say that a node in the middle is dropping the traffic due to a wrong re-routing operation. if you could reproduce the issue, it would be nice if you could get the tt log on all the nodes along the path. In this way we can clearly see who is doing what.
(11:58:09 AM) gui_: ah, ordex, btw, there's no "in the middle" :( (11:58:29 AM) ordex: what do you mean? (11:58:41 AM) ordex: does it happen with two nodes only? (11:58:44 AM) gui_: labanda-este is a direct neighbor of tdorado (11:58:49 AM) gui_: i mean the path is (11:58:53 AM) gui_: oeste -> este -> tdorado
And, finally, to throw some spice into the mix, i downgraded kmod-batman-adv just in labanda-este (my key suspect) twice, and... i can reproduce this issue with 3.8.3+2013.2.0-2 and 3.8.3+2013.1.0-3 but not with 3.8.3+2012.4.0-1
both labanda-oeste and tdorado are still running 2013.2.0. Downgrading labanda-este to 2012.4.0 was enough to solve the issue.
so it looks like a regression introduced between 2012.4.0 and 2013.1.0
why didn't you 2013.0.0 since you were jumping from version to version? :)
Thanks a lot for doing these tests!
Cheers,
b.a.t.m.a.n@lists.open-mesh.org
-
Antonio Quartulli -
Gui Iribarren