babeld segmentation fault on exit node causes lost routes

[paidforby]

Related to #21, the "new" exit node continues to have difficulties maintaining its babeld process.

On home nodes pointed toward new exit node, I'm seeing this is the logs

Tue Apr 24 19:07:43 2018 user.notice root: no mesh routes available yet via [l2tp0] on try [26]: checking again in [5]s...

On the "new" exit node, I'm noticed this in /var/log/messages

Apr 24 12:17:55 exit0 kernel: [433698.664554] babeld[830]: segfault at 18 ip 00005567267473d0 sp 00007ffc6a239240 error 4 in babeld[55672673d000+16000]
Apr 24 17:27:26 exit0 kernel: [452270.052907] babeld[3596]: segfault at fffffff337dc3df9 ip 000055e3a510f112 sp 00007fffd89c3400 error 7 in babeld[55e3a5104000+16000]
Apr 24 18:10:33 exit0 kernel: [454857.088438] traps: babeld[3767] general protection ip:561947add3d0 sp:7fffc111a920 error:0
Apr 24 18:10:33 exit0 kernel: [454857.088445]  in babeld[561947ad3000+16000]

However, the babeld process appears to alive and well and restarting it does nothing

● babeld.service - babeld
   Loaded: loaded (/etc/systemd/system/babeld.service; disabled; vendor preset: 
   Active: active (running) since Tue 2018-04-24 18:10:33 PDT; 59min ago
 Main PID: 5288 (babeld)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/babeld.service
           └─5288 /usr/local/bin/babeld -F -S /var/lib/babeld/state -c /etc/babe

Apr 24 18:22:23 exit0 babeld[5288]: removing: l2tp354-354
Apr 24 18:22:32 exit0 babeld[5288]: removing: l2tp355-355
Apr 24 18:24:24 exit0 babeld[5288]: removing: l2tp356-356
Apr 24 18:26:13 exit0 babeld[5288]: removing: l2tp357-357
Apr 24 18:26:15 exit0 babeld[5288]: send: Cannot assign requested address
Apr 24 18:28:16 exit0 babeld[5288]: removing: l2tp358-358
Apr 24 19:05:13 exit0 babeld[5288]: Warning: cannot restore old configuration fo
Apr 24 19:05:13 exit0 babeld[5288]: removing: l2tp350-350
Apr 24 19:07:05 exit0 babeld[5288]: removing: l2tp360-360
Apr 24 19:08:55 exit0 babeld[5288]: removing: l2tp361-361

Any ideas of the root cause? Perhaps its related to #24 that haunts the old exitnode? I'm tempted to just restart it and see if comes back to life, but I don't think that will help us solve the problem. Some other node whispers should jump into the exit node and see what they can figure out.

[bennlich]

That's cool that the babeld process gets restarted successfully. This means that your change to the systemd service file worked!

My first guess is: after babeld restarts on the exit node, it is unaware of any pre-existing tunnels, so it won't respond to any babeling on any existing tunnel interfaces.

Can test this hypothesis by restarting meshrouting on a homenode that is showing the no mesh routes available yet error. Restarting meshrouting will restart tunneldigger and cause a new l2tp interface to come up on the exitnode. This executes the hook that alerts babeld of the new interface. If the hypothesis is correct, the homenode should succeed in getting a route.

[paidforby]

Tested your suggestion and it does not appear to work. Additionally I have been flashing new nodes, creating new tunnels, and turning nodes off and on all day, and none of them have be able to babel with the exit node.

One question this brings to mind is, why are we still using our fork of babeld "https://github.com/sudomesh/babeld"? Is it just for the convenience of babeld -i? Is there something I am missing, I noticed we also added a "fungible mode"? Why not use a stable release of https://github.com/jech/babeld?

Just wondering if our babelling difficulties were perhaps fixed somewhere in the 186 commits and 4 releases since we forked ours.

Also if our changes don't conflict with the normal operation of babeld, why don't we make a pull request to the main repo?

[bennlich]

Tested your suggestion and it does not appear to work. Additionally I have been flashing new nodes, creating new tunnels, and turning nodes off and on all day, and none of them have be able to babel with the exit node.

K, dang.

One question this brings to mind is, why are we still using our fork of babeld "https://github.com/sudomesh/babeld"? Is it just for the convenience of babeld -i? Is there something I am missing, I noticed we also added a "fungible mode"? Why not use a stable release of https://github.com/jech/babeld?

Yes we are stilling using our fork. The important piece of our fork is the babeld -a option, which lets you add a new interface to an already running babeld. This is called from the exitnode tunneldigger uphook script. AFAIK the main babeld branch requires you to pass in all the interfaces you want to babel on when babeld first starts.

I think these changes were pretty hefty, but I haven't looked at them closely--here's the diff: sudomesh/babeld@sudomesh:acc7bde48f504609a4b67ed205798f3c4c07b057...master.

[bennlich]

@paidforby Are the home nodes you've been testing with using the old tunneldigger or the new tunneldigger? (Only the new one will connect reliably to HE.)

[jhpoelen]

The restart script related to #21 automatically adds tunneldigger interfaces to a newly restarted babeld process. That seems to be working quite well as far as I can tell. However, when the babeld process crashes and restarts via systemd, this re-adding of tunnel digger interfaces does not occur. https://github.com/sudomesh/exitnode/blob/dad8b658b07f42c2146eb8893fdd571b4149f2d0/src/opt/babeld-monitor/babeld-monitor.sh#L43 .

Do you have a specific home node on which this issue present itself?

[jhpoelen]

Along the lines of @bennlich question - which version of the firmware are you using? are you using an upgraded version of babeld. Suggest to use v0.2.3 rather than a newer (untested) version to avoid unnecessary variability.

[jhpoelen]

A short glimpse at the tunneldigger logs on the "new" exit node:

Apr 25 10:52:04 exit0 python[510]: [WARNING/tunneldigger.broker] Session identifier 1 already exists.
Apr 25 10:52:04 exit0 python[510]: [WARNING/tunneldigger.protocol] Failed to create tunnel (ba096bf9-9aa5-4fcc-92af-306e7009ee3c) while proc
Apr 25 10:52:07 exit0 python[510]: [INFO/tunneldigger.broker] Creating tunnel (xxx-306e7009ee3c) with id 465.
Apr 25 10:52:07 exit0 python[510]: [WARNING/tunneldigger.broker] Session identifier 1 already exists.

Note the Session identifier 1 already exists. This is a sign that old tunneldigger clients are used to establish tunnels. The clients need to be upgraded before being able to connect to the "new" exit node.

[paidforby]

@jhpoelen I'm using two different versions on different hardware and neither is working,

• MyNet N750 with v0.2.3 and makenode v0.0.1
• MyNet N600 with v0.3.0

I've seen v0.3.0 working numerous times, when the new exitnode is in a known working state. The tunneldigger upgrade was made in sudomesh/nodewatcher-firmware-packages@d4e3b9f so any new build of the firmware should pull in the new version of tunneldigger. Could you provide instructions on checking the tunneldigger client version on home nodes?

It should also be noted that https://peoplesopen.herokuapp.com/ is reporting far fewer nodes than it was when it was working, so I imagine others using v0.2.3 and up are seeing this problem as well.

The only change I did make is I had to turn off my "bridging" nodes that helped restore order to the mesh after we resolved #21 (one was v0.2.2 pointing at the old exit node and one was v0.3.0 pointing at the new exitnode)

[paidforby]

The only change I did make is I had to turn off my "bridging" nodes that helped restore order to the mesh after we resolved #21

Ok, so weird. I reconfigured the bridge node setup in my room just now and it appears to have corrected the issues with the new exit node? I have no explanation for why this works, but the number of nodes jumped from 19 before I set it up, to 34 afterwards. I will also note that the number of gateways remained at 14? Aha, that means that 15 nodes out in the world are relying on the single gateway in my room. Interesting. Here's the set up the restores order,

1. MyNet N600 flashed with sudowrt v0.2.2 and configured with makenode v0.1.0, provide internet via WAN port, comment out the "new" exit node in /etc/config/tunneldigger so it will only look for the old

2. MyNet N600 flashed with sudowrt v0.2.3 and configured with makenode v0.1.0 (or just sudowrt v0.3.0 and no makenode 😁), provide internet via WAN port, comment out the "old" exit node in /etc/config/tunneldigger so it will only look for the new.

3. Allow a little time for them to find their respective exit nodes, then find each other over their ad-hoc interfaces, and then share their routing tables and...volia! the mesh converges in less than 5 mins.

Any ideas why we might be seeing, does this give any clues as to the root cause? Why must we have a bridge setup? Shouldn't the new nodes work all on their own?

[jhpoelen]

I'd need more information (routes, logs etc) to understand the root cause of this. Last time I checked, mole in sudoroom was acting as a bridge between the "new" and the "old" exit nodes. However, today, mole (65.93.65) was unable to ping 100.64.0.42 (old exit node). This indicates that mole is no longer bridging between new and old exit node. Perhaps this is because all the nodes at sudoroom are now running the new firmware.

Note that the monitor is coded/configured to only report via the old exit node at this point. There's no reason why we can't extend this to include more exit node. This would require a little javascript coding . . .

[jhpoelen]

With the information I have now, I think we are just looking at a feature, rather than a bug. Extending the monitor software would help to monitor the network from multiple exit nodes. Also, we can create a static bridge directly between the exit nodes by configuring a client on the one, talking to a broker on the other. I'd favor extending the monitoring, especially because we don't really have any mesh services at this point.

[paidforby]

I realize now that the monitor only reports through the old exit node, I don't necessarily take issue with that. Perhaps my comment was misunderstood, but I'd strongly disagree that this a feature, it seems more like a major flaw in the new exit node, only that we haven't noticed it until recently because mole and an old node in sudoroom were bridging the exitnodes. After turning off the old nodes in sudoroom on Tuesday, 4/17, we immediately observed the first outage the next day in #21, while partially patched, I still think we have yet to discover the root cause. Similarly, after shutting down my bridging nodes on Saturday 4/21, there was a second outage, first observed on 4/24. The following is detailed description of the behavior I have observed in the case of both outages,

1. The bridging nodes are setup, everything is working normally, i.e. everyone on 100.64.0.0/10 subnet can ping everyone else and can reach the internet.
2. The bridging nodes are turned off, everything continues working normally.
3. Some time later, an error occurs in babeld on the new exit node (segmentation fault? maybe related to node establish tunnels, but does not get route to mesh #21 or setsockopt out of memory causes babeld failure #24) and babeld enters into a bad state, routes disappear to the old exit node (explaining the decrease in the monitor) and, more importantly, nodes maintain (or setup a new) tunnels to the new exit node, but are able to reach the internet or babel with any other nodes on the mesh. I've observed this on countless nodes newly flashed (with 0.2.3 or later) and ones that were flashed (with 0.2.3) and patched (for home nodes depend on static exit node ips #23 and Domain names not being resolved over extender node bridged connection  #27) weeks ago.
4. After either a) restarting the new exit node in the case of node establish tunnels, but does not get route to mesh #21 or b) restarting the babeld process, though it was still active and running, nodes tunnelling to the new exit node are still not able to reach the internet or babel with other nodes.
5. After reconfiguring the bridging nodes as I described in babeld segmentation fault on exit node causes lost routes #31 (comment), all nodes flashed with 0.2.3 or later and configured with makenode 0.0.1 or patched up to Domain names not being resolved over extender node bridged connection  #27 are suddenly able to reach the internet through the new exit node and babel again with each other.

What this means to me is that the new exit node is failing to operate independently of the old exit node. The "nuclear" option to check this theory would be to simply turn off the old exit node (or at least disable babeld and tunneldigger). However, for a more delicate way of reproducing, I suggest:

1. Turning off the bridging nodes that I am currently maintaining (I see this being a huge flaw/feature also, because what if I'm not near my bridging nodes, or what if someone else is unwittingly maintaining bridging nodes)
2. Check if everything is still working normally for an hour or two (allowing time for routes to disappear maybe?)
3. kill -9 the babeld process on the new exit node to trigger systemd to restart it and maybe put it into that bad state, otherwise wait a few hours/days for the error to occur
4. Check if everything is working normally (again allowing time for routes to disappear?)

Rather than running a tunneldigger client on a broker which seems messy to me, a temporary solution would be to create a self contained bridge node that is always left on, so when babeld is restarted, nodes are able to rediscover their route to other nodes and to the internet. However, this avoiding the real problem that is hiding somewhere in https://github.com/sudomesh/exitnode or the babeld-monitor.

[paidforby]

Here are some notable portions of /var/log/messages from a node that was on during outage, home_node_messages_dump_1.txt
home_node_messages_dump_2.txt

and also on the new exit node, I see both

Apr 17 15:19:38 exit0 kernel: [2681419.863612] HTB: quantum of class 10001 is big. Consider r2q change.
Apr 17 18:42:28 exit0 kernel: [2693589.502208] traps: babeld[17629] general protection ip:556562bea3d0 sp:7ffec3777290 error:0
Apr 17 18:42:28 exit0 kernel: [2693589.502215]  in babeld[556562be0000+16000]

and

Apr 19 21:44:53 exit0 kernel: [35712.741489] HTB: quantum of class 10001 is big. Consider r2q change.
Apr 20 20:43:24 exit0 kernel: [118424.812594] perf: interrupt took too long (2502 > 2500), lowering kernel.perf_event_max_sample_rate to 79750
Apr 21 22:17:13 exit0 kernel: [210454.370263] perf: interrupt took too long (3131 > 3127), lowering kernel.perf_event_max_sample_rate to 63750
Apr 24 12:17:55 exit0 kernel: [433698.664554] babeld[830]: segfault at 18 ip 00005567267473d0 sp 00007ffc6a239240 error 4 in babeld[55672673d000+16000]
Apr 24 17:27:26 exit0 kernel: [452270.052907] babeld[3596]: segfault at fffffff337dc3df9 ip 000055e3a510f112 sp 00007fffd89c3400 error 7 in babeld[55e3a5104000+16000]
Apr 24 18:10:33 exit0 kernel: [454857.088438] traps: babeld[3767] general protection ip:561947add3d0 sp:7fffc111a920 error:0
Apr 24 18:10:33 exit0 kernel: [454857.088445]  in babeld[561947ad3000+16000]
Apr 25 10:50:02 exit0 kernel: [514826.886135] HTB: quantum of class 10001 is big. Consider r2q change.
Apr 25 10:52:19 exit0 kernel: [514963.182555] HTB: quantum of class 10001 is big. Consider r2q change.
Apr 25 20:47:44 exit0 kernel: [550689.056115] babeld[5288]: segfault at fffffffb56cb2ff9 ip 0000557496a84112 sp 00007fff5886f6a0 error 7 in babeld[557496a79000+16000]
Apr 25 20:53:16 exit0 kernel: [551021.085994] babeld[22067]: segfault at 39 ip 0000555856d4b3d0 sp 00007ffc050306e0 error 4 in babeld[555856d41000+16000]

which seems to line up with the recent outages. I don't see anything similar in the old exit node's logs