node establish tunnels, but does not get route to mesh

[jhpoelen]

For some reason, a specific node, successfully creates a tunnel digger interface, but exitnode fails to create a route for the node. This is why the client's ping to the 100.64.0.42 go unanswered, client drops the tunnel and tries to reconnect all over again. As far as I can tell, this only happens with one specific node. mesh IP address of home node can be shared privately if needed.

Please see attached log file.

tcpdumpL2TP-2018-03-13.txt

[jhpoelen]

Found while attempting to reproduce #8 .

[paidforby]

I'm also observing this on a handful of nodes, patched with #23 and #27. Immediately after flashing/makenodeing (or patching or even zeroconf'ing), they will appear to work and provide a route to the mesh and the internet via the exit node (either 100.64.0.42 or 100.64.0.43) but after awhile the routes will disappear and babel will stop babeling, despite the l2tp tunnel still being successfully established. babeld -i provides the very unexciting output,

root@node_paidforby_:~# babeld -i
Listening on interfaces: l2tp0 mesh2 mesh5 eth0.1 eth0.2 

My id 02:90:a9:ff:fe:0e:36:61 seqno 51954
100.65.99.0/26 metric 128 (exported)

Also tailing /var/log/messages repeatedly shows,

Wed Apr 18 09:05:47 2018 user.notice root: no mesh routes available yet via [l2tp0] on try [126]: checking again in [5]s...

but it also looks like the tunnel is getting shutdown and restarted every so often?

Wed Apr 18 09:07:00 2018 daemon.notice netifd: wan (1629): Stopping tunneldigger for interface l2tp0
Wed Apr 18 09:07:00 2018 daemon.warn td-client: Got termination signal, shutting down tunnel...
Wed Apr 18 09:07:00 2018 daemon.notice netifd: wan (1629):   waiting for tunneldigger to stop
Wed Apr 18 09:07:00 2018 user.notice root: Received 'session.down' for interface l2tp0
Wed Apr 18 09:07:01 2018 daemon.notice netifd: wan (1629):   tunneldigger stopped
Wed Apr 18 09:07:01 2018 daemon.notice netifd: wan (1629): Starting tunneldigger on l2tp0
Wed Apr 18 09:07:01 2018 daemon.info td-client: Performing broker selection...
Wed Apr 18 09:07:02 2018 daemon.debug td-client: Broker usage of 64.71.176.94:8942: 255
Wed Apr 18 09:07:02 2018 daemon.info td-client: Selected 64.71.176.94:8942 as the best broker.
Wed Apr 18 09:07:03 2018 daemon.info td-client: Tunnel successfully established.
Wed Apr 18 09:07:03 2018 daemon.info td-client: Requesting the broker to configure downstream bandwidth limit of 99999 kbps.
Wed Apr 18 09:07:03 2018 user.notice root: Received 'session.up' for interface l2tp0
Wed Apr 18 09:07:03 2018 kern.warn kernel: [  794.590000] HTB: quantum of class 10001 is big. Consider r2q change.
Wed Apr 18 09:07:04 2018 user.notice root: New mtu=1488
Wed Apr 18 09:07:11 2018 daemon.notice netifd: wan (1629): brctl: bridge br-open: Device or resource busy
Wed Apr 18 09:07:11 2018 daemon.notice netifd: wan (1629): brctl: bridge br-open: Device or resource busy
Wed Apr 18 09:07:12 2018 daemon.notice netifd: wan (1629): Starting in fungible mode
Wed Apr 18 09:07:13 2018 user.notice root: no mesh routes available yet via [l2tp0] on try [141]: checking again in [5]s...
Wed Apr 18 09:07:18 2018 user.notice root: no mesh routes available yet via [l2tp0] on try [142]: checking again in [5]s...
Wed Apr 18 09:07:23 2018 daemon.info td-client: Setting MTU to 1446
Wed Apr 18 09:07:23 2018 user.notice root: no mesh routes available yet via [l2tp0] on try [143]: checking again in [5]s...
Wed Apr 18 09:07:24 2018 daemon.info td-client: Setting MTU to 1446
Wed Apr 18 09:07:28 2018 user.notice root: no mesh routes available yet via [l2tp0] on try [144]: checking again in [5]s...

This looks suspiciously like the output produced by /etc/init.d/meshrouting I'm going to attempt re-adding the single line deletion suggested by the patch to #23 and see if the that changes anything.

[paidforby]

Or maybe it's udhcp.user, either way I'll revert one then the other and find the cause, or maybe the exit node is misbehaving?

[jhpoelen]

@paidforby suggest to troubleshoot the exit node first to get a complete picture.

[paidforby]

I do not have access to exit nodes, my node is now working after forcing it to use psychz exit node, not sure if there is a problem with HE. But I also, reverted patch 23 so it's hard to tell what fixed what. will do more debugging and report back.

[jhpoelen]

@paidforby perhaps time to get access to the exit nodes. I can confirm it is an issue on the HE exit node.

[paidforby]

Cool, yes, I can ping 100.64.0.43 again. Any ideas of the cause, is it related to #24 ? You can PM me to give me access so I can work on that bug, thanks.

[jhpoelen]

It appears that a "dirty" pid file /var/run/babeld.pid caused issue. After cleaning up the pid file, the babeld started ok.

$ /usr/local/bin/babeld -F -S /var/lib/babeld/state -c /etc/babeld.conf 
Starting in fungible mode
creat(/var/run/babeld.pid): File exists
$ ps -ef | grep babeld
xxx 19757 19436  0 10:41 pts/0    00:00:00 grep babeld
$ sudo rm /var/run/babeld.pid
$ sudo service babeld status
● babeld.service - babeld
   Loaded: loaded (/etc/systemd/system/babeld.service; disabled; vendor preset: enabled)
   Active: failed (Result: exit-code) since Tue 2018-04-17 18:42:30 PDT; 15h ago
  Process: 10452 ExecStart=/usr/local/bin/babeld -F -S /var/lib/babeld/state -c /etc/babeld.conf (code=exited, status=1/FAILURE)
 Main PID: 10452 (code=exited, status=1/FAILURE)
$ sudo service babeld start
$ sudo service babeld status
● babeld.service - babeld
   Loaded: loaded (/etc/systemd/system/babeld.service; disabled; vendor preset: enabled)
   Active: active (running) since Wed 2018-04-18 10:41:38 PDT; 2s ago
 Main PID: 19826 (babeld)
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/babeld.service
           └─19826 /usr/local/bin/babeld -F -S /var/lib/babeld/state -c /etc/babeld.conf

Apr 18 10:41:38 exit0 systemd[1]: Started babeld.

[bennlich]

@jhpoelen was babeld not running on the HE exit node?

[jhpoelen]

yep, as shown in

$ ps -ef | grep babeld
xxx 19757 19436  0 10:41 pts/0    00:00:00 grep babeld
$ 

[bennlich]

Saw that. Was confused by the order. Wondering why you tried to start it manually with

/usr/local/bin/babeld -F -S /var/lib/babeld/state -c /etc/babeld.conf 

instead of with service start as you did later. I guess babeld was not running and was failing to start w/ service command--is that right?

[jhpoelen]

yep. tried starting manually to see what was going on and eliminate systemd from the equation.

[bennlich]

Got it. Any sign of why it died?

[jhpoelen]

please switch to rc

[bennlich]

Here's the log excerpt when babeld died on HE:

Apr 17 18:30:18 exit0 systemd[1]: Started babeld-monitor.
Apr 17 18:30:18 exit0 babeld-monitor.sh[10257]: found no [Cannot allocate memory] error entry or babeld is not running
Apr 17 18:39:08 exit0 babeld[17629]: Warning: cannot save old configuration for l2tp745-745.
Apr 17 18:40:18 exit0 systemd[1]: Started babeld-monitor.
Apr 17 18:40:18 exit0 babeld-monitor.sh[10333]: found no [Cannot allocate memory] error entry or babeld is not running
Apr 17 18:40:26 exit0 babeld[17629]: removing: l2tp745-745
Apr 17 18:40:34 exit0 babeld[17629]: Warning: cannot save old configuration for l2tp746-746.
Apr 17 18:42:17 exit0 babeld[17629]: removing: l2tp746-746
Apr 17 18:42:28 exit0 systemd[1]: babeld.service: Main process exited, code=killed, status=11/SEGV
Apr 17 18:42:28 exit0 systemd[1]: babeld.service: Unit entered failed state.
Apr 17 18:42:28 exit0 systemd[1]: babeld.service: Failed with result 'signal'.
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]
Apr 17 18:42:28 exit0 systemd[1]: babeld.service: Service hold-off time over, scheduling restart.
Apr 17 18:42:28 exit0 systemd[1]: Stopped babeld.
Apr 17 18:42:28 exit0 systemd[1]: Started babeld.
Apr 17 18:42:28 exit0 babeld[10443]: creat(/var/run/babeld.pid): File exists
Apr 17 18:42:28 exit0 babeld[10443]: Starting in fungible mode
Apr 17 18:42:28 exit0 systemd[1]: babeld.service: Main process exited, code=exited, status=1/FAILURE
Apr 17 18:42:28 exit0 systemd[1]: babeld.service: Unit entered failed state.
Apr 17 18:42:28 exit0 systemd[1]: babeld.service: Failed with result 'exit-code'.
Apr 17 18:42:29 exit0 systemd[1]: babeld.service: Service hold-off time over, scheduling restart.
Apr 17 18:42:29 exit0 systemd[1]: Stopped babeld.

So I guess it was a kernel panic?