Possible bad interaction between BLA2 and TT?
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
Quoted 49 lines · Gui Iribarren
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/R1kHQCQGlabanda-oeste
http://pastebin.com/b1Uc23VZBoth ping6s were started at the same time, so the seq numbers are synchronized, and can be used as timestamps.
Quoted 9 lines
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.
Quoted 10 lines
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
Quoted 11 lines · Gui Iribarren
Quoted 10 lines · Gui Iribarren
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,
Signature · 4 lines
Antonio Quartulli ..each of us alone is worth nothing.. Ernesto "Che" Guevara
Quoted 13 lines · Antonio Quartulli
Quoted 11 lines · Gui Iribarren
Quoted 10 lines · Gui Iribarren
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
Quoted 5 lines
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
Quoted 32 lines · Gui Iribarren
Quoted 13 lines · Antonio Quartulli
Quoted 11 lines · Gui Iribarren
Quoted 10 lines · Gui Iribarren
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 129Quoted 5 lines
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 -> tdoradoAnd, 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
Quoted 4 lines
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,
Signature · 4 lines
Antonio Quartulli ..each of us alone is worth nothing.. Ernesto "Che" Guevara