OpenVPN with static key stopped working

[Michał Obrembski]

Steps to reproduce:

1. Clear NVRAM (not sure if required, but tested on cleared NVRAM)
2. Set Server to Static key
3. Generate static key
4. Save settings
5. Try to start openvpn server

Then check logs. Server is not started, and in logs you can see only enigmatic (Server failure to start). I've set vpn_debug to 4 - i havent get any more details.

Static key was working in stable 2018.5 version, not sure what about beta release.

[pedro]

No problem here on 2019.2.004 (https://bitbucket.org/pedro311/freshtomato-arm/commits/70f43a3ce7aeaef4fcae78b3580cd10743bd2b7b)

Mar  4 18:50:08 router kern.info kernel: ADDRCONF(NETDEV_UP): tun21: link is not ready
Mar  4 18:50:08 router kern.info kernel: device tun21 entered promiscuous mode
Mar  4 18:50:08 router daemon.warn openvpn[2861]: disabling NCP mode (--ncp-disable) because not in P2MP client or server mode
Mar  4 18:50:08 router daemon.notice openvpn[2861]: OpenVPN 2.4.7 arm-unknown-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Mar  3 2019
Mar  4 18:50:08 router daemon.notice openvpn[2861]: library versions: OpenSSL 1.0.2r  26 Feb 2019, LZO 2.10
Mar  4 18:50:08 router daemon.notice openvpn[2862]: Outgoing Static Key Encryption: Cipher 'AES-128-CBC' initialized with 128 bit key
Mar  4 18:50:08 router daemon.notice openvpn[2862]: Outgoing Static Key Encryption: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar  4 18:50:08 router daemon.notice openvpn[2862]: Incoming Static Key Encryption: Cipher 'AES-128-CBC' initialized with 128 bit key
Mar  4 18:50:08 router daemon.notice openvpn[2862]: Incoming Static Key Encryption: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar  4 18:50:08 router daemon.notice openvpn[2862]: TUN/TAP device tun21 opened
Mar  4 18:50:08 router daemon.notice openvpn[2862]: TUN/TAP TX queue length set to 100
Mar  4 18:50:08 router daemon.notice openvpn[2862]: /sbin/ifconfig tun21 10.6.0.1 pointopoint 10.6.0.2 mtu 1500
Mar  4 18:50:08 router kern.info kernel: ADDRCONF(NETDEV_CHANGE): tun21: link becomes ready
Mar  4 18:50:08 router daemon.warn openvpn[2862]: Could not determine IPv4/IPv6 protocol. Using AF_INET6
Mar  4 18:50:08 router daemon.notice openvpn[2862]: Socket Buffers: R=[122880->122880] S=[122880->122880]
Mar  4 18:50:08 router daemon.notice openvpn[2862]: setsockopt(IPV6_V6ONLY=0)
Mar  4 18:50:08 router daemon.notice openvpn[2862]: UDPv6 link local (bound): [AF_INET6][undef]:1194
Mar  4 18:50:08 router daemon.notice openvpn[2862]: UDPv6 link remote: [AF_UNSPEC]

[Michał Obrembski]

Ok, so let's analyze it. How did you configured it?

From my logs:

Mar  6 12:49:51 wygodna authpriv.info dropbear[4154]: Child connection from 61.0.0.0:57422
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_INFO: 640: VPN GUI server backend starting...
Mar  6 12:49:55 wygodna kern.info kernel: tun: Universal TUN/TAP device driver, 1.6
Mar  6 12:49:55 wygodna kern.info kernel: tun: (C) 1999-2004 Max Krasnyansky <[e-mail]>
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 732: Writing config file
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1082: Done writing config file
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1085: Writing certs/keys
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1146: Done writing certs/keys
Mar  6 12:49:55 wygodna kern.info kernel: ADDRCONF(NETDEV_UP): tun21: link is not ready
Mar  6 12:49:55 wygodna kern.info kernel: device tun21 entered promiscuous mode
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_INFO: 1159: Starting OpenVPN server 1
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_ERROR: 1163: Starting VPN instance failed...
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_INFO: 1267: Stopping VPN GUI server backend.
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1270: Removing cron job
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1277: Done removing cron job
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1280: Removing firewall rules.
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1293: Done removing firewall rules.
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1296: Stopping OpenVPN server.
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1299: OpenVPN server stopped.
Mar  6 12:49:55 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1302: Removing VPN device.
Mar  6 12:49:56 wygodna kern.info kernel: ADDRCONF(NETDEV_CHANGE): tun21: link becomes ready
Mar  6 12:49:56 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 1310: VPN device removed.
Mar  6 12:49:56 wygodna user.info preinit[1]: VPN_LOG_INFO: 1333: VPN GUI server backend stopped.
Mar  6 12:49:56 wygodna authpriv.info dropbear[4209]: Child connection from XX.YY.ZZ.WW:41473
Mar  6 12:50:01 wygodna authpriv.info dropbear[4209]: Exit before auth: Disconnect received

(FreshTomato latest version )

It appears that TUN device is not ready while openvpn is starting...It becomes ready but it's too late

Moreover, VPN Client is also not working in static key mode on my side. I've just swapped nodes (now server becomes client, and client becomes server), same logs:

Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_INFO: 73: VPN GUI client backend starting...
Mar  6 13:27:59 wygodna kern.info kernel: tun: Universal TUN/TAP device driver, 1.6
Mar  6 13:27:59 wygodna kern.info kernel: tun: (C) 1999-2004 Max Krasnyansky <[e-mail]>
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 182: Writing config file
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 341: Done writing config file
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 344: Writing certs/keys
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 408: Done writing certs/keys
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_INFO: 421: Starting OpenVPN client 1
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_ERROR: 425: Starting OpenVPN failed...
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_INFO: 537: Stopping VPN GUI client backend.
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 540: Removing cron job
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 547: Done removing cron job
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 550: Removing firewall rules.
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 563: Done removing firewall rules.
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 566: Stopping OpenVPN client.
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 569: OpenVPN client stopped.
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 572: Removing VPN device.
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_EXTRA: 580: VPN device removed.
Mar  6 13:27:59 wygodna user.info preinit[1]: VPN_LOG_INFO: 609: VPN GUI client backend stopped.

[Michał Obrembski]

OK, more to say. This commit is problematic: 58496b97a394c800b4c35423bbfd541eba9080ad rc: openvpn: make instance run code handle more than 1 CPU core

On my router (i tested it on Asus RT-N18U, which has 1 core CPU). rc/vpn.c: taskset_ret = cpu_eval(NULL, cpulist, &buffer[0], "--cd", &buffer2[0], "--config", "config.ovpn");

this fails, When i revert this commit, everything is ok. cpu_eval is using tasksel, which is failing don't know why.

I think somethink could be wrong with taskset, look:

taskset -c 1 /etc/openvpn/vpnclient1 --cd /etc/openvpn/client1 --
config config.ovpn
sched_setaffinity: Invalid argument
failed to set pid 0's affinity.

Tried also in another way, like described in --help:

taskset 0 /etc/openvpn/vpnclient1 --cd /etc/openvpn/client1 --config config.ovpn
sched_setaffinity: Invalid argument
failed to set pid 0's affinity.

Ok, so it apparently something is wrong with

sysconf(_SC_NPROCESSORS_CONF)

I've tested what is returned here. On AC68U (2 cores) it returns 2 However, on N18U (1 core) it also returns 2! Which leads to problems with openvpn.

Don't know why, but it is apparently wrong. There is also another sysconf variable, called _SC_NPROCESSORS_ONLN which returns count of processors which are online now. This variable however returns good values. I'm not sure if it is good to rely on this, i need to check

Fix proposal: https://bitbucket.org/kille72/freshtomato-arm/pull-requests/13/fix-counting-of-cpu-cores-in-system/diff

[pedro]

It's interesting, because this code comes from this Merlin's commit: https://github.com/RMerl/asuswrt-merlin.ng/commit/22024a0229265e574df42683abe0aa2bafbf572e
(RMerl committed on 9 Oct 2018)
So if something is wrong, it should be noticed long ago, IMO...
What image (SMP/NOSMP) are you using on that RT-N18U?

[Michał Obrembski]

I belive i was testing on this image:

https://exotic.se/freshtomato-arm/v2018/2018.5/freshtomato-RT-N18U-ARM-2018.5-AIO-64K-NOSMP.zip

Don't remember sorry, and i can't really retest it since this N18 is working in my client's home. Now i'm using my custom build, builded using ac68z target - it also produces N18 image with above patch and it's fine.

It may be possible, that i was using SMP version on N18, but then i suggest 1) Merge my patch (not sure if SMP brings us something on one-core platforms) or 2) remove creating N18 image on other targets than n18 from makefile :)