WARNING: Failed running command (--client-connect): could not execute external program
I have a working openvpn_as configuration (2.0.17). I would like to execute a script when a user connects/disconnects from the vpn but have spent a day on it and still dont have it working.
I put in the advanced VPN settings the following
script-security 3 system
client-connect /path/to/script/start.sh
client-disconnect /path/to/script/stop.sh
The start script so far just contain the following (and the stop is same with different name of the temp file)
#!/bin/bash
echo "starting"
env > /tmp/start.$$
exit 0
So i found a few posts online about including the #!/bin/bash line and making sure it exits with zero.
Also found posts regarding setting script-security 2, 3 and 3 system.
I've tried it with all three combinations and it still gets the same error.
I confirmed the path to the script matches what i have set in the server script settings
The script was originally owned by root but i also tried with it owned by openvpn_as and just for the hell of it, tried it with permissions 777.
in all cases, i get exactly the same error.
I also tried adding verb 3, 4, 6 and 11 to see if it might tell me the script it was trying to execute but verb 11 doesnt give any additional information from that of verb 3 regarding what it's doing with file processing - spitting out the full filename it's looking for would helpful in the debugging info. Below is the verb 11 output if this junk means anything to anybody.
Any help appreciated. I did note if I changed the action to up instead of client-connect, it did run the script but i'm unclear if that will run every time a user connects or just when the VPN server starts. So either some clarity around difference between up and client-connect or some idea why client-connect doesnt work would be much appreciated. The down script didnt run when the VPN user disconnected.
Thanks in advance
Trevor
15-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36563 78.146.26.44:26247 TLS: found match, session[0], sid=8cbd46a7 a7e8e8d4'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36586 78.146.26.44:26247 PID_TEST [0] [TLS_AUTH-0] [] 1435764650:51 1435764650:52 t=1435764657[0] r=[-1,0,0,0,1]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36603 78.146.26.44:26247 TLS: received control channel packet s#=0 sid=8cbd46a7 a7e8e8d4'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36618 78.146.26.44:26247 ACK received for pid 23, deleting from send buffer'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36644 78.146.26.44:26247 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=e98d7530 1d9d0657, stored-sid=8cbd46a7 a7e8e8d4, stored-ip=[AF_INET]78.146.26.44:26247'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36660 78.146.26.44:26247 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36675 78.146.26.44:26247 ACK reliable_can_send active=1 current=0 : [25] 24'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36694 78.146.26.44:26247 ACK reliable_send_timeout 3 [25] 24'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36708 78.146.26.44:26247 TLS: tls_process: timeout set to 3'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36727 78.146.26.44:26247 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=ab99dce5 918db688, stored-sid=00000000 00000000, stored-ip=[undef]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36746 78.146.26.44:26247 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36764 STREAM: SET NEXT, buf=[440,0] next=[440,1544] len=-1 maxlen=1544'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36810 STREAM: SET NEXT, buf=[440,0] next=[440,1544] len=-1 maxlen=1544'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=36826 MULTI TCP: multi_tcp_post TA_SOCKET_READ -> TA_UNDEF'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386227 EP_WAIT[0] rwflags=0x0001 ev=0x00000001 arg=0x01adbf90'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386277 MULTI TCP: multi_tcp_action a=TA_SOCKET_READ p=0'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386295 MULTI TCP: multi_tcp_dispatch a=TA_SOCKET_READ mi=0x01adbf90'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386313 78.146.26.44:26247 STREAM: GET NEXT len=1544'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386337 78.146.26.44:26247 STREAM: ADD length_added=52'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386353 78.146.26.44:26247 STREAM: ADD returned TRUE, buf_len=50, residual_len=0'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386367 78.146.26.44:26247 STREAM: GET FINAL len=50'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386381 78.146.26.44:26247 STREAM: RESET'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386396 78.146.26.44:26247 TCPv4_SERVER read returned 50'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386471 78.146.26.44:26247 TCPv4_SERVER READ [50] from [AF_INET]78.146.26.44:26247: P_ACK_V1 kid=0 sid=8cbd46a7 a7e8e8d4 tls_hmac=392a8a91 01428eaf cfae1bcb 877de836 6d56e609 pid=[ #53 / time = (1435764650) Wed Jul 1 15:30:50 2015 ] [ 24 sid=e98d7530 1d9d0657 ]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386492 78.146.26.44:26247 TLS: control channel, op=P_ACK_V1, IP=[AF_INET]78.146.26.44:26247'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386521 78.146.26.44:26247 TLS: initial packet test, i=0 state=S_SENT_KEY, mysid=e98d7530 1d9d0657, rec-sid=8cbd46a7 a7e8e8d4, rec-ip=[AF_INET]78.146.26.44:26247, stored-sid=8cbd46a7 a7e8e8d4, stored-ip=[AF_INET]78.146.26.44:26247'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386538 78.146.26.44:26247 TLS: found match, session[0], sid=8cbd46a7 a7e8e8d4'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386570 78.146.26.44:26247 PID_TEST [0] [TLS_AUTH-0] [] 1435764650:52 1435764650:53 t=1435764657[0] r=[-1,0,0,0,1]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386589 78.146.26.44:26247 TLS: received control channel packet s#=0 sid=8cbd46a7 a7e8e8d4'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386607 78.146.26.44:26247 ACK received for pid 24, deleting from send buffer'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386640 78.146.26.44:26247 TLS: tls_multi_process: i=0 state=S_SENT_KEY, mysid=e98d7530 1d9d0657, stored-sid=8cbd46a7 a7e8e8d4, stored-ip=[AF_INET]78.146.26.44:26247'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386657 78.146.26.44:26247 TLS: tls_process: chg=0 ks=S_SENT_KEY lame=S_UNDEF to_link->len=0 wakeup=604800'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386673 78.146.26.44:26247 STATE S_ACTIVE'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386705 78.146.26.44:26247 Control Channel: TLSv1, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-SHA, 2048 bit RSA'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386739 78.146.26.44:26247 [twjnorth] Peer Connection Initiated with [AF_INET]78.146.26.44:26247'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386759 78.146.26.44:26247 ACK reliable_can_send active=0 current=0 : [25]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386784 78.146.26.44:26247 TLS: tls_process: chg=1 ks=S_ACTIVE lame=S_UNDEF to_link->len=0 wakeup=604800'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386800 78.146.26.44:26247 ACK reliable_can_send active=0 current=0 : [25]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386816 78.146.26.44:26247 ACK reliable_send_timeout 604800 [25]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386832 78.146.26.44:26247 TLS: tls_process: timeout set to 49'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386853 78.146.26.44:26247 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=ab99dce5 918db688, stored-sid=00000000 00000000, stored-ip=[undef]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=386874 78.146.26.44:26247 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=398633 twjnorth/78.146.26.44:26247 WARNING: Failed running command (--client-connect): could not execute external program'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=398770 STREAM: SET NEXT, buf=[440,0] next=[440,1544] len=-1 maxlen=1544'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=398792 STREAM: SET NEXT, buf=[440,0] next=[440,1544] len=-1 maxlen=1544'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=398806 MULTI TCP: multi_tcp_post TA_SOCKET_READ -> TA_UNDEF'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=398837 EP_CTL fd=3 rwflags=0x0002 ev=0x00000004 arg=0x00000004'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=398875 EP_WAIT[0] rwflags=0x0002 ev=0x00000004 arg=0x00000004'
2015-07-02 01:30:57+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:57 2015 us=398912 EP_CTL fd=3 rwflags=0x0001 ev=0x00000001 arg=0x00000004'
2015-07-02 01:30:58+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:58 2015 us=528119 MULTI: REAP range 336 -> 352'
2015-07-02 01:30:58+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:58 2015 us=528165 MULTI TCP: multi_tcp_action a=TA_TIMEOUT p=0'
2015-07-02 01:30:58+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:58 2015 us=528183 MULTI TCP: multi_tcp_dispatch a=TA_TIMEOUT mi=0x00000000'
2015-07-02 01:30:58+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:58 2015 us=528211 twjnorth/78.146.26.44:26247 TIMER: coarse timer wakeup 1 seconds'
2015-07-02 01:30:58+1000 [-] OVPN 0 OUT: 'Wed Jul 1 15:30:58 2015 us=528259 twjnorth/78.146.26.44:26247 TLS: tls_multi_process: i=0 state=S_ACTIVE, mysid=e98d7530 1d9d0657, stored-sid=8cbd46a7 a7e8e8d4, stored-ip=[AF_INET]78.146.26.44:26247'
