Openvpn won't start after upgrading to firmware v2.25

fthuijs · June 4, 2017, 2:59pm

I had a perfectly working Openvpn connection on my ar-150 running firmware v2.19. Then I upgraded to firmware v2.25 and now I get the error message: ERROR: Linux route add command failed: external program exited with error status: 1.

I did not change anything nor on my ar-150 nor on my Openvpn server. I just upgraded the firmware of my ar-150.

What went wrong, and more important: how can I fix it!

Frank

P.S. Making an Openvpn connection from my iPad using the OpenVPN app still works, so there is nothing wrong with my Openvpn server, nor my ovpn files…

Information from the system log:

Sun Jun 4 08:44:51 2017 daemon.notice openvpn[8985]: OpenVPN 2.3.10 mips-openwrt-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [MH] [IPv6]

Sun Jun 4 08:44:51 2017 daemon.notice openvpn[8985]: library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08

Sun Jun 4 08:44:51 2017 daemon.notice openvpn[8986]: Control Channel Authentication: tls-auth using INLINE static key file

Sun Jun 4 08:44:51 2017 daemon.notice openvpn[8986]: NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay

Sun Jun 4 08:44:51 2017 daemon.notice openvpn[8986]: UDPv4 link local: [undef]

Sun Jun 4 08:44:51 2017 daemon.notice openvpn[8986]: UDPv4 link remote: [AF_INET]x.x.x.x:443

Sun Jun 4 08:44:55 2017 daemon.notice openvpn[8986]: [server] Peer Connection Initiated with [AF_INET]x.x.x.x:443

Sun Jun 4 08:44:57 2017 daemon.notice openvpn[8986]: TUN/TAP device tun0 opened

Sun Jun 4 08:44:57 2017 daemon.notice openvpn[8986]: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0

Sun Jun 4 08:44:57 2017 daemon.notice openvpn[8986]: /usr/sbin/ip link set dev tun0 up mtu 1500

Sun Jun 4 08:44:57 2017 daemon.notice openvpn[8986]: /usr/sbin/ip addr add dev tun0 local 10.8.0.22 peer 10.8.0.21

Sun Jun 4 08:44:57 2017 daemon.warn openvpn[8986]: ERROR: Linux route add command failed: external program exited with error status: 1

Sun Jun 4 08:44:57 2017 daemon.notice openvpn[8986]: GID set to nogroup

Sun Jun 4 08:44:57 2017 daemon.notice openvpn[8986]: UID set to nobody

Sun Jun 4 08:44:57 2017 daemon.notice openvpn[8986]: Initialization Sequence Completed

glitch · June 4, 2017, 4:25pm

Do a clean install (don’t save settings) and try again.

fthuijs · June 4, 2017, 6:34pm

Glitch, Thanks for your answer. What do you mean exactly: clean install of the firmware, or clean install of the openvpn-openssl software? If it is a clean install of the firmware, can it be done from de GLi Gui? At the moment I only have an iPad available which connects to the ar-150 via Wifi.

glitch · June 4, 2017, 9:19pm

I mean re-install the latest firmware from GUI. Do not save the settings - start from scratch.

Alternatively, you could try a factory reset and then start from scratch.

fthuijs · June 5, 2017, 3:00am

I re-installed the firmware without keeping the settings. After re-applying all the settings and uploading the ovpn file I started openvpn. I’m sorry to inform you that I still get the same error. So re-installing the firmware didn’t solve my problem.

Any other suggestions?

alzhao · June 5, 2017, 10:43am

Can you try firmware v2.255 GL.iNet download center

fthuijs · June 5, 2017, 3:59pm

Hi alzhao,

I installed firmware v2.255. Openvpn does start now but there are still a lot of error messages in the log. In particular add route and delete route give problems. The very first time (just after flashing) I started openvpn there were no messages. Then, stopping and starting generated error messages concerning the route add and route delete. I will adjust a part of the system log.

Mon Jun 5 09:39:11 2017 daemon.notice openvpn[3606]: OpenVPN 2.4.0 mips-openwrt-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD]

Mon Jun 5 09:39:11 2017 daemon.notice openvpn[3606]: library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08

Mon Jun 5 09:39:12 2017 daemon.notice openvpn[3609]: TCP/UDP: Preserving recently used remote address: [AF_INET]x.x.x.x:443

Mon Jun 5 09:39:12 2017 daemon.notice openvpn[3609]: UDP link local: (not bound)

Mon Jun 5 09:39:12 2017 daemon.notice openvpn[3609]: UDP link remote: [AF_INET]x.x.x.x:443

Mon Jun 5 09:39:12 2017 daemon.notice openvpn[3609]: NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay

Mon Jun 5 09:39:15 2017 daemon.notice openvpn[3609]: [server] Peer Connection Initiated with [AF_INET]x.x.x.x:443

Mon Jun 5 09:39:16 2017 daemon.notice netifd: Interface ‘VPN_client’ is enabled

Mon Jun 5 09:39:16 2017 daemon.notice netifd: Network device ‘tun0’ link is up

Mon Jun 5 09:39:16 2017 daemon.notice netifd: Interface ‘VPN_client’ has link connectivity

Mon Jun 5 09:39:16 2017 daemon.notice netifd: Interface ‘VPN_client’ is setting up now

Mon Jun 5 09:39:16 2017 daemon.notice openvpn[3609]: TUN/TAP device tun0 opened

Mon Jun 5 09:39:16 2017 daemon.notice openvpn[3609]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0

Mon Jun 5 09:39:16 2017 daemon.notice openvpn[3609]: /usr/sbin/ip link set dev tun0 up mtu 1500

Mon Jun 5 09:39:16 2017 daemon.notice netifd: Interface ‘VPN_client’ is now up

Mon Jun 5 09:39:16 2017 daemon.notice openvpn[3609]: /usr/sbin/ip addr add dev tun0 local 10.8.0.22 peer 10.8.0.21

Mon Jun 5 09:39:16 2017 daemon.notice openvpn[3609]: GID set to nogroup

Mon Jun 5 09:39:16 2017 daemon.notice openvpn[3609]: UID set to nobody

Mon Jun 5 09:39:16 2017 daemon.notice openvpn[3609]: Initialization Sequence Completed

Mon Jun 5 09:39:17 2017 user.notice firewall: Reloading firewall due to ifup of VPN_client (tun0)

Mon Jun 5 09:39:39 2017 daemon.err openvpn[3609]: event_wait : Interrupted system call (code=4)

Mon Jun 5 09:39:39 2017 daemon.warn openvpn[3609]: ERROR: Linux route delete command failed: external program exited with error status: 1

Mon Jun 5 09:39:39 2017 daemon.notice openvpn[3609]: /usr/sbin/ip addr del dev tun0 local 10.8.0.22 peer 10.8.0.21

Mon Jun 5 09:39:39 2017 daemon.warn openvpn[3609]: Linux ip addr del failed: external program exited with error status: 2

Mon Jun 5 09:39:39 2017 daemon.notice netifd: Network device ‘tun0’ link is down

Mon Jun 5 09:39:39 2017 daemon.notice netifd: Interface ‘VPN_client’ has link connectivity loss

Mon Jun 5 09:39:39 2017 daemon.notice netifd: Interface ‘VPN_client’ is now down

Mon Jun 5 09:39:39 2017 daemon.notice openvpn[3609]: SIGTERM[hard,] received, process exiting

Mon Jun 5 09:39:39 2017 daemon.notice netifd: Interface ‘VPN_client’ is disabled

Mon Jun 5 09:39:50 2017 daemon.notice openvpn[4426]: OpenVPN 2.4.0 mips-openwrt-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD]

Mon Jun 5 09:39:50 2017 daemon.notice openvpn[4426]: library versions: OpenSSL 1.0.2g 1 Mar 2016, LZO 2.08

Mon Jun 5 09:39:50 2017 daemon.notice openvpn[4427]: TCP/UDP: Preserving recently used remote address: [AF_INET]x.x.x.x:443

Mon Jun 5 09:39:50 2017 daemon.notice openvpn[4427]: UDP link local: (not bound)

Mon Jun 5 09:39:50 2017 daemon.notice openvpn[4427]: UDP link remote: [AF_INET]x.x.x.x:443

Mon Jun 5 09:39:50 2017 daemon.notice openvpn[4427]: NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay

Mon Jun 5 09:39:53 2017 daemon.notice openvpn[4427]: [server] Peer Connection Initiated with [AF_INET]x.x.x.x:443

Mon Jun 5 09:39:54 2017 daemon.notice openvpn[4427]: TUN/TAP device tun0 opened

Mon Jun 5 09:39:54 2017 daemon.notice openvpn[4427]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0

Mon Jun 5 09:39:54 2017 daemon.notice openvpn[4427]: /usr/sbin/ip link set dev tun0 up mtu 1500

Mon Jun 5 09:39:54 2017 daemon.notice openvpn[4427]: /usr/sbin/ip addr add dev tun0 local 10.8.0.22 peer 10.8.0.21

Mon Jun 5 09:39:54 2017 daemon.notice netifd: Interface ‘VPN_client’ is enabled

Mon Jun 5 09:39:54 2017 daemon.notice netifd: Network device ‘tun0’ link is up

Mon Jun 5 09:39:54 2017 daemon.notice netifd: Interface ‘VPN_client’ has link connectivity

Mon Jun 5 09:39:54 2017 daemon.notice netifd: Interface ‘VPN_client’ is setting up now

Mon Jun 5 09:39:54 2017 daemon.notice netifd: Interface ‘VPN_client’ is now up

Mon Jun 5 09:39:54 2017 daemon.warn openvpn[4427]: ERROR: Linux route add command failed: external program exited with error status: 1

Mon Jun 5 09:39:54 2017 daemon.notice openvpn[4427]: GID set to nogroup

Mon Jun 5 09:39:54 2017 daemon.notice openvpn[4427]: UID set to nobody

Mon Jun 5 09:39:54 2017 daemon.notice openvpn[4427]: Initialization Sequence Completed

Mon Jun 5 09:39:55 2017 user.notice firewall: Reloading firewall due to ifup of VPN_client (tun0)

Mon Jun 5 09:41:09 2017 daemon.err openvpn[4427]: event_wait : Interrupted system call (code=4)

Mon Jun 5 09:41:09 2017 daemon.warn openvpn[4427]: ERROR: Linux route delete command failed: external program exited with error status: 1

Mon Jun 5 09:41:09 2017 daemon.notice openvpn[4427]: /usr/sbin/ip addr del dev tun0 local 10.8.0.22 peer 10.8.0.21

Mon Jun 5 09:41:09 2017 daemon.warn openvpn[4427]: Linux ip addr del failed: external program exited with error status: 2

Mon Jun 5 09:41:09 2017 daemon.notice netifd: Network device ‘tun0’ link is down

Mon Jun 5 09:41:09 2017 daemon.notice netifd: Interface ‘VPN_client’ has link connectivity loss

Mon Jun 5 09:41:09 2017 daemon.notice netifd: Interface ‘VPN_client’ is now down

Mon Jun 5 09:41:09 2017 daemon.notice openvpn[4427]: SIGTERM[hard,] received, process exiting

Mon Jun 5 09:41:09 2017 daemon.notice netifd: Interface ‘VPN_client’ is disabled

alzhao · June 9, 2017, 4:52pm

Does the openvpn finally work or not in v2.255?

Some error will make the openvpn exit but some didn’t.

If it still exit, can you give me your config so that I have a try?

fthuijs · June 9, 2017, 5:24pm

Hi alzhao, in the end openvpn works.

But I’m concerned about the messages in the system log. First of all there where no error messages in firmware 2.19 and I did not change the openvpn config. Second, I use the same openvpn config in the Openvpn app on an iPad, and there the log stays clear of error messages.

As I read in the readme of the firmware, version 2.255 contains openvpn version 2.4. My openvpn server is still 2.3. I will upgrade my openvpn server to version 2.4 to see if the route delete and route add still give error messages. Let you know in this post…

fthuijs · June 9, 2017, 6:44pm

alzhao, I upgraded my server openvpn version to 2.4,2. Still got the same error messages concerning route delete and route add. Will now check server.conf and client.conf related to openvpn version 2.4.2.

At the end, openvpn is still working despite the confusing error messages…

fthuijs · June 9, 2017, 11:56pm

alzhao, I adjusted the server.conf and the .ovpn files according to the newest sample files provided by openvpn. This had no effect on the acting of the ar-150 which means: openvpn working, but still error messages.

alzhao · June 12, 2017, 5:33pm

OK. Thanks for the feedback. Will ask my engineers to investigate.

hansome · June 16, 2017, 7:49pm

I tried to many times in differcent situation, but no that ERROR message occured. Could you please turn up openvpn’s verbose level to 3 and run it foregound. By vi your .ovpn config file, add line “verb 3” and delete line “daemon”.

eg,

cd /etc/openvpn
vi client.ovpn
openvpn client.ovpn

and show me the log.
Especially the ‘PUSH: Received control message’ by your vpn server, and your local routing table.

fthuijs · June 16, 2017, 11:13pm

hansome,

Thanks for your reply! At this moment I have only remote access to my ar-150. I can get remote access to the GUI, but as far as I know I can not get access to the advanced settings and via that get access to the system log. So I can supply/activate an .ovpn file with verb 3 in it, but I’m afraid I can’t get the results in the log file…

Or is there a way to remotely get access to the advanced settings??

hansome · June 17, 2017, 7:03pm

Truely the firewall will block remote access.

BTW, I mean run openvpn at terminal foregroud, and check the stdout. It’s convinient to exclude info from other program.

fthuijs · June 17, 2017, 8:25pm

hi hansome,

I did what you asked in a terminal window connected directly to my openvpn server (to be clear: the ar-150 is not involved in this action in any way).

The output of the openvpn proces is (I anonymized the IP-adres of my openvpn server (X.X.X.X) and some personal details. The rest of the log is untouched.):

Sat Jun 17 14:00:44 2017 OpenVPN 2.4.2 armv6l-unknown-linux-gnueabihf [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Jun 9 2017

Sat Jun 17 14:00:44 2017 library versions: OpenSSL 1.0.1t 3 May 2016, LZO 2.08

Sat Jun 17 14:00:44 2017 Outgoing Control Channel Authentication: Using 160 bit message hash ‘SHA1’ for HMAC authentication

Sat Jun 17 14:00:44 2017 Incoming Control Channel Authentication: Using 160 bit message hash ‘SHA1’ for HMAC authentication

Sat Jun 17 14:00:50 2017 TCP/UDP: Preserving recently used remote address: [AF_INET]X.X.X.X:443

Sat Jun 17 14:00:50 2017 Socket Buffers: R=[163840->163840] S=[163840->163840]

Sat Jun 17 14:00:50 2017 UDP link local: (not bound)

Sat Jun 17 14:00:50 2017 UDP link remote: [AF_INET]X.X.X.X:443

Sat Jun 17 14:00:50 2017 NOTE: UID/GID downgrade will be delayed because of --client, --pull, or --up-delay

Sat Jun 17 14:00:50 2017 TLS: Initial packet from [AF_INET]X.X.X.X:443, sid=876e27c1 bdd046f1

Sat Jun 17 14:00:50 2017 VERIFY OK: depth=1, C=NL, ST=ZH, L=City, O=Private, OU=Private, CN=OpenVPN-CA, name=EasyRSA, emailAddress=me@isp.nl

Sat Jun 17 14:00:50 2017 VERIFY KU OK

Sat Jun 17 14:00:50 2017 Validating certificate extended key usage

Sat Jun 17 14:00:50 2017 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication

Sat Jun 17 14:00:50 2017 VERIFY EKU OK

Sat Jun 17 14:00:50 2017 VERIFY OK: depth=0, C=NL, ST=ZH, L=City, O=Private, OU=Private, CN=server, name=EasyRSA, emailAddress=me@isp.nl

Sat Jun 17 14:00:50 2017 WARNING: ‘link-mtu’ is used inconsistently, local=‘link-mtu 1557’, remote=‘link-mtu 1558’

Sat Jun 17 14:00:50 2017 WARNING: ‘comp-lzo’ is present in remote config but missing in local config, remote=‘comp-lzo’

Sat Jun 17 14:00:50 2017 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA

Sat Jun 17 14:00:50 2017 [server] Peer Connection Initiated with [AF_INET]X.X.X.X:443

Sat Jun 17 14:00:51 2017 SENT CONTROL [server]: ‘PUSH_REQUEST’ (status=1)

Sat Jun 17 14:00:51 2017 PUSH: Received control message: ‘PUSH_REPLY,route 192.168.157.0 255.255.255.0,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 192.168.157.121,compress lz4-v2,route 10.8.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.8.0.22 10.8.0.21,peer-id 0,cipher AES-256-GCM’

Sat Jun 17 14:00:51 2017 OPTIONS IMPORT: timers and/or timeouts modified

Sat Jun 17 14:00:51 2017 OPTIONS IMPORT: compression parms modified

Sat Jun 17 14:00:51 2017 OPTIONS IMPORT: --ifconfig/up options modified

Sat Jun 17 14:00:51 2017 OPTIONS IMPORT: route options modified

Sat Jun 17 14:00:51 2017 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified

Sat Jun 17 14:00:51 2017 OPTIONS IMPORT: peer-id set

Sat Jun 17 14:00:51 2017 OPTIONS IMPORT: adjusting link_mtu to 1624

Sat Jun 17 14:00:51 2017 OPTIONS IMPORT: data channel crypto options modified

Sat Jun 17 14:00:51 2017 Data Channel Encrypt: Cipher ‘AES-256-GCM’ initialized with 256 bit key

Sat Jun 17 14:00:51 2017 Data Channel Decrypt: Cipher ‘AES-256-GCM’ initialized with 256 bit key

Sat Jun 17 14:00:51 2017 ROUTE_GATEWAY 192.168.157.121/255.255.255.0 IFACE=eth0 HWADDR=b8:27:eb:1d:e5:eb

Sat Jun 17 14:00:51 2017 TUN/TAP device tun1 opened

Sat Jun 17 14:00:51 2017 TUN/TAP TX queue length set to 100

Sat Jun 17 14:00:51 2017 do_ifconfig, tt->did_ifconfig_ipv6_setup=0

Sat Jun 17 14:00:51 2017 /sbin/ifconfig tun1 10.8.0.22 pointopoint 10.8.0.21 mtu 1500

Sat Jun 17 14:00:51 2017 /sbin/route add -net X.X.X.X netmask 255.255.255.255 gw 192.168.157.121

Sat Jun 17 14:00:51 2017 /sbin/route add -net 0.0.0.0 netmask 128.0.0.0 gw 10.8.0.21

Sat Jun 17 14:00:51 2017 /sbin/route add -net 128.0.0.0 netmask 128.0.0.0 gw 10.8.0.21

Sat Jun 17 14:00:51 2017 /sbin/route add -net 192.168.157.0 netmask 255.255.255.0 gw 10.8.0.21

P.S. 192.168.157.X is my local network in which also de openvpn server is placed. FYI: at the remote site the ar-150 has IP-adres 192.168.8.1. All netmasks are 255.255.255.0 as far as I know.

I’m curious for your comments…

jp316 · June 18, 2017, 10:28am

I am having the same problem,. it gets to “Initialization Sequence Completed” and then hangs. This is for connection to a private VPN. I went looking at thel ink above (GL.iNet download center) and I don’t see any 2.255 anymore. Looks like 2.26 s there, but I don’t know which version to grab.

So, which should I look at?

glitch · June 18, 2017, 5:34pm

2.26 is newer than 2.257, so try that.

Nobody can help you when you say “I’ve got a problem/the same problem”. Write down exactly what you have done and what you are trying to do.

hansome · June 19, 2017, 11:07am

Hi FThuijs, Hi jp316,

It’s the option “user nobody group nobody” casuing the ERROR. User nobody doesn’t have permisson to change route table.

After some strace I found that route table operation is in child process, ie calling /usr/sbin/ip, and the time fork is not squenced before the time when process’s uid set to nobody. So some route may be added successfully, some failed. And route del operation is always after process’s uid set being nobody, so route del always fail.

Simply remove "“user nobody group nobody” in your ovpn file, it’s fine to run openvpn as root.

fthuijs · June 19, 2017, 2:10pm

Hi hansome,

Thanks for your research! I implemented the user / group option because it’s adviced as a security option.

As this user / group option was allways in my configuration, I think that the flow of starting openvpn changed between firmware version 2.19 and 2.25. I will remove the option so I get ride of the error messages.