Openvpn server route race condition?

Having an intermittent issue with Openvpn routes for client subnets disappearing from the routing table.
It doesn't happen all the time, and kind of feels like a race condition type scenario.

Openvpn is otherwise operating fine, and if the routes are missing, manually adding them back restores that functionality.

Logs always show that openvpn is (at least trying) to add the routes:

Sun Apr 21 17:56:31 2019 daemon.notice openvpn(custom_config)[25926]: /sbin/ifconfig tun0 10.8.0.1 netmask 255.255.255.0 mtu 1500 broadcast 10.8.0.255
Sun Apr 21 17:56:31 2019 daemon.notice openvpn(custom_config)[25926]: /sbin/route add -net 192.168.3.0 netmask 255.255.255.0 gw 10.8.0.4
Sun Apr 21 17:56:31 2019 daemon.notice openvpn(custom_config)[25926]: /sbin/route add -net 192.168.10.0 netmask 255.255.255.0 gw 10.8.0.5
Sun Apr 21 17:56:31 2019 daemon.notice openvpn(custom_config)[25926]: /sbin/route add -net 192.168.2.0 netmask 255.255.255.0 gw 10.8.0.3

So my questions:

  1. What in the system could be trying to delete routes or set routes back to defaults
  2. Anyone else seen this before and conquered it?
  3. What else have i missed?

Thanks for the links. That mostly looks like it applies to the client side right?
I’m having issues on the server side i.e. not the “push routes”

Without configs and logs we are limited to theoretical speculations.

That’s right. So I’m asking you to speculate on the server side instead :slight_smile:

At the very least, explain the method you use to add these routes.

The normal way via a server conf line. I've included the configs below but I don't think they will make a difference here.
Config

mode                  server
port                  3194
proto                 udp
tls-server
ifconfig              10.1.0.1 255.255.255.0
topology              subnet
client-config-dir     /etc/openvpn/ccd
script-security       2
tls-verify	      "/usr/lib/gargoyle/ovpn-cn-check.sh /etc/openvpn/verified-userlist"
crl-verify            /etc/openvpn/crl.pem
client-to-client




cipher                AES-128-CBC

dev                   tun
keepalive             25 180
status                /var/run/openvpn_status
verb                  3


dh                    /etc/openvpn/dh1024.pem
ca                    /etc/openvpn/ca.crt
cert                  /etc/openvpn/server.crt
key                   /etc/openvpn/server.key
tls-auth              /etc/openvpn/ta.key 0

persist-key
persist-tun
comp-lzo

push "topology subnet"
push "route-gateway 10.1.0.1"


route 192.168.1.0 255.255.255.0 10.1.0.2
route 192.168.14.0 255.255.255.0 10.1.0.6

NonWorking example

## DIDNT WORK - routes missing
Sun Apr 21 21:14:55 2019 daemon.err openvpn(custom_config)[11585]: event_wait : Interrupted system call (code=4)
Sun Apr 21 21:14:55 2019 daemon.notice openvpn(custom_config)[11585]: /sbin/route del -net 192.168.1.0 netmask 255.255.255.0
Sun Apr 21 21:14:55 2019 daemon.notice openvpn(custom_config)[11585]: /sbin/route del -net 192.168.14.0 netmask 255.255.255.0
Sun Apr 21 21:14:55 2019 daemon.notice openvpn(custom_config)[11585]: Closing TUN/TAP interface
Sun Apr 21 21:14:55 2019 daemon.notice openvpn(custom_config)[11585]: /sbin/ifconfig tun0 0.0.0.0
Sun Apr 21 21:14:55 2019 daemon.notice netifd: Network device 'tun0' link is down
Sun Apr 21 21:14:55 2019 daemon.notice netifd: Interface 'vpn' has link connectivity loss
Sun Apr 21 21:14:55 2019 daemon.notice netifd: Interface 'vpn' is now down
Sun Apr 21 21:14:55 2019 daemon.notice openvpn(custom_config)[11585]: SIGTERM[hard,] received, process exiting
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: OpenVPN 2.4.4 mips-openwrt-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD]
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: library versions: OpenSSL 1.0.2q  20 Nov 2018, LZO 2.10
Sun Apr 21 21:14:56 2019 daemon.warn openvpn(custom_config)[12217]: NOTE: your local LAN uses the extremely common subnet address 192.168.0.x or 192.168.1.x.  Be aware that this might create routing conflicts if you connect to the VPN server from public locations such as internet cafes that use the same subnet.
Sun Apr 21 21:14:56 2019 daemon.warn openvpn(custom_config)[12217]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: Diffie-Hellman initialized with 1024 bit key
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: TUN/TAP device tun0 opened
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: TUN/TAP TX queue length set to 100
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: /sbin/ifconfig tun0 10.1.0.1 netmask 255.255.255.0 mtu 1500 broadcast 10.1.0.255
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: /sbin/route add -net 192.168.1.0 netmask 255.255.255.0 gw 10.1.0.2
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: /sbin/route add -net 192.168.14.0 netmask 255.255.255.0 gw 10.1.0.6
Sun Apr 21 21:14:56 2019 daemon.warn openvpn(custom_config)[12217]: Could not determine IPv4/IPv6 protocol. Using AF_INET
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: Socket Buffers: R=[163840->163840] S=[163840->163840]
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: UDPv4 link local (bound): [AF_INET][undef]:3194
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: UDPv4 link remote: [AF_UNSPEC]
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: MULTI: multi_init called, r=256 v=256
Sun Apr 21 21:14:56 2019 daemon.notice openvpn(custom_config)[12217]: Initialization Sequence Completed
Sun Apr 21 21:14:56 2019 daemon.notice netifd: Interface 'vpn' is disabled
Sun Apr 21 21:14:56 2019 daemon.notice netifd: Interface 'vpn' is enabled
Sun Apr 21 21:14:56 2019 daemon.notice netifd: Interface 'vpn' is disabled
Sun Apr 21 21:14:56 2019 daemon.notice netifd: Interface 'vpn' is enabled
Sun Apr 21 21:14:56 2019 daemon.notice netifd: Network device 'tun0' link is up
Sun Apr 21 21:14:56 2019 daemon.notice netifd: Interface 'vpn' has link connectivity
Sun Apr 21 21:14:56 2019 daemon.notice netifd: Interface 'vpn' is setting up now
Sun Apr 21 21:14:56 2019 daemon.notice netifd: Interface 'vpn' is now up
Sun Apr 21 21:14:56 2019 user.notice firewall: Reloading firewall due to ifup of vpn (tun0)

Working example

## WORKED - routes okay
Sun Apr 21 21:13:19 2019 daemon.err openvpn(custom_config)[10901]: event_wait : Interrupted system call (code=4)
Sun Apr 21 21:13:19 2019 daemon.notice openvpn(custom_config)[10901]: /sbin/route del -net 192.168.1.0 netmask 255.255.255.0
Sun Apr 21 21:13:19 2019 daemon.warn openvpn(custom_config)[10901]: ERROR: Linux route delete command failed: external program exited with error status: 1
Sun Apr 21 21:13:19 2019 daemon.notice openvpn(custom_config)[10901]: /sbin/route del -net 192.168.14.0 netmask 255.255.255.0
Sun Apr 21 21:13:19 2019 daemon.warn openvpn(custom_config)[10901]: ERROR: Linux route delete command failed: external program exited with error status: 1
Sun Apr 21 21:13:19 2019 daemon.notice openvpn(custom_config)[10901]: Closing TUN/TAP interface
Sun Apr 21 21:13:19 2019 daemon.notice openvpn(custom_config)[10901]: /sbin/ifconfig tun0 0.0.0.0
Sun Apr 21 21:13:19 2019 daemon.notice netifd: Network device 'tun0' link is down
Sun Apr 21 21:13:19 2019 daemon.notice netifd: Interface 'vpn' has link connectivity loss
Sun Apr 21 21:13:19 2019 daemon.notice netifd: Interface 'vpn' is now down
Sun Apr 21 21:13:19 2019 daemon.notice openvpn(custom_config)[10901]: SIGTERM[hard,] received, process exiting
Sun Apr 21 21:13:19 2019 daemon.notice netifd: Interface 'vpn' is disabled
Sun Apr 21 21:14:00 2019 user.notice root: openvpn stopped, restarting
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: OpenVPN 2.4.4 mips-openwrt-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD]
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: library versions: OpenSSL 1.0.2q  20 Nov 2018, LZO 2.10
Sun Apr 21 21:14:00 2019 daemon.warn openvpn(custom_config)[11585]: NOTE: your local LAN uses the extremely common subnet address 192.168.0.x or 192.168.1.x.  Be aware that this might create routing conflicts if you connect to the VPN server from public locations such as internet cafes that use the same subnet.
Sun Apr 21 21:14:00 2019 daemon.warn openvpn(custom_config)[11585]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: Diffie-Hellman initialized with 1024 bit key
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Sun Apr 21 21:14:00 2019 daemon.notice netifd: Interface 'vpn' is enabled
Sun Apr 21 21:14:00 2019 daemon.notice netifd: Network device 'tun0' link is up
Sun Apr 21 21:14:00 2019 daemon.notice netifd: Interface 'vpn' has link connectivity
Sun Apr 21 21:14:00 2019 daemon.notice netifd: Interface 'vpn' is setting up now
Sun Apr 21 21:14:00 2019 daemon.notice netifd: Interface 'vpn' is now up
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: TUN/TAP device tun0 opened
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: TUN/TAP TX queue length set to 100
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: /sbin/ifconfig tun0 10.1.0.1 netmask 255.255.255.0 mtu 1500 broadcast 10.1.0.255
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: /sbin/route add -net 192.168.1.0 netmask 255.255.255.0 gw 10.1.0.2
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: /sbin/route add -net 192.168.14.0 netmask 255.255.255.0 gw 10.1.0.6
Sun Apr 21 21:14:00 2019 daemon.warn openvpn(custom_config)[11585]: Could not determine IPv4/IPv6 protocol. Using AF_INET
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: Socket Buffers: R=[163840->163840] S=[163840->163840]
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: UDPv4 link local (bound): [AF_INET][undef]:3194
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: UDPv4 link remote: [AF_UNSPEC]
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: MULTI: multi_init called, r=256 v=256
Sun Apr 21 21:14:00 2019 daemon.notice openvpn(custom_config)[11585]: Initialization Sequence Completed
Sun Apr 21 21:14:01 2019 user.notice firewall: Reloading firewall due to ifup of vpn (tun0)
1 Like

I can write something that will check and maintain the routes, but this is supposed to work, and does most of the time.
The reason i think it is a race condition is i can trigger it quite easily on an older slower router, but only 1 in 10 times with a much faster device.
I suspect that the route add commands are triggered before the iface is fully up and therefore failing (silently).

1 Like

There we go, thanks for the tip.
It looks like netifd was interfering, and removing the dummy network config and network with device options in the firewall config has made a difference. I'll need to observe and test more but initially seems good. :+1:

1 Like

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.