Merlin 386.5.2 bug: OpenVPN Server does not start after router restart (scheduled restart, explicit restart, or power reset)

[eibgrad]

Well I'll take a look and see if I can reproduce the problem now that I have a better understanding. But again, if it's a very rare occurrence, that could still be difficult.

In the meantime, it might be prudent to create a simple script that runs on bootup and waits for the OpenVPN server to come online, then force a restart. Presumably that will workaround the issue, if NOT necessarily fix it.

 

[eibgrad]

I created a simple script to automatically restart the OpenVPN servers once they become established.

merlin-ovpn-server-restart.sh - Pastebin.com

Pastebin.com is the number one paste tool since 2002. Pastebin is a website where you can store text online for a set period of time.

pastebin.com

It's only intended as a workaround until the underlying problem can be reproduced and corrected.

Directions for installation are provided in the script.

 

[eibgrad]

I updated the script to v1.1.0. I decided to also check the OpenVPN server "state", just to be sure the server wasn't in some quasi up state, but clearly established.

I still can't reproduce the problem. I've tried pulling the power cord on the router, blocking NTP, rebooting every 5 mins, etc., and it works just fine. I can only assume the problem is most likely caused by a power surge, which makes it effectively unrepeatable for diagnostic purposes.

As mentioned previously, if remote access is critical to your setup, consider using a UPS, esp. if you're using USB drives. Unexpected power loss can corrupt partitions and partition tables too.

 

[David Kremer]

I can reproduce this quite frequently now, just by rebooting the router (by clicking the Reboot button in the UI). It also happens during a power cycle sometimes. I'm on the latest firmware 386.7_2

 

[L&LD]

Sounds like your router is damaged from the power outages.

Or, a full reset to factory defaults is required.

The issues you're stating are not an issue for every other user (at least, not on these forums).

You can try a new power supply to see if it fixes anything.

But a full reset to factory defaults (multiple times and with multiple methods, including reflashing the same firmware you're using now) will be (also) needed to rule out a hardware issue.

 

[ColinTaylor]

I can reproduce this quite frequently now, just by rebooting the router (by clicking the Reboot button in the UI). It also happens during a power cycle sometimes. I'm on the latest firmware 386.7_2

Provide logs from the router and the client showing the failing connection attempt. That will help to pinpoint the problem.

 

[Smokey613]

As mentioned previously, if remote access is critical to your setup, consider using a UPS, esp. if you're using USB drives. Unexpected power loss can corrupt partitions and partition tables too.

You are correct about a UPS.

IMHO, a UPS should be considered mandatory on all networking equipment. I have UPS units on all my electronics with the exceptions of some IoT devices.

 

[David Kremer]

Provide logs from the router and the client showing the failing connection attempt. That will help to pinpoint the problem.

How do I obtain server logs? I can ssh in and get them from a system file, or I can get them from the UI, thanks for any advice.

 

[ColinTaylor]

How do I obtain server logs? I can ssh in and get them from a system file, or I can get them from the UI, thanks for any advice.

The OpenVPN server logs to the general system log which you can view and save from System Log - General Log. Or you can copy them directly from the files at /tmp/syslog.log and /tmp/syslog.log-1. The client's log should be available within whatever application you're using.

 

[David Kremer]

It keeps happening. Due to many power outages in my area, I'm always forced to log in after every power outage, turn off the VPN, and turn on the VPN again. I wonder if the stock firmware (non-Merlin) has this bug too? I'd gladly switch just to avoid this bug.

This is what the client side log says (Viscosity) while it fails to connect to the VPN server:

2022-10-20 18:57:11: SIGUSR1[connection failed(soft), init_instance] received, process restarting
2022-10-20 18:57:11: Valid endpoint found: X.X.X.X:1194: tcp-client
2022-10-20 18:57:11: TCP/UP: Preserving recently used remote address: [AF_INET]X.X.X.X:1194
2022-10-20 18:57:11: Attempting to establish TCP connection with [AF_INET]X.X.X.X:1194 [nonblock]
2022-10-20 18:58:33: TCP: connect to [AF_INET]X.X.X.X:1194 failed: Operation timed out
2022-10-20 18:58:33: SIGUSR1[connection failed(soft), init_instance] received, process restarting
2022-10-20 18:58:33: Valid endpoint found: X.X.X.X:1194:tcp-client
2022-10-20 18:58:33: TCP/UP: Preserving recently used remote address: [AF_INET]X.X.X.X:1194
2022-10-20 18:58:33: Attempting to establish TCP connection with [AF_INET]X.X.X.X:1194 [nonblock]

 

[ColinTaylor]

This is what the client side log says (Viscosity) while it fails to connect to the VPN server:

What does the server side log say?

 

[David Kremer]

What does the server side log say?

I realize I should have sent this, but by the time I checked the log was wiped. I'll provide this next time it happens. I assume /tmp/syslog.log is the log on the router.

 

[ColinTaylor]

I realize I should have sent this, but by the time I checked the log was wiped.

It shouldn't be wiped unless you manually did it through the GUI or did a hard factory reset. The system log files are periodically copied to jffs so that they are preserved and restored over a reboot.

I assume /tmp/syslog.log is the log on the router.

Correct. The previous log (if it's rolled over) is /tmp/syslog.log-1.

 

[David Kremer]

It shouldn't be wiped unless you manually did it through the GUI or did a hard factory reset. The system log files are periodically copied to jffs so that they are preserved and restored over a reboot.


Correct. The previous log (if it's rolled over) is /tmp/syslog.log-1.

There's nothing of interest in the /tmp/syslog.log other than these lines:

May 5 01:02:31 dnsmasq-dhcp[412]: DHCPOFFER(br0) 192.168.2.77 00:5d:59:b3:74:75
May 5 01:02:32 dnsmasq-dhcp[412]: DHCPDISCOVER(br0) 00:5d:59:b3:74:75
May 5 01:10:49 miniupnpd[1726]: SoapMethod: Unknown: GetPortMappingNumberOfEntries urn:schemas-upnp-org:service:WANIPConnection:1
May 5 01:38:32 syslog: wlceventd_proc_event(491): eth1: Deauth_ind 3C:1D:66A:BC:7C, status: 0, reason: Disassociated due to inactivity (4), rssi:0
May 5 01:38:32 syslog: wlceventd_proc_event(508): eth1: Disassoc 3C:1D:66A:BC:7C, status: 0, reason: Disassociated because sending station is leaving (or has left) BSS (8), rssi:0
May 5 02:01:40 syslog: wlceventd_proc_event(527): eth1: Auth 4C:1D:36A:BC:7C, status: Successful (0), rssi:0
May 5 02:01:40 syslog: wlceventd_proc_event(556): eth1: Assoc 4C:1D:36A:BC:7C, status: Successful (0), rssi:0

The VPN client cannot connect until the VPN is manually turned off on the router and then turned on again. Note how when the router reboots it thinks the date today is May 5, 2018.

 

[David Kremer]

When I turned off the VPN and on again, it worked. Here's what happened in the log:

May 5 07:26:06 rc_service: httpds 421:notify_rc stop_vpnserver1
...
May 5 07:26:48 rc_service: httpds 421:notify_rc restart_chpass;restart_vpnserver1
...
May 5 07:26:51 ovpn-server1[6635]: ovpn-up 1 server tun21 1500 1624 10.8.0.1 255.255.255.0 init

 

[ColinTaylor]

Note how when the router reboots it thinks the date today is May 5, 2018.

That's normal initially. After the router connects to the internet it should update the time via NTP. If it doesn't correct the time this will cause problems, especially for things that rely on having the correct time like VPNs.

Upload the complete unedited syslog to pastebin.com and provide a link to it for us to looks at. Seeing all the messages in context is important. Knowing what messages are not there is as important as those that are.

 

[truglodite]

I'm curious about this one, because I recently experienced 2 power outages in a row where I lost openvpn access. One of the times I was away from home, had my daughter power off/on the router with the switch, and the server started working again. Not sure if it has to do with my ISP's gateway device... I have fiber in home, and the fiber gateway powered down in both instances. I'm also using ntpmerlin and unbound for dns.

This was with a ups, with a 24hr and a 72hr outage.

 

[David Kremer]

That's normal initially. After the router connects to the internet it should update the time via NTP. If it doesn't correct the time this will cause problems, especially for things that rely on having the correct time like VPNs.

Upload the complete unedited syslog to pastebin.com and provide a link to it for us to looks at. Seeing all the messages in context is important. Knowing what messages are not there is as important as those that are.

It happened again. Power outage and router restart with VPN disalbed (even though it says OpenVPN Server ON in the Merlin GUI). The only fix is to turn it OFF and ON again. This time I have all the logs, /tmp/syslog.log and /tmp/syslog.log-1. Can I private message them to you? Not sure if logs expose anything sensitive.

 

[ColinTaylor]

It happened again. Power outage and router restart with VPN disalbed (even though it says OpenVPN Server ON in the Merlin GUI). The only fix is to turn it OFF and ON again. This time I have all the logs, /tmp/syslog.log and /tmp/syslog.log-1. Can I private message them to you? Not sure if logs expose anything sensitive.

Yes, send them via a private message or a password protected pastebin.com link.

 

[David Kremer]

Yes, send them via a private message or a password protected pastebin.com link.

Ok just did