Openvpn: Server2 not starting up on reboot...

[truglodite]

I am not sure if this has anything to do with my change from tls-auth to tls-crypt, or configuring openvpn and the webgui with custom certs... but my router refuses to automatically start openvpn server instance 2 after reboot. I have to log in to the webgui, and "apply" advanced settings of server2 for it to work after reboot. Everything else is working as it is supposed to: n66u, 380_67, absolution-sh (3.9)... and I've got dnssec enabled. Not sure what else to add to this... maybe logs after reboot (server2 frozen on "applying config")... and logs after applying server2 advanced settings (gets server2 going):

After reboot (server2 isn't started... line5 looks interesting):

Jul 27 20:52:04 rc_service: ntp 868:notify_rc restart_upnp
Jul 27 20:52:04 rc_service: waitting "start_vpnserver1" via udhcpc ...
Jul 27 20:52:12 kernel: tun: Universal TUN/TAP device driver, 1.6
Jul 27 20:52:12 kernel: tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
Jul 27 20:52:13 rc_service: skip the event: start_vpnserver2.
Jul 27 20:52:13 kernel: device tun21 entered promiscuous mode
Jul 27 20:52:13 openvpn-routing: Refreshing policy rules for client 1
Jul 27 20:52:14 openvpn-routing: Allow WAN access to all VPN clients
Jul 27 20:52:14 openvpn-routing: Refreshing policy rules for client 2
Jul 27 20:52:14 openvpn-routing: Allow WAN access to all VPN clients
Jul 27 20:52:14 openvpn-routing: Refreshing policy rules for client 3
Jul 27 20:52:14 openvpn-routing: Allow WAN access to all VPN clients
Jul 27 20:52:14 openvpn-routing: Refreshing policy rules for client 4
Jul 27 20:52:14 openvpn-routing: Allow WAN access to all VPN clients
Jul 27 20:52:14 openvpn-routing: Refreshing policy rules for client 5
Jul 27 20:52:14 openvpn-routing: Allow WAN access to all VPN clients
Jul 27 20:52:14 ddns_update: ez-ipupdate: starting...
Jul 27 20:52:15 ddns_update: connected to nwsrv-ns1.asus.com (103.10.4.108) on port 80.
Jul 27 20:52:15 ddns_update: Asus update entry:: return: HTTP/1.1 200 OK^M Date: Fri, 28 Jul 2017 03:52:14 GMT^M Server: Apache^M X-Powered-By: PHP/5.6.30^M Content-Length: 0^M Connection: close^M Content-Type: text/html; charset=UTF-8^M ^M
Jul 27 20:52:15 ddns_update: retval= 0, ddns_return_code (,200)
Jul 27 20:52:15 ddns_update: asusddns_update: 0
Jul 27 20:52:15 ddns: ddns update ok
Jul 27 20:52:15 dhcp_client: bound XXX.XXX.XXX.XXX via XXX.XXX.XXX.XXX during 259200 seconds.
Jul 27 20:52:20 openvpn[1022]: OpenVPN 2.4.3 mipsel-unknown-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Jul 16 2017
Jul 27 20:52:20 openvpn[1022]: library versions: OpenSSL 1.0.2l  25 May 2017, LZO 2.08
Jul 27 20:52:20 openvpn[1024]: PLUGIN_INIT: POST /usr/lib/openvpn-plugin-auth-pam.so '[/usr/lib/openvpn-plugin-auth-pam.so] [openvpn]' intercepted=PLUGIN_AUTH_USER_PASS_VERIFY
Jul 27 20:52:20 openvpn[1024]: Diffie-Hellman initialized with 4096 bit key
Jul 27 20:52:20 openvpn[1024]: Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 27 20:52:20 openvpn[1024]: Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 27 20:52:20 openvpn[1024]: Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 27 20:52:20 openvpn[1024]: Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 27 20:52:21 rc_service: ntp 868:notify_rc restart_diskmon
Jul 27 20:52:21 disk_monitor: Finish
Jul 27 20:52:21 disk_monitor: be idle
Jul 27 20:52:23 crond[295]: time disparity of 1047112 minutes detected
Jul 27 20:52:35 openvpn[1024]: TUN/TAP device tun21 opened
Jul 27 20:52:35 openvpn[1024]: TUN/TAP TX queue length set to 100
Jul 27 20:52:35 openvpn[1024]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Jul 27 20:52:35 openvpn[1024]: /usr/sbin/ip link set dev tun21 up mtu 1500
Jul 27 20:52:35 openvpn[1024]: /usr/sbin/ip addr add dev tun21 10.8.0.X/24 broadcast 10.8.0.255
Jul 27 20:52:35 openvpn[1024]: Could not determine IPv4/IPv6 protocol. Using AF_INET
Jul 27 20:52:35 openvpn[1024]: Socket Buffers: R=[87380->87380] S=[16384->16384]
Jul 27 20:52:35 openvpn[1024]: Listening for incoming TCP connection on [AF_INET]XXX.XXX.XXX.XXX:443
Jul 27 20:52:35 openvpn[1024]: TCPv4_SERVER link local (bound): [AF_INET]XXX.XXX.XXX.XXX:443
Jul 27 20:52:35 openvpn[1024]: TCPv4_SERVER link remote: [AF_UNSPEC]

Then, after "applying" server2 advanced settings (the server is now started):

Jul 27 20:55:41 rc_service: httpds 293:notify_rc restart_chpass;restart_vpnserver2
Jul 27 20:55:43 kernel: device tun22 entered promiscuous mode
Jul 27 20:55:47 openvpn[1295]: OpenVPN 2.4.3 mipsel-unknown-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Jul 16 2017
Jul 27 20:55:47 openvpn[1295]: library versions: OpenSSL 1.0.2l  25 May 2017, LZO 2.08
Jul 27 20:55:47 openvpn[1297]: PLUGIN_INIT: POST /usr/lib/openvpn-plugin-auth-pam.so '[/usr/lib/openvpn-plugin-auth-pam.so] [openvpn]' intercepted=PLUGIN_AUTH_USER_PASS_VERIFY
Jul 27 20:55:47 openvpn[1297]: Diffie-Hellman initialized with 4096 bit key
Jul 27 20:55:47 openvpn[1297]: Outgoing Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 27 20:55:47 openvpn[1297]: Outgoing Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 27 20:55:47 openvpn[1297]: Incoming Control Channel Encryption: Cipher 'AES-256-CTR' initialized with 256 bit key
Jul 27 20:55:47 openvpn[1297]: Incoming Control Channel Encryption: Using 256 bit message hash 'SHA256' for HMAC authentication
Jul 27 20:55:47 openvpn[1297]: TUN/TAP device tun22 opened
Jul 27 20:55:47 openvpn[1297]: TUN/TAP TX queue length set to 100
Jul 27 20:55:47 openvpn[1297]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Jul 27 20:55:47 openvpn[1297]: /usr/sbin/ip link set dev tun22 up mtu 1500
Jul 27 20:55:47 openvpn[1297]: /usr/sbin/ip addr add dev tun22 XXX.XXX.XXX.XXX/24 broadcast 10.16.0.255
Jul 27 20:55:47 openvpn[1297]: Could not determine IPv4/IPv6 protocol. Using AF_INET
Jul 27 20:55:47 openvpn[1297]: Socket Buffers: R=[118784->118784] S=[118784->118784]
Jul 27 20:55:47 openvpn[1297]: UDPv4 link local (bound): [AF_INET]XXX.XXX.XXX.XXX:1194
Jul 27 20:55:47 openvpn[1297]: UDPv4 link remote: [AF_UNSPEC]
Jul 27 20:55:47 openvpn[1297]: MULTI: multi_init called, r=256 v=256
Jul 27 20:55:47 openvpn[1297]: IFCONFIG POOL: base=XXX.XXX.XXX.XXX size=252, ipv6=0
Jul 27 20:55:47 openvpn[1297]: Initialization Sequence Completed

Any ideas if I'm doing something wrong with my config, or something else (perhaps bug with tls-crypt implementation)?

Fortunately it's not the end of the world... if I'm away from my house and the power goes down (router reset), I can still access through server1. However it's quite annoying when I discover server2 down... and I figure I'll learn something if I can fix it.

Thanks,
Kevin

 

[RMerlin]

This usually means that vpnserver1 took too long to start.

And now that Asus has moved the rc_service code into a closed source blob, I can't adjust wait timers anymore (I used to allow more time than Asus).

I'm getting fed up with this closed source non-sense. Two new features appeared in a recent 382 GPL, and both of these are also closed source now.

Quick listing of stuff that is now closed source in 382 (beside the obvious BWDPI/Tuxera/Broadcom stuff):

- Networkmap
- OpenVPN
- JFFS backup
- Let's Encrypt
- httpd's MIME handler
- rc notification functions
- Notification Center
- AiCloud sync clients (FTP/dropbox/etc...)
- Printer server
- Protection Service


This is going to ultimately kill this project.

 

[LouisvilleUK]

This is going to ultimately kill this project.

Sad, sad day when this happens.

 

[ASadani]

I would hope the project still remains alive with 380.66 and updates to it. Most of us won't update further s the current firmware gives all that is needed at least for me. The individual binaries can live to the new versions as a fork. I hope so. I just got introduced to this and I read this news. Sad

 

[truglodite]

Gah, would ringing the Asus bell help? I was planning on spending extra for Asus this year (north of $200) just to stay with Merlin. Not sure why they're closing up the code, but if they kill this off I will donate the router savings to RMerlin as a thanks for the good times. I hope that never happens... dd-wrt is a lot more work for what I'm doing.

That said, I guess this means there is no way to fix my problem? I was hoping I could use a script to try and restart server2 some time after reboot is done. I don't mind doing homework/experimenting if there is a way... Just need to get pointed the right direction.

Kevin

Ps... Merlin I still owe you a case of beverage.

 

[RMerlin]

That said, I guess this means there is no way to fix my problem?

I could try putting a delay between launch of each server instances at boot time to at least reduce the risk of such an issue occurring. Not sure it will help in your particular case tho. You seem to have multiple services having trouble to start at the same time, might be caused by the additional services you have enabled that are also being started at the same time.

 

[sfx2000]

Quick listing of stuff that is now closed source in 382 (beside the obvious BWDPI/Tuxera/Broadcom stuff):

- Networkmap
- OpenVPN
- JFFS backup
- Let's Encrypt
- httpd's MIME handler
- rc notification functions
- Notification Center
- AiCloud sync clients (FTP/dropbox/etc...)
- Printer server
- Protection Service

This is going to ultimately kill this project.

There's a couple of items there - closing source might get them into trouble, not all of it is GPL... I can understand why Asus is starting to lock down things, but still.

Moving walkway is nearing it's end - it's not because of the committed folks in the 3rd party community that support the product - Asus has a big sword over their head as a result of certain actions in the US...

 

[truglodite]

I was trying to post the preceding part of that reboot syslog in it's entirety, but cloudflare is blocking it.

So here are a few clippings that my inexperienced eyes thought may be of interest. There are a few longer pauses:

00:08 stop_nat_rules: apply the redirect_rules!
00:08 dropbear[274]: Running in background
00:08 WAN_Connection: ISP's DHCP did not function properly.
00:13 custom_config: Appending content of /jffs/configs/dnsmasq.conf.add.
00:13 custom_script: Running /jffs/scripts/dnsmasq.postconf (args: /etc/dnsmasq.conf)

00:32 rc_service: udhcpc 605:notify_rc start_upnp
00:32 rc_service: waitting "stop_upnp" via udhcpc ...
00:33 rc_service: udhcpc 605:notify_rc start_vpnserver1
00:33 rc_service: waitting "start_upnp" via udhcpc ...
00:33 ntp: start NTP update
00:34 rc_service: udhcpc 605:notify_rc start_vpnserver2
00:34 rc_service: waitting "start_vpnserver1" via udhcpc ...
00:35 WAN_Connection: WAN was restored.
52:04 rc_service: ntp 868:notify_rc restart_upnp
52:04 rc_service: waitting "start_vpnserver1" via udhcpc ...
52:12 kernel: tun: Universal TUN/TAP device driver, 1.6
52:12 kernel: tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
52:13 rc_service: skip the event: start_vpnserver2.

...the latter portion of this reboot syslog is already posted above.

The time jump is I think due to the ntp update after wan is restored, then about an 8sec pause as server1 is started. Not sure if it would help, if you plan on adding a delay for this.

Kev

 

[john9527]

@RMerlin
The start of the vpn servers/clients at boot waits for 10 sec by default to see if the time is sync'd before giving up and doing the start. On my fork, I raised that to 60 sec. It may help out here.
https://github.com/john9527/asuswrt-merlin/commit/77267abd56db1a8900c351e31697602c24546d2b

 

[RMerlin]

There's a couple of items there - closing source might get them into trouble, not all of it is GPL...

All that code I listed was written by them (AFAIK), so they control what licence they wish to apply to it.

 

[RMerlin]

@RMerlin
The start of the vpn servers/clients at boot waits for 10 sec by default to see if the time is sync'd before giving up and doing the start. On my fork, I raised that to 60 sec. It may help out here.
https://github.com/john9527/asuswrt-merlin/commit/77267abd56db1a8900c351e31697602c24546d2b

Not sure if it will fix this particular issue, but that code portion is worth having another look at. 60 secs seems a bit long tho, as it means that any queued rc event would expire long before that, causing events to be missed.

 

[john9527]

Not sure if it will fix this particular issue, but that code portion is worth having another look at. 60 secs seems a bit long tho, as it means that any queued rc event would expire long before that, causing events to be missed.

There can be no queued event for vpn....it's the eas start at boot. So it also gives time for any other services to get started. In fact, I made it even longer later to account for additional delays I saw if you are running dual wan with a vpn active.

EDIT: As I think more about this (with some additional learning since then)....it should probably wait forever for the time to sync, since trying to start openvpn with a non-sync'd time is an exercise in futility with the certificate validation sure to fail.

 

[RMerlin]

There can be no queued event for vpn...

I was thinking about this:

00:34 rc_service: waitting "start_vpnserver1" via udhcpc ...

 

[RMerlin]

One problem that might be specific to my firmware tho: that code currently checks for , January 1, 2012 12:00:00 AM. However, my RT-AC88U starts its clock at January 1st 2015, which means this portion of code isn't working at all for me. That might explain quite a few time-related issues.

 

[john9527]

I was thinking about this:

00:34 rc_service: waitting "start_vpnserver1" via udhcpc ...

That's actually a bit misleading.....
udhcpc calls wan_up which calls start_vpn_eas (where my patch is)

 

[RMerlin]

That's actually a bit misleading.....
udhcpc calls wan_up which calls start_vpn_eas (where my patch is)

That's the calling process name getting reported.

Anyway, I fixed the completely broken time check code this afternoon, and also made it wait quite a bit longer. Might not fix every corner cases, but it will definitely take care of some of these.