Menu
What's new
By:
Filters Better Search

vpnclient1 up / down scripts (openvpn) ac86u help needed

  • SNBForums Code of Conduct

    SNBForums is a community for everyone, no matter what their level of experience.

    Please be tolerant and patient of others, especially newcomers. We are all here to share and learn!

    The rules are simple: Be patient, be nice, be helpful or be gone!

Butterfly Bones said:
Thanks, I've updated and went back through all scripts carefully. I see no indication anywhere that VPN_Failover.sh is running on my router, htop, ps grep, like I can if run via cron or from command line.
Click to expand...

What happens if you execute the openvpn-event trigger script manually:
Code: 
./vpnclient1-route-up
 
Martineau said:
What happens if you execute the openvpn-event trigger script manually:
Code: 
./vpnclient1-route-up
Click to expand...
This shows in red using x-term ssh into router.
Code: 
@RT-AC86U-4608:/jffs/scripts# ./vpnclient1-route-up
    **ERROR** VPN Client '' is INVALID (1-5 only)
Here are the contents of vpnclient1-route-up
Code: 
#!/bin/sh
VPN_ID=${dev:4:1}
sh /jffs/scripts/VPN_Failover.sh "$VPN_ID" "delay=60"
Code: 
@RT-AC86U-4608:/jffs/scripts# ls -al vpnclient1-route-up
-rwxr-xr-x    1 [redact] root            84 May  9 15:42 vpnclient1-route-up
I tried with 1.15 from the command line, no errors displayed and ps grep shows it as expected. I ran killall "pid" before I did the CLI test.
Code: 
@RT-AC86U-4608:/tmp/home/root# ps | grep VPN_Failover.sh
17730 [redact]  3364 S    sh /jffs/scripts/VPN_Failover.sh 1
 
Butterfly Bones said:
Here are the contents of vpnclient1-route-up
Code: 
#!/bin/sh
VPN_ID=${dev:4:1}
sh /jffs/scripts/VPN_Failover.sh "$VPN_ID" "delay=60"
Click to expand...
In post #1 you correctly included the "&" character at the end of the VPN Failover monitor request:rolleyes:

I suggest you copy'n'paste the following to see if this now correctly allows 'vpnclient1-route-up' to start the background script
Code: 
/jffs/scripts/VPN_Failover.sh   "$VPN_ID"   "delay=60"   &
 
After reviewing the code, my current design decision for 384.12 is to have two scripts (updown-client.sh and updown-server.sh) in the firmware. The server-specific code (which wasn't used anyway) will be removed from the client version, and the server version will only handle launching the openvpn-event script (if it exists), and also logging doing so (which is an improvement over the current design where calls to that custom script weren't logged). This will also allow users to create an openvpn-event script even after a server was started, as the updown directive will always be there in the server config.

The reason why updown was not previously used by clients set to authorize through a secret key instead of TLS is because in secret key mode, the client does not pull parameters from the server. Since the updown.sh primary responsibility was to handle pushed DNS/WINS/domain info, there wasn't anything to do, hence the script wasn't used at all.

openvpn-event script not being fired when DNS mode was set to ignore was just a bug - the check done for openvpn-event took into account the auth mode, but not the dns mode. Moving that check into the script itself will help better handle things in the future.
 
Martineau said:
In post #1 you correctly included the "&" character at the end of the VPN Failover monitor request:rolleyes:

I suggest you copy'n'paste the following to see if this now correctly allows 'vpnclient1-route-up' to start the background script
Code: 
/jffs/scripts/VPN_Failover.sh   "$VPN_ID"   "delay=60"   &
Click to expand...
Copy error when posting here. Just checked and ran ./vpnclient1-route-up again.
Code: 
@RT-AC86U-4608:/jffs/scripts# cat vpnclient1-route-up
#!/bin/sh
VPN_ID=${dev:4:1}
/jffs/scripts/VPN_Failover.sh "$VPN_ID" "delay=60" &
Code: 
@RT-AC86U-4608:/jffs/scripts#
@RT-AC86U-4608:/jffs/scripts# ./vpnclient1-route-up
    **ERROR** VPN Client '' is INVALID (1-5 only)
 
Last edited:
RMerlin said:
After reviewing the code, my current design decision for 384.12 is to have two scripts (updown-client.sh and updown-server.sh) in the firmware. The server-specific code (which wasn't used anyway) will be removed from the client version, and the server version will only handle launching the openvpn-event script (if it exists), and also logging doing so (which is an improvement over the current design where calls to that custom script weren't logged). This will also allow users to create an openvpn-event script even after a server was started, as the updown directive will always be there in the server config.

The reason why updown was not previously used by clients set to authorize through a secret key instead of TLS is because in secret key mode, the client does not pull parameters from the server. Since the updown.sh primary responsibility was to handle pushed DNS/WINS/domain info, there wasn't anything to do, hence the script wasn't used at all.

openvpn-event script not being fired when DNS mode was set to ignore was just a bug - the check done for openvpn-event took into account the auth mode, but not the dns mode. Moving that check into the script itself will help better handle things in the future.
Click to expand...

Sounds great! Thanks for taking the time to look into this problem.
 
Butterfly Bones said:
Code: 
@RT-AC86U-4608:/jffs/scripts# ./vpnclient1-route-up
    **ERROR** VPN Client '' is INVALID (1-5 only)
Click to expand...

Invoking the above from the command line will always generate the error as you are not running within the OpenVPN environment, hence the OpenVPN '$dev' environment variable doesn't exist, but all we are tesing is that the script is physically executing 'VPN_Failover.sh'

Did you try starting VPN Client 1, and check Syslog for messages?

Perhaps it may be prudent to include the following in 'vpnclient1-route-up'
Code: 
logger -st "($(basename $0))" "Requesting VPN_Failover monitor....."

Now you should be able to scan Syslog for proof that 'vpnclient1-route-up' is executing
Code: 
grep "VPN_Failover" /opt/var/messages
and there should be messages from 'VPN_Failover.sh'
 
Martineau said:
Invoking the above from the command line will always generate the error as you are not running within the OpenVPN environment, hence the OpenVPN '$dev' environment variable doesn't exist, but all we are tesing is that the script is physically executing 'VPN_Failover.sh'

Did you try starting VPN Client 1, and check Syslog for messages?

Perhaps it may be prudent to include the following in 'vpnclient1-route-up'
Code: 
logger -st "($(basename $0))" "Requesting VPN_Failover monitor....."

Now you should be able to scan Syslog for proof that 'vpnclient1-route-up' is executing
Code: 
grep "VPN_Failover" /opt/var/messages
and there should be messages from 'VPN_Failover.sh'
Click to expand...
I added the logger line before and ran it.
Code: 
#!/bin/sh
logger -st "($(basename $0))" "Requesting VPN_Failover monitor....."
VPN_ID=${dev:4:1}
/jffs/scripts/VPN_Failover.sh "$VPN_ID" "delay=60" &
Then I moved logger line after and ran it again.
Code: 
#!/bin/sh
VPN_ID=${dev:4:1}
/jffs/scripts/VPN_Failover.sh "$VPN_ID" "delay=60" &
logger -st "($(basename $0))" "Requesting VPN_Failover monitor....."
Got this both times. Remember I run syslog-ng so all messages to go /opt/var/log/messages (symlinked back to /tmp/syslog.log so it shows in webgui) or /opt/var/log/openvpn/log

In router SSH x-term
Code: 
xxxxxxx@RT-AC86U-4608:/tmp/home/root# grep "VPN_Failover" /opt/var/messages
grep: /opt/var/messages: No such file or directory

xxxxxxx@RT-AC86U-4608:/tmp/home/root# grep "VPN_Failover" /opt/var/log/messages
xxxxxxx@RT-AC86U-4608:/tmp/home/root#

xxxxxxx@RT-AC86U-4608:/tmp/home/root# grep "VPN_Failover" /opt/var/log/openvpn.log
xxxxxxx@RT-AC86U-4608:/tmp/home/root#

xxxxxxx@RT-AC86U-4608:/tmp/home/root# grep "VPN_Failover" /tmp/syslog.log
xxxxxxx@RT-AC86U-4608:/tmp/home/root#
This is the only vpn related line I see running ps with no switches in a terminal.
Code: 
22605 xxxxxxx  6756 S    /etc/openvpn/vpnclient1 --cd /etc/openvpn/client1 --config config.ovpn
 
Butterfly Bones said:
I added the logger line before and ran it.
Code: 
#!/bin/sh
logger -st "($(basename $0))" "Requesting VPN_Failover monitor....."
VPN_ID=${dev:4:1}
/jffs/scripts/VPN_Failover.sh "$VPN_ID" "delay=60" &
Then I moved logger line after and ran it again.
Code: 
#!/bin/sh
VPN_ID=${dev:4:1}
/jffs/scripts/VPN_Failover.sh "$VPN_ID" "delay=60" &
logger -st "($(basename $0))" "Requesting VPN_Failover monitor....."
Got this both times. Remember I run syslog-ng so all messages to go /opt/var/log/messages (symlinked back to /tmp/syslog.log so it shows in webgui) or /opt/var/log/openvpn/log
Click to expand...

OK it's late so one final attempt.

Start VPN Client 1...........then scan whatever file you have mangled for Syslog for either of two strings.
e.g. if using syslog-ng without filters
Code: 
grep -E "VPN_Failover|vpnclient1" /opt/var/log/messages
Several lines must be extracted and displayed

If you can provide the redacted portion of the complete Syslog between
Code: 
rc_service: service xxxxx:notify_rc start_vpnclient1
to
Code: 
ovpn-client1[xxxxx]: Initialization Sequence Completed
then this may help others to assist.

I'm out of ideas.
 
Martineau said:
OK it's late so one final attempt.

Start VPN Client 1...........then scan whatever file you have mangled for Syslog for either of two strings.
e.g. if using syslog-ng without filters
Code: 
grep -E "VPN_Failover|vpnclient1" /opt/var/log/messages
Several lines must be extracted and displayed

If you can provide the redacted portion of the complete Syslog between
Code: 
rc_service: service xxxxx:notify_rc start_vpnclient1
to
Code: 
ovpn-client1[xxxxx]: Initialization Sequence Completed
then this may help others to assist.

I'm out of ideas.
Click to expand...
Thanks for the attempts to solve this, I do appreciate it. I decided to remove the syslog-ng for now so I know where all messages go, webgui and /tmp/syslog.log.

After a reboot without vpn configured to start it boot, here is all I see.
Code: 
May 10 16:45:13 rc_service: httpds xxx:notify_rc start_vpnclient1
May 10 16:45:13 custom_script: Running /jffs/scripts/service-event (args: start vpnclient1)
May 10 16:45:13 kernel: tun: Universal TUN/TAP device driver, 1.6
May 10 16:45:13 kernel: tun: (C) 1999-2004 Max Krasnyansky <maxk@qualcomm.com>
May 10 16:45:13 ovpn-client1[xxxx]: OpenVPN 2.4.7 arm-buildroot-linux-gnueabi [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on May  8 2019
May 10 16:45:13 ovpn-client1[xxxx]: library versions: OpenSSL 1.1.1b  26 Feb 2019, LZO 2.08
May 10 16:45:13 ovpn-client1[xxxx]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
May 10 16:45:14 ovpn-client1[xxxx]: TCP/UDP: Preserving recently used remote address: [AF_INET]xxx.xxx.xxx.xxx:1194
May 10 16:45:14 ovpn-client1[xxxx]: Socket Buffers: R=[524288->1048576] S=[524288->1048576]
May 10 16:45:14 ovpn-client1[xxxx]: UDP link local: (not bound)
May 10 16:45:14 ovpn-client1[xxxx]: UDP link remote: [AF_INET]xxx.xxx.xxx.xxx:1194
May 10 16:45:14 ovpn-client1[xxxx]: TLS: Initial packet from [AF_INET]xxx.xxx.xxx.xxx:1194, sid=12aad7ae c36ddb7f
May 10 16:45:14 ovpn-client1[xxxx]: VERIFY OK: depth=1, C=US, ST=NY, L=New York, O=Simplex Solutions Inc., OU=Vpn Unlimited, CN=server.[vpn_provider_name.com, name=server.[vpn_provider_name.com, emailAddress=support@xxxxxxxxxx.com
May 10 16:45:14 ovpn-client1[xxxx]: VERIFY KU OK
May 10 16:45:14 ovpn-client1[xxxx]: Validating certificate extended key usage
May 10 16:45:14 ovpn-client1[xxxx]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
May 10 16:45:14 ovpn-client1[xxxx]: VERIFY EKU OK
May 10 16:45:14 ovpn-client1[xxxx]: VERIFY OK: depth=0, CN=openvpn2.[vpn_provider_name.com
May 10 16:45:14 ovpn-client1[xxxx]: Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 4096 bit RSA
May 10 16:45:14 ovpn-client1[xxxx]: [openvpn2.[vpn_provider_name.com] Peer Connection Initiated with [AF_INET]107.170.205.243:1194
May 10 16:45:15 ovpn-client1[xxxx]: SENT CONTROL [openvpn2.[vpn_provider_name.com]: 'PUSH_REQUEST' (status=1)
May 10 16:45:20 ovpn-client1[xxxx]: SENT CONTROL [openvpn2.[vpn_provider_name.com]: 'PUSH_REQUEST' (status=1)
May 10 16:45:20 ovpn-client1[xxxx]: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS xx.xxx.xx.x,rcvbuf 262144,sndbuf 262144,comp-lzo no,ping 5,ping-exit 30,route ,topology net30,ifconfig xx.xxx.xx.xx xx.xxx.xx.xx,peer-id 7,cipher AES-256-GCM'
May 10 16:45:20 ovpn-client1[xxxx]: OPTIONS IMPORT: timers and/or timeouts modified
May 10 16:45:20 ovpn-client1[xxxx]: OPTIONS IMPORT: compression parms modified
May 10 16:45:20 ovpn-client1[xxxx]: OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
May 10 16:45:20 ovpn-client1[xxxx]: Socket Buffers: R=[1048576->524288] S=[1048576->524288]
May 10 16:45:20 ovpn-client1[xxxx]: OPTIONS IMPORT: --ifconfig/up options modified
May 10 16:45:20 ovpn-client1[xxxx]: OPTIONS IMPORT: route options modified
May 10 16:45:20 ovpn-client1[xxxx]: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
May 10 16:45:20 ovpn-client1[xxxx]: OPTIONS IMPORT: peer-id set
May 10 16:45:20 ovpn-client1[xxxx]: OPTIONS IMPORT: adjusting link_mtu to 1625
May 10 16:45:20 ovpn-client1[xxxx]: OPTIONS IMPORT: data channel crypto options modified
May 10 16:45:20 ovpn-client1[xxxx]: Data Channel: using negotiated cipher 'AES-256-GCM'
May 10 16:45:20 ovpn-client1[xxxx]: Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 10 16:45:20 ovpn-client1[xxxx]: Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 10 16:45:20 ovpn-client1[xxxx]: TUN/TAP device tun11 opened
May 10 16:45:20 ovpn-client1[xxxx]: TUN/TAP TX queue length set to 1000
May 10 16:45:20 ovpn-client1[xxxx]: /bin/ip link set dev tun11 up mtu 1500
May 10 16:45:20 ovpn-client1[xxxx]: /bin/ip addr add dev tun11 local xxx.xx.x.xx peer xxx.xx.x.xx
May 10 16:45:22 openvpn-routing: Configuring policy rules for client 1
May 10 16:45:22 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 xxx.xx.x.xx xxx.xx.x.xx)
May 10 16:45:22 openvpn-event[6748]:      Script executing.. for VPN event: vpnclient1-route-up
May 10 16:45:22 ovpn-client1[xxxx]: Initialization Sequence Completed
 
Butterfly Bones said:
Code: 
May 10 16:45:22 openvpn-event[6748]:      Script executing.. for VPN event: vpnclient1-route-up
May 10 16:45:22 ovpn-client1[xxxx]: Initialization Sequence Completed
Click to expand...
So Syslog shows that script 'openvpn-event' ran, and issued the message saying it was requesting the execution of 'vpnclient1-route-up'.

However, assuming 'vpnclient1-route-up' actually contains the Syslog 'logger -t' directive, there is no evidence in Syslog that the 'vpnclient1-route-up' script actually ran.

So create a verbose debugging version of the 'openvpn-event' script

i.e. Insert the following two lines after the '#!/bin/sh' line
Code: 
set -x
(
and append the following line to the end of the script
Code: 
) 2>&1 | logger -st $(basename $0)"[$$_***DEBUG]"
Also perform the above for the 'vpnclient1-route-up' script

Again we need to verify that 'vpnclient1-route-up' is capable of requesting 'VPN_Failover.sh' - manually issue
Code: 
./vpnclient1-route-up
Hopefully you should see the verbose "DEBUG" messages, together with the expected "**ERROR** VPN Client '' is INVALID (1-5 only)"

Now if you run
Code: 
service restart_vpnclient1
there should be "DEBUG" messages in Syslog during the initialisation of VPN Client 1

You can provide the portion of Syslog between
Code: 
openvpn-event[xxxx_***DEBUG]:
and
Code: 
ovpn-client1[xxxx]: Initialization Sequence Completed
 
Last edited:
Martineau said:
So create a verbose debugging version of the 'openvpn-event' script

i.e. Insert the following two lines after the '#!/bin/sh' line
Code: 
set -x
(
and append the following line to the end of the script
Code: 
) 2>&1 | logger -st $(basename $0)"[$$_***DEBUG]"
Click to expand...
Thank you, I just got time to work with this. Just to clarify, I have john9527 template, with your additions from an early post above, as my openvpn-event like this. Should I keep this and add those two lines

nevermind, thinking about it I knew I needed to keep John's template. See below
 
Last edited:
Here is the terminal output.
Code: 
[redact]@RT-AC86U-4608:/jffs/scripts# ./vpnclient1-route-up
+ basename ./vpnclient1-route-up
+ logger -st vpnclient1-route-up[1839_***DEBUG]
vpnclient1-route-up[1839_***DEBUG]: + VPN_ID=
vpnclient1-route-up[1839_***DEBUG]: + basename+  ./vpnclient1-route-up
vpnclient1-route-up[1839_***DEBUG]: sh /jffs/scripts/VPN_Failover.sh  delay=60
vpnclient1-route-up[1839_***DEBUG]: + logger -st (vpnclient1-route-up) Requesting VPN_Failover monitor.....
vpnclient1-route-up[1839_***DEBUG]: (vpnclient1-route-up): Requesting VPN_Failover monitor.....
vpnclient1-route-up[1839_***DEBUG]:
vpnclient1-route-up[1839_***DEBUG]:     **ERROR** VPN Client '' is INVALID (1-5 only)
vpnclient1-route-up[1839_***DEBUG]:
The last two lines in red.

This is what I see in the webgui syslog.
Code: 
May 11 15:27:15 (vpnclient1-route-up): Requesting VPN_Failover monitor.....
May 11 15:27:15 vpnclient1-route-up[1839_***DEBUG]: + VPN_ID=
May 11 15:27:15 vpnclient1-route-up[1839_***DEBUG]: + basename+  ./vpnclient1-route-up
May 11 15:27:15 vpnclient1-route-up[1839_***DEBUG]: sh /jffs/scripts/VPN_Failover.sh  delay=60
May 11 15:27:15 vpnclient1-route-up[1839_***DEBUG]: + logger -st (vpnclient1-route-up) Requesting VPN_Failover monitor.....
May 11 15:27:15 vpnclient1-route-up[1839_***DEBUG]: (vpnclient1-route-up): Requesting VPN_Failover monitor.....
May 11 15:27:15 (VPN_Failover.sh): 1842 v1.15 delay=60
May 11 15:27:15 (VPN_Failover.sh): 1842 **ERROR** VPN Client '' is INVALID (1-5 only)
May 11 15:27:15 vpnclient1-route-up[1839_***DEBUG]: ^[[91m^G
May 11 15:27:15 vpnclient1-route-up[1839_***DEBUG]:     **ERROR** VPN Client '' is INVALID (1-5 only)
May 11 15:27:15 vpnclient1-route-up[1839_***DEBUG]: ^[[0m
Obviously the same, the syslog just cannot handle the ASCII characters.

The syslog as requested.
Code: 
May 11 15:22:29 rc_service: service 1268:notify_rc restart_vpnclient1
May 11 15:22:29 custom_script: Running /jffs/scripts/service-event (args: restart vpnclient1)
May 11 15:22:29 ovpn-client1[8057]: event_wait : Interrupted system call (code=4)
May 11 15:22:29 ovpn-client1[8057]: vpnrouting.sh tun11 1500 1553 10.200.0.70 10.200.0.69 init
May 11 15:22:29 openvpn-routing: Configuring policy rules for client 1
May 11 15:22:29 openvpn-routing: Tunnel down - VPN client access blocked
May 11 15:22:29 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 10.200.0.70 10.200.0.69 init)
May 11 15:22:29 ovpn-client1[8057]: Closing TUN/TAP interface
May 11 15:22:29 ovpn-client1[8057]: /bin/ip addr del dev tun11 local 10.200.0.70 peer 10.200.0.69
May 11 15:22:29 lldpd[882]: removal request for address of 10.200.0.69%23, but no knowledge of it
May 11 15:22:29 ovpn-client1[8057]: SIGTERM[hard,] received, process exiting
May 11 15:22:29 ovpn-client1[1503]: OpenVPN 2.4.7 arm-buildroot-linux-gnueabi [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on May  8 2019
May 11 15:22:29 ovpn-client1[1503]: library versions: OpenSSL 1.1.1b  26 Feb 2019, LZO 2.08
May 11 15:22:29 ovpn-client1[1504]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
May 11 15:22:34 ovpn-client1[1504]: TCP/UDP: Preserving recently used remote address: [AF_INET]xxx.xxx.xxx.xxx:1194
May 11 15:22:34 ovpn-client1[1504]: Socket Buffers: R=[524288->1048576] S=[524288->1048576]
May 11 15:22:34 ovpn-client1[1504]: UDP link local: (not bound)
May 11 15:22:34 ovpn-client1[1504]: UDP link remote: [AF_INET]xxx.xxx.xxx.xxx:1194
May 11 15:22:34 ovpn-client1[1504]: TLS: Initial packet from [AF_INET]xxx.xxx.xxx.xxx:1194, sid=83bdee14 e189d25b
May 11 15:22:34 ovpn-client1[1504]: VERIFY OK: depth=1, C=US, ST=NY, L=New York, O=Simplex Solutions Inc., OU=Vpn Unlimited, CN=server.vpnunlimitedapp.com, name=server.vpnunlimitedapp.com, emailAddress=support@simplexsolutionsinc.com
May 11 15:22:34 ovpn-client1[1504]: VERIFY KU OK
May 11 15:22:34 ovpn-client1[1504]: Validating certificate extended key usage
May 11 15:22:34 ovpn-client1[1504]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
May 11 15:22:34 ovpn-client1[1504]: VERIFY EKU OK
May 11 15:22:34 ovpn-client1[1504]: VERIFY OK: depth=0, CN=openvpn2.vpnunlimitedapp.com
May 11 15:22:34 ovpn-client1[1504]: Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 4096 bit RSA
May 11 15:22:34 ovpn-client1[1504]: [openvpn2.vpnunlimitedapp.com] Peer Connection Initiated with [AF_INET]xxx.xxx.xxx.xxx:1194
May 11 15:22:36 ovpn-client1[1504]: SENT CONTROL [openvpn2.vpnunlimitedapp.com]: 'PUSH_REQUEST' (status=1)
May 11 15:22:41 ovpn-client1[1504]: SENT CONTROL [openvpn2.vpnunlimitedapp.com]: 'PUSH_REQUEST' (status=1)
May 11 15:22:41 ovpn-client1[1504]: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 10.200.0.1,rcvbuf 262144,sndbuf 262144,comp-lzo no,ping 5,ping-exit 30,route 10.200.0.1,topology net30,ifconfig 10.200.0.46 10.200.0.45,peer-id 10,cipher AES-256-GCM'
May 11 15:22:41 ovpn-client1[1504]: OPTIONS IMPORT: timers and/or timeouts modified
May 11 15:22:41 ovpn-client1[1504]: OPTIONS IMPORT: compression parms modified
May 11 15:22:41 ovpn-client1[1504]: OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
May 11 15:22:41 ovpn-client1[1504]: Socket Buffers: R=[1048576->524288] S=[1048576->524288]
May 11 15:22:41 ovpn-client1[1504]: OPTIONS IMPORT: --ifconfig/up options modified
May 11 15:22:41 ovpn-client1[1504]: OPTIONS IMPORT: route options modified
May 11 15:22:41 ovpn-client1[1504]: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
May 11 15:22:41 ovpn-client1[1504]: OPTIONS IMPORT: peer-id set
May 11 15:22:41 ovpn-client1[1504]: OPTIONS IMPORT: adjusting link_mtu to 1625
May 11 15:22:41 ovpn-client1[1504]: OPTIONS IMPORT: data channel crypto options modified
May 11 15:22:41 ovpn-client1[1504]: Data Channel: using negotiated cipher 'AES-256-GCM'
May 11 15:22:41 ovpn-client1[1504]: Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 11 15:22:41 ovpn-client1[1504]: Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 11 15:22:41 ovpn-client1[1504]: TUN/TAP device tun11 opened
May 11 15:22:41 ovpn-client1[1504]: TUN/TAP TX queue length set to 1000
May 11 15:22:41 ovpn-client1[1504]: /bin/ip link set dev tun11 up mtu 1500
May 11 15:22:41 ovpn-client1[1504]: /bin/ip addr add dev tun11 local 10.200.0.46 peer 10.200.0.45
May 11 15:22:43 openvpn-routing: Configuring policy rules for client 1
May 11 15:22:43 openvpn-routing: Tunnel re-established, restoring WAN access to clients
May 11 15:22:43 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 10.200.0.46 10.200.0.45)
May 11 15:22:43 ovpn-client1[1504]: Initialization Sequence Completed
 
Last edited:
One more test, checking @eibgrad theory and changed Accept DNS Configuration from "Disabled" to "Relaxed" and TLS control channel security from "Disabled" to "Incoming Auth(0)" and started vpnclient1.
Code: 
May 11 15:57:17 rc_service: httpds 25178:notify_rc start_vpnclient1
May 11 15:57:17 custom_script: Running /jffs/scripts/service-event (args: start vpnclient1)
May 11 15:57:17 ovpn-client1[4781]: OpenVPN 2.4.7 arm-buildroot-linux-gnueabi [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on May  8 2019
May 11 15:57:17 ovpn-client1[4781]: library versions: OpenSSL 1.1.1b  26 Feb 2019, LZO 2.08
May 11 15:57:17 ovpn-client1[4782]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
May 11 15:57:17 ovpn-client1[4782]: TCP/UDP: Preserving recently used remote address: [AF_INET]xxx.xxx.xxx.xxx:1194
May 11 15:57:17 ovpn-client1[4782]: Socket Buffers: R=[524288->1048576] S=[524288->1048576]
May 11 15:57:17 ovpn-client1[4782]: UDP link local: (not bound)
May 11 15:57:17 ovpn-client1[4782]: UDP link remote: [AF_INET]xxx.xxx.xxx.xxx:1194
May 11 15:57:17 ovpn-client1[4782]: TLS: Initial packet from [AF_INET]xxx.xxx.xxx.xxx:1194, sid=ffb4f48b 4acdf6b6
May 11 15:57:17 ovpn-client1[4782]: VERIFY OK: depth=1, C=US, ST=NY, L=New York, O=Simplex Solutions Inc., OU=Vpn Unlimited, CN=server.vpnunlimitedapp.com, name=server.vpnunlimitedapp.com, emailAddress=support@simplexsolutionsinc.com
May 11 15:57:17 ovpn-client1[4782]: VERIFY KU OK
May 11 15:57:17 ovpn-client1[4782]: Validating certificate extended key usage
May 11 15:57:17 ovpn-client1[4782]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
May 11 15:57:17 ovpn-client1[4782]: VERIFY EKU OK
May 11 15:57:17 ovpn-client1[4782]: VERIFY OK: depth=0, CN=openvpn2.vpnunlimitedapp.com
May 11 15:57:17 ovpn-client1[4782]: Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 4096 bit RSA
May 11 15:57:17 ovpn-client1[4782]: [openvpn2.vpnunlimitedapp.com] Peer Connection Initiated with [AF_INET]xxx.xxx.xxx.xxx:1194
May 11 15:57:18 ovpn-client1[4782]: SENT CONTROL [openvpn2.vpnunlimitedapp.com]: 'PUSH_REQUEST' (status=1)
May 11 15:57:23 ovpn-client1[4782]: SENT CONTROL [openvpn2.vpnunlimitedapp.com]: 'PUSH_REQUEST' (status=1)
May 11 15:57:23 ovpn-client1[4782]: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 10.200.0.1,rcvbuf 262144,sndbuf 262144,comp-lzo no,ping 5,ping-exit 30,route 10.200.0.1,topology net30,ifconfig 10.200.0.6 10.200.0.5,peer-id 1,cipher AES-256-GCM'
May 11 15:57:23 ovpn-client1[4782]: OPTIONS IMPORT: timers and/or timeouts modified
May 11 15:57:23 ovpn-client1[4782]: OPTIONS IMPORT: compression parms modified
May 11 15:57:23 ovpn-client1[4782]: OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
May 11 15:57:23 ovpn-client1[4782]: Socket Buffers: R=[1048576->524288] S=[1048576->524288]
May 11 15:57:23 ovpn-client1[4782]: OPTIONS IMPORT: --ifconfig/up options modified
May 11 15:57:23 ovpn-client1[4782]: OPTIONS IMPORT: route options modified
May 11 15:57:23 ovpn-client1[4782]: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
May 11 15:57:23 ovpn-client1[4782]: OPTIONS IMPORT: peer-id set
May 11 15:57:23 ovpn-client1[4782]: OPTIONS IMPORT: adjusting link_mtu to 1625
May 11 15:57:23 ovpn-client1[4782]: OPTIONS IMPORT: data channel crypto options modified
May 11 15:57:23 ovpn-client1[4782]: Data Channel: using negotiated cipher 'AES-256-GCM'
May 11 15:57:23 ovpn-client1[4782]: Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 11 15:57:23 ovpn-client1[4782]: Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 11 15:57:23 ovpn-client1[4782]: TUN/TAP device tun11 opened
May 11 15:57:23 ovpn-client1[4782]: TUN/TAP TX queue length set to 1000
May 11 15:57:23 ovpn-client1[4782]: /bin/ip link set dev tun11 up mtu 1500
May 11 15:57:23 ovpn-client1[4782]: /bin/ip addr add dev tun11 local 10.200.0.6 peer 10.200.0.5
May 11 15:57:23 ovpn-client1[4782]: updown.sh tun11 1500 1553 10.200.0.6 10.200.0.5 init
May 11 15:57:23 rc_service: service 4842:notify_rc updateresolv
May 11 15:57:23 custom_script: Running /jffs/scripts/service-event (args:  updateresolv)
May 11 15:57:24 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 10.200.0.6 10.200.0.5 init)
May 11 15:57:26 openvpn-routing: Configuring policy rules for client 1
May 11 15:57:26 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 10.200.0.6 10.200.0.5)
May 11 15:57:26 ovpn-client1[4782]: Initialization Sequence Completed
First time this has appeared in the log.
Code: 
May 11 15:57:23 ovpn-client1[4782]: updown.sh tun11 1500 1553 10.200.0.6 10.200.0.5 init
 
Last edited:
One more item, here is the complete openvpn-event
Code: 
#!/bin/sh
set -x
(
scr_name="$(basename $0)[$$]"
case "$1" in
    "tun11")
        vpn_name="client1"
        ;;
    "tun12")
        vpn_name="client2"
        ;;
    "tun13")
        vpn_name="client3"
        ;;
    "tun14")
        vpn_name="client4"
        ;;
    "tun15")
        vpn_name="client5"
        ;;
    "tun21")
        vpn_name="server1"
        ;;
    "tun22")
        vpn_name="server2"
        ;;
    *)
        vpn_name=""
        ;;
esac
# Call appropriate script based on script_type
vpn_script_name="vpn$vpn_name-$script_type"
# Check script state
vpn_script_state=$(cat $vpn_script_log 2>/dev/null)
if [ "$vpn_script_name" = "$vpn_script_state" ]; then
    #======================================================================================Martineau Hack =====================
    #echo "VPN script" $vpn_script_name "already run" | logger -t "$scr_name"
    echo "     ***VPN script" $vpn_script_name "already run" | logger -t "$scr_name"
    #====================================================================================================================
    exit 0
fi
# Execute and log script state
if [[ -f "/jffs/scripts/$vpn_script_name" ]] ; then
    #======================================================================================Martineau Hack =====================
    echo "     Script executing.. for VPN event: "$vpn_script_name | logger -t $scr_name
    #====================================================================================================================
    echo "$vpn_script_name" > $vpn_script_log
    sh /jffs/scripts/$vpn_script_name $*
else
    #======================================================================================Martineau Hack =====================
    #echo "Script not defined for event: "$vpn_script_name | logger -t $scr_name
    echo "     Script not defined for VPN event: "$vpn_script_name | logger -t $scr_name
    #====================================================================================================================
    exit 0
) 2>&1 | logger -st $(basename $0)"[$$_***DEBUG]"
fi
 
Sadly your poor copy'n'paste (not scripting) skills for the three debug lines has created another problem...:rolleyes:

i.e. in post #50, script openvpn-event was executing correctly (but may have a minor run-time flaw - hence the need to trace its execution logic)
Butterfly Bones said:
Code: 
May 10 16:45:22 openvpn-event[6748]:      Script executing.. for VPN event: vpnclient1-route-up
May 10 16:45:22 ovpn-client1[xxxx]: Initialization Sequence Completed
Click to expand...
...but in post #53
Butterfly Bones said:
One more test, checking @eibgrad theory and changed Accept DNS Configuration from "Disabled" to "Relaxed" and TLS control channel security from "Disabled" to "Incoming Auth(0)" and started vpnclient1.
Code: 
<snip>
May 11 15:57:26 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 10.200.0.6 10.200.0.5)
May 11 15:57:26 ovpn-client1[4782]: Initialization Sequence Completed
First time this has appeared in the log.
Code: 
May 11 15:57:23 ovpn-client1[4782]: updown.sh tun11 1500 1553 10.200.0.6 10.200.0.5 init
Click to expand...
you confusingly altered settings on a whim rather than concentrating on the single task that has been requested of you, consequently you managed to mangle the debugging code..

Can you see what you did incorrectly?
Butterfly Bones said:
Here is the complete openvpn-event
Code: 
<snip>
) 2>&1 | logger -st $(basename $0)"[$$_***DEBUG]"
fi
Click to expand...
 
reverted to original settings

Accept DNS Configuration now "Disabled"
TLS control channel security now"Disabled"

openvpn-event corrected
Code: 
#!/bin/sh
set -x
(
scr_name="$(basename $0)[$$]"

%<  (SNIP)  >%

fi
) 2>&1 | logger -st $(basename $0)"[$$_***DEBUG]"

executed
Code: 
[redact]@RT-AC86U-4608:/jffs/scripts# ./vpnclient1-route-up

last two lines in red - as expected
Code: 
+ basename ./vpnclient1-route-up
+ logger -st vpnclient1-route-up[23060_***DEBUG]
vpnclient1-route-up[23060_***DEBUG]: + VPN_ID=
vpnclient1-route-up[23060_***DEBUG]: + sh /jffs/scripts/VPN_Failover.sh  delay=60
vpnclient1-route-up[23060_***DEBUG]: + basename ./vpnclient1-route-up
vpnclient1-route-up[23060_***DEBUG]: + logger -st (vpnclient1-route-up) Requesting VPN_Failover monitor.....
vpnclient1-route-up[23060_***DEBUG]: (vpnclient1-route-up): Requesting VPN_Failover monitor.....
vpnclient1-route-up[23060_***DEBUG]:
vpnclient1-route-up[23060_***DEBUG]:     **ERROR** VPN Client '' is INVALID (1-5 only)
vpnclient1-route-up[23060_***DEBUG]:

.... see next post, SNB says post too long
 
executed
Code: 
[redact]@RT-AC86U-4608:/tmp/home/root# service restart_vpnclient1
Done.
webgui output
Code: 
May 12 07:31:03 rc_service: service 22058:notify_rc restart_vpnclient1
May 12 07:31:03 custom_script: Running /jffs/scripts/service-event (args: restart vpnclient1)
May 12 07:31:03 ovpn-client1[21747]: vpnrouting.sh tun11 1500 1553 10.200.0.70 10.200.0.69 init
May 12 07:31:03 openvpn-routing: Configuring policy rules for client 1
May 12 07:31:03 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 10.200.0.70 10.200.0.69 init)
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + basename /jffs/scripts/openvpn-event
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + scr_name=openvpn-event[22105]
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + vpn_name=client1
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + vpn_script_name=vpnclient1-route-pre-down
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + cat
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + vpn_script_state=
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + [ vpnclient1-route-pre-down =  ]
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + [[ -f /jffs/scripts/vpnclient1-route-pre-down ]]
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + logger -t openvpn-event[22105]
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + echo      Script executing.. for VPN event: vpnclient1-route-pre-down
May 12 07:31:03 openvpn-event[22105]:      Script executing.. for VPN event: vpnclient1-route-pre-down
May 12 07:31:03 openvpn-event[22105_***DEBUG]: /jffs/scripts/openvpn-event: line 61: can't create : nonexistent directory
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + echo vpnclient1-route-pre-down
May 12 07:31:03 openvpn-event[22105_***DEBUG]: + sh /jffs/scripts/vpnclient1-route-pre-down tun11 1500 1553 10.200.0.70 10.200.0.69 init
May 12 07:31:03 openvpn-event[22105_***DEBUG]: Error: Address /jffs/scripts/vpnclient1-route-pre-down is invalid
May 12 07:31:03 openvpn-event[22105_***DEBUG]: *** Usage:
May 12 07:31:03 openvpn-event[22105_***DEBUG]:  dw/dh/db <physical address in hex> <number>
May 12 07:31:03 openvpn-event[22105_***DEBUG]:  dw/dh/db <-k> <virtual address in hex> <number>
May 12 07:31:03 openvpn-event[22105_***DEBUG]:  sw/sh/sb <physical address in hex> <data value1> <data value2> ..<data valueN>
May 12 07:31:03 openvpn-event[22105_***DEBUG]:  sw/sh/sb <-k> <virtual address in hex> <data value1> <data value2> ..<data valueN>
May 12 07:31:03 openvpn-event[22105_***DEBUG]:  fw/fh/fb  <physical address in hex> <data value> <length>
May 12 07:31:03 openvpn-event[22105_***DEBUG]:  fw/fh/fb <-k> <virtual address in hex> <data value> <length>
May 12 07:31:03 openvpn-event[22105_***DEBUG]:   -s (currently works with physical addresses for d*/s*/f* commands
May 12 07:31:03 openvpn-event[22105_***DEBUG]: and virtual addresses for s*/f* commands)
May 12 07:31:03 ovpn-client1[21747]: Closing TUN/TAP interface
May 12 07:31:03 ovpn-client1[21747]: /bin/ip addr del dev tun11 local 10.200.0.70 peer 10.200.0.69
May 12 07:31:03 lldpd[882]: removal request for address of 10.200.0.69%39, but no knowledge of it
May 12 07:31:03 ovpn-client1[21747]: SIGTERM[hard,] received, process exiting
May 12 07:31:03 ovpn-client1[22203]: OpenVPN 2.4.7 arm-buildroot-linux-gnueabi [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on May  8 2019
May 12 07:31:03 ovpn-client1[22203]: library versions: OpenSSL 1.1.1b  26 Feb 2019, LZO 2.08
May 12 07:31:03 ovpn-client1[22204]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
May 12 07:31:06 kernel: [BLOCKED - INBOUND] IN=eth0 OUT= MAC=88:d7:f6:1d:46:08:00:01:5c:6d:22:46:08:00 SRC=185.176.26.101 DST=71.93.53.239 LEN=40 TOS=0x00 PREC=0x00 TTL=237 ID=12786 PROTO=TCP SPT=45693 DPT=17724 SEQ=3306766625 ACK=0 WINDOW=1024 RES=0x00 SYN URGP=0 MARK=0x8000000
May 12 07:31:08 ovpn-client1[22204]: TCP/UDP: Preserving recently used remote address: [AF_INET]xxx.xxx.xxx.xx:1194
May 12 07:31:08 ovpn-client1[22204]: Socket Buffers: R=[524288->1048576] S=[524288->1048576]
May 12 07:31:08 ovpn-client1[22204]: UDP link local: (not bound)
May 12 07:31:08 ovpn-client1[22204]: UDP link remote: [AF_INET]xxx.xxx.xxx.xx:1194
May 12 07:31:08 ovpn-client1[22204]: TLS: Initial packet from [AF_INET]xxx.xxx.xxx.xx:1194, sid=eaf9d671 ca59c530
May 12 07:31:08 ovpn-client1[22204]: VERIFY OK: depth=1, C=US, ST=NY, L=New York, O=Simplex Solutions Inc., OU=Vpn Unlimited, CN=server.vpnunlimitedapp.com, name=server.vpnunlimitedapp.com, emailAddress=support@simplexsolutionsinc.com
May 12 07:31:08 ovpn-client1[22204]: VERIFY KU OK
May 12 07:31:08 ovpn-client1[22204]: Validating certificate extended key usage
May 12 07:31:08 ovpn-client1[22204]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
May 12 07:31:08 ovpn-client1[22204]: VERIFY EKU OK
May 12 07:31:08 ovpn-client1[22204]: VERIFY OK: depth=0, CN=openvpn2.vpnunlimitedapp.com
May 12 07:31:09 ovpn-client1[22204]: Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 4096 bit RSA
May 12 07:31:09 ovpn-client1[22204]: [openvpn2.vpnunlimitedapp.com] Peer Connection Initiated with [AF_INET]xxx.xxx.xxx.xx:1194
May 12 07:31:10 ovpn-client1[22204]: SENT CONTROL [openvpn2.vpnunlimitedapp.com]: 'PUSH_REQUEST' (status=1)
May 12 07:31:15 ovpn-client1[22204]: SENT CONTROL [openvpn2.vpnunlimitedapp.com]: 'PUSH_REQUEST' (status=1)
May 12 07:31:15 ovpn-client1[22204]: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 10.200.0.1,rcvbuf 262144,sndbuf 262144,comp-lzo no,ping 5,ping-exit 30,route 10.200.0.1,topology net30,ifconfig 10.200.0.82 10.200.0.81,peer-id 19,cipher AES-256-GCM'
May 12 07:31:15 ovpn-client1[22204]: OPTIONS IMPORT: timers and/or timeouts modified
May 12 07:31:15 ovpn-client1[22204]: OPTIONS IMPORT: compression parms modified
May 12 07:31:15 ovpn-client1[22204]: OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
May 12 07:31:15 ovpn-client1[22204]: Socket Buffers: R=[1048576->524288] S=[1048576->524288]
May 12 07:31:15 ovpn-client1[22204]: OPTIONS IMPORT: --ifconfig/up options modified
May 12 07:31:15 ovpn-client1[22204]: OPTIONS IMPORT: route options modified
May 12 07:31:15 ovpn-client1[22204]: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
May 12 07:31:15 ovpn-client1[22204]: OPTIONS IMPORT: peer-id set
May 12 07:31:15 ovpn-client1[22204]: OPTIONS IMPORT: adjusting link_mtu to 1625
May 12 07:31:15 ovpn-client1[22204]: OPTIONS IMPORT: data channel crypto options modified
May 12 07:31:15 ovpn-client1[22204]: Data Channel: using negotiated cipher 'AES-256-GCM'
May 12 07:31:15 ovpn-client1[22204]: Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 12 07:31:15 ovpn-client1[22204]: Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 12 07:31:15 ovpn-client1[22204]: TUN/TAP device tun11 opened
May 12 07:31:15 ovpn-client1[22204]: TUN/TAP TX queue length set to 1000
May 12 07:31:15 ovpn-client1[22204]: /bin/ip link set dev tun11 up mtu 1500
May 12 07:31:15 ovpn-client1[22204]: /bin/ip addr add dev tun11 local 10.200.0.82 peer 10.200.0.81
May 12 07:31:17 openvpn-routing: Configuring policy rules for client 1
May 12 07:31:17 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 10.200.0.82 10.200.0.81)
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + basename /jffs/scripts/openvpn-event
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + scr_name=openvpn-event[22386]
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + vpn_name=client1
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + vpn_script_name=vpnclient1-route-up
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + cat
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + vpn_script_state=
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + [ vpnclient1-route-up =  ]
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + [[ -f /jffs/scripts/vpnclient1-route-up ]]
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + logger -t openvpn-event[22386]
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + echo      Script executing.. for VPN event: vpnclient1-route-up
May 12 07:31:17 openvpn-event[22386]:      Script executing.. for VPN event: vpnclient1-route-up
May 12 07:31:17 openvpn-event[22386_***DEBUG]: /jffs/scripts/openvpn-event: line 61: can't create : nonexistent directory
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + echo vpnclient1-route-up
May 12 07:31:17 openvpn-event[22386_***DEBUG]: + sh /jffs/scripts/vpnclient1-route-up tun11 1500 1553 10.200.0.82 10.200.0.81
May 12 07:31:17 openvpn-event[22386_***DEBUG]: Error: Address /jffs/scripts/vpnclient1-route-up is invalid
May 12 07:31:17 openvpn-event[22386_***DEBUG]: *** Usage:
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  dw/dh/db <physical address in hex> <number>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  dw/dh/db <-k> <virtual address in hex> <number>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  sw/sh/sb <physical address in hex> <data value1> <data value2> ..<data valueN>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  sw/sh/sb <-k> <virtual address in hex> <data value1> <data value2> ..<data valueN>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  fw/fh/fb  <physical address in hex> <data value> <length>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  fw/fh/fb <-k> <virtual address in hex> <data value> <length>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:   -s (currently works with physical addresses for d*/s*/f* commands
May 12 07:31:17 openvpn-event[22386_***DEBUG]: and virtual addresses for s*/f* commands)
May 12 07:31:17 ovpn-client1[22204]: Initialization Sequence Completed
 
@Butterfly Bones Whilst I can recreate this silly typo error :oops:
Code: 
May 12 07:31:17 openvpn-event[22386_***DEBUG]: /jffs/scripts/openvpn-event: line 61: can't create : nonexistent directory
I can't explain
Code: 
May 12 07:31:17 openvpn-event[22386_***DEBUG]: Error: Address /jffs/scripts/vpnclient1-route-up is invalid
May 12 07:31:17 openvpn-event[22386_***DEBUG]: *** Usage:
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  dw/dh/db <physical address in hex> <number>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  dw/dh/db <-k> <virtual address in hex> <number>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  sw/sh/sb <physical address in hex> <data value1> <data value2> ..<data valueN>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  sw/sh/sb <-k> <virtual address in hex> <data value1> <data value2> ..<data valueN>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  fw/fh/fb  <physical address in hex> <data value> <length>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:  fw/fh/fb <-k> <virtual address in hex> <data value> <length>
May 12 07:31:17 openvpn-event[22386_***DEBUG]:   -s (currently works with physical addresses for d*/s*/f* commands
May 12 07:31:17 openvpn-event[22386_***DEBUG]: and virtual addresses for s*/f* commands)
Clearly the openvpn-event script isn't actually asking the shell to execute '/jffs/scripts/vpnclient1-route-up' but instead appears to pass it as a 'text string' argument to a utility?:confused:

This more than likely explains why the script never exists as a separate process.:eek:

I have found this which appears to be the source of the text. o_O
Perhaps @RMerlin may have previously encountered this obscure utility?

Anyway, I suggest you delete the openvpn-event script, and recreate it from the openvpn-event script template and insert the three debugging lines, and retest
Code: 
service restart_vpnclient1
 
Last edited:
Thanks again. Deleted openvpn-event and recreated, did not attempt to include the "Marineau Hack" lines that I added previously. Checked all 3 scripts, verified chmod 755 on all.
Code: 
May 12 10:48:03 rc_service: service 31798:notify_rc restart_vpnclient1
May 12 10:48:03 custom_script: Running /jffs/scripts/service-event (args: restart vpnclient1)
May 12 10:48:03 ovpn-client1[31236]: event_wait : Interrupted system call (code=4)
May 12 10:48:03 ovpn-client1[31236]: vpnrouting.sh tun11 1500 1553 10.200.0.14 10.200.0.13 init
May 12 10:48:03 openvpn-routing: Configuring policy rules for client 1
May 12 10:48:03 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 10.200.0.14 10.200.0.13 init)
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + basename /jffs/scripts/openvpn-event
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + scr_name=openvpn-event[31845]
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + vpn_name=client1
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + vpn_script_name=vpnclient1-route-pre-down
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + nvram get vpn_script_state
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + vpn_script_state=vpnclient1-route-up
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + nvram set vpn_script_state=vpnclient1-route-pre-down
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + [ vpnclient1-route-pre-down = vpnclient1-route-up ]
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + [[ -f /jffs/scripts/vpnclient1-route-pre-down ]]
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + sh /jffs/scripts/vpnclient1-route-pre-down tun11 1500 1553 10.200.0.14 10.200.0.13 init
May 12 10:48:03 openvpn-event[31845_***DEBUG]: Error: Address /jffs/scripts/vpnclient1-route-pre-down is invalid
May 12 10:48:03 openvpn-event[31845_***DEBUG]: *** Usage:
May 12 10:48:03 openvpn-event[31845_***DEBUG]:  dw/dh/db <physical address in hex> <number>
May 12 10:48:03 openvpn-event[31845_***DEBUG]:  dw/dh/db <-k> <virtual address in hex> <number>
May 12 10:48:03 openvpn-event[31845_***DEBUG]:  sw/sh/sb <physical address in hex> <data value1> <data value2> ..<data valueN>
May 12 10:48:03 openvpn-event[31845_***DEBUG]:  sw/sh/sb <-k> <virtual address in hex> <data value1> <data value2> ..<data valueN>
May 12 10:48:03 openvpn-event[31845_***DEBUG]:  fw/fh/fb  <physical address in hex> <data value> <length>
May 12 10:48:03 openvpn-event[31845_***DEBUG]:  fw/fh/fb <-k> <virtual address in hex> <data value> <length>
May 12 10:48:03 openvpn-event[31845_***DEBUG]:   -s (currently works with physical addresses for d*/s*/f* commands
May 12 10:48:03 openvpn-event[31845_***DEBUG]: and virtual addresses for s*/f* commands)
May 12 10:48:03 openvpn-event[31845_***DEBUG]: + exit 0
May 12 10:48:03 ovpn-client1[31236]: Closing TUN/TAP interface
May 12 10:48:03 ovpn-client1[31236]: /bin/ip addr del dev tun11 local 10.200.0.14 peer 10.200.0.13
May 12 10:48:03 lldpd[882]: removal request for address of 10.200.0.13%47, but no knowledge of it
May 12 10:48:03 ovpn-client1[31236]: SIGTERM[hard,] received, process exiting
May 12 10:48:04 ovpn-client1[31944]: OpenVPN 2.4.7 arm-buildroot-linux-gnueabi [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on May  8 2019
May 12 10:48:04 ovpn-client1[31944]: library versions: OpenSSL 1.1.1b  26 Feb 2019, LZO 2.08
May 12 10:48:04 ovpn-client1[31945]: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
May 12 10:48:09 ovpn-client1[31945]: TCP/UDP: Preserving recently used remote address: [AF_INET]xxx.xxx.xxx.xx:1194
May 12 10:48:09 ovpn-client1[31945]: Socket Buffers: R=[524288->1048576] S=[524288->1048576]
May 12 10:48:09 ovpn-client1[31945]: UDP link local: (not bound)
May 12 10:48:09 ovpn-client1[31945]: UDP link remote: [AF_INET]xxx.xxx.xxx.xx:1194
May 12 10:48:09 ovpn-client1[31945]: TLS: Initial packet from [AF_INET]xxx.xxx.xxx.xx:1194, sid=0b9051fc 3c0b33dd
May 12 10:48:09 ovpn-client1[31945]: VERIFY OK: depth=1, C=US, ST=NY, L=New York, O=Simplex Solutions Inc., OU=Vpn Unlimited, CN=server.vpnunlimitedapp.com, name=server.vpnunlimitedapp.com, emailAddress=support@simplexsolutionsinc.com
May 12 10:48:09 ovpn-client1[31945]: VERIFY KU OK
May 12 10:48:09 ovpn-client1[31945]: Validating certificate extended key usage
May 12 10:48:09 ovpn-client1[31945]: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
May 12 10:48:09 ovpn-client1[31945]: VERIFY EKU OK
May 12 10:48:09 ovpn-client1[31945]: VERIFY OK: depth=0, CN=openvpn2.vpnunlimitedapp.com
May 12 10:48:09 ovpn-client1[31945]: Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, 4096 bit RSA
May 12 10:48:09 ovpn-client1[31945]: [openvpn2.vpnunlimitedapp.com] Peer Connection Initiated with [AF_INET]xxx.xxx.xxx.xx:1194
May 12 10:48:10 ovpn-client1[31945]: SENT CONTROL [openvpn2.vpnunlimitedapp.com]: 'PUSH_REQUEST' (status=1)
May 12 10:48:15 ovpn-client1[31945]: SENT CONTROL [openvpn2.vpnunlimitedapp.com]: 'PUSH_REQUEST' (status=1)
May 12 10:48:15 ovpn-client1[31945]: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1,dhcp-option DNS 10.200.0.1,rcvbuf 262144,sndbuf 262144,comp-lzo no,ping 5,ping-exit 30,route 10.200.0.1,topology net30,ifconfig 10.200.0.54 10.200.0.53,peer-id 17,cipher AES-256-GCM'
May 12 10:48:15 ovpn-client1[31945]: OPTIONS IMPORT: timers and/or timeouts modified
May 12 10:48:15 ovpn-client1[31945]: OPTIONS IMPORT: compression parms modified
May 12 10:48:15 ovpn-client1[31945]: OPTIONS IMPORT: --sndbuf/--rcvbuf options modified
May 12 10:48:15 ovpn-client1[31945]: Socket Buffers: R=[1048576->524288] S=[1048576->524288]
May 12 10:48:15 ovpn-client1[31945]: OPTIONS IMPORT: --ifconfig/up options modified
May 12 10:48:15 ovpn-client1[31945]: OPTIONS IMPORT: route options modified
May 12 10:48:15 ovpn-client1[31945]: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
May 12 10:48:15 ovpn-client1[31945]: OPTIONS IMPORT: peer-id set
May 12 10:48:15 ovpn-client1[31945]: OPTIONS IMPORT: adjusting link_mtu to 1625
May 12 10:48:15 ovpn-client1[31945]: OPTIONS IMPORT: data channel crypto options modified
May 12 10:48:15 ovpn-client1[31945]: Data Channel: using negotiated cipher 'AES-256-GCM'
May 12 10:48:15 ovpn-client1[31945]: Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 12 10:48:15 ovpn-client1[31945]: Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
May 12 10:48:15 ovpn-client1[31945]: TUN/TAP device tun11 opened
May 12 10:48:15 ovpn-client1[31945]: TUN/TAP TX queue length set to 1000
May 12 10:48:15 ovpn-client1[31945]: /bin/ip link set dev tun11 up mtu 1500
May 12 10:48:15 ovpn-client1[31945]: /bin/ip addr add dev tun11 local 10.200.0.54 peer 10.200.0.53
May 12 10:48:17 openvpn-routing: Configuring policy rules for client 1
May 12 10:48:17 custom_script: Running /jffs/scripts/openvpn-event (args: tun11 1500 1553 10.200.0.54 10.200.0.53)
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + basename /jffs/scripts/openvpn-event
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + scr_name=openvpn-event[32176]
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + vpn_name=client1
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + vpn_script_name=vpnclient1-route-up
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + nvram get vpn_script_state
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + vpn_script_state=vpnclient1-route-pre-down
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + nvram set vpn_script_state=vpnclient1-route-up
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + [ vpnclient1-route-up = vpnclient1-route-pre-down ]
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + [[ -f /jffs/scripts/vpnclient1-route-up ]]
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + sh /jffs/scripts/vpnclient1-route-up tun11 1500 1553 10.200.0.54 10.200.0.53
May 12 10:48:17 openvpn-event[32176_***DEBUG]: Error: Address /jffs/scripts/vpnclient1-route-up is invalid
May 12 10:48:17 openvpn-event[32176_***DEBUG]: *** Usage:
May 12 10:48:17 openvpn-event[32176_***DEBUG]:  dw/dh/db <physical address in hex> <number>
May 12 10:48:17 openvpn-event[32176_***DEBUG]:  dw/dh/db <-k> <virtual address in hex> <number>
May 12 10:48:17 openvpn-event[32176_***DEBUG]:  sw/sh/sb <physical address in hex> <data value1> <data value2> ..<data valueN>
May 12 10:48:17 openvpn-event[32176_***DEBUG]:  sw/sh/sb <-k> <virtual address in hex> <data value1> <data value2> ..<data valueN>
May 12 10:48:17 openvpn-event[32176_***DEBUG]:  fw/fh/fb  <physical address in hex> <data value> <length>
May 12 10:48:17 openvpn-event[32176_***DEBUG]:  fw/fh/fb <-k> <virtual address in hex> <data value> <length>
May 12 10:48:17 openvpn-event[32176_***DEBUG]:   -s (currently works with physical addresses for d*/s*/f* commands
May 12 10:48:17 openvpn-event[32176_***DEBUG]: and virtual addresses for s*/f* commands)
May 12 10:48:17 openvpn-event[32176_***DEBUG]: + exit 0
May 12 10:48:17 ovpn-client1[31945]: Initialization Sequence Completed
SNB too long, see next message.
 
You must log in or register to reply here.

Similar threads

chetstone
Which user script to use to start a daemon at boot-up?
Replies
3
Views
378
chetstone
chetstone
T
Troubles with VPN Client + DDNS Setup on GT-BE98
Replies
5
Views
356
Tuntenfisch
T
T
[Help] Problems setting up OpenVPN
Replies
7
Views
355
Thookie
T
S
wan-event sometimes not triggered during WAN event
Replies
2
Views
1K
salvo
S
S
OpenVPN client 1, 3 and 5 not working
2
Replies
24
Views
3K
Tech9
Tech9
Similar threads
Thread starter Title Forum Replies Date
Rob Bowlby fwupdate.asuswrt-merlin.net - diversion.ch Down? Asuswrt-Merlin 7
N RT-AX88U wireless shuts down at irregular intervals Asuswrt-Merlin 8
V RT-AX88U Link Down on PC boot Asuswrt-Merlin 0
P In dnsmasq, how do I stop overriding an address if the server goes down? Asuswrt-Merlin 1
M AX82U issues with WAN port going down every day Asuswrt-Merlin 2
G multiple wired ports down Asuswrt-Merlin 5
skeal Attached drive not idling down as the firmware says and is set for Asuswrt-Merlin 6
visortgw asuswrt-merlin.net Website Site Down? Asuswrt-Merlin 18
C hardware down-/up-load graphics miss torrent Asuswrt-Merlin 0
L Custom DDNS vs Drop Down List for Same Provider Asuswrt-Merlin 3

Similar threads

Latest threads

Support SNBForums w/ Amazon

If you'd like to support SNBForums, just use this link and buy anything on Amazon. Thanks!

Sign Up For SNBForums Daily Digest

Get an update of what's new every day delivered to your mailbox. Sign up here!

Members online

Total: 843 (members: 26, guests: 817)
Top