[OpenVPN home] [Date Prev] [Date Index] [Date Next]
[OpenVPN mailing lists] [Thread Prev] [Thread Index] [Thread Next]
Google
 
Web openvpn.net

[Openvpn-users] Troubleshooting OpenVPN client at inaccessible remote site


  • Subject: [Openvpn-users] Troubleshooting OpenVPN client at inaccessible remote site
  • From: Drew Gibson <drew@xxxxxxxxx>
  • Date: Mon, 29 Oct 2007 15:07:46 -0400

Dear List,

I recently sent a router running OpenVPN client (on OpenWRT) to our new 
office in Singapore. The router was configured and tested in Toronto, 
shipped to Singapore, installed and tested OK. We had a solid OpenVPN 
connection back to the Toronto server. Port 1194 is forwarded from our 
firewall to the internal OpenVPN server. SSH was disabled on the 
router's external interface once the OpenVPN tunnel was up and running.

Our new office (in Singapore) was moved from temporary to more permanent 
space, including relocation of the Internet connection and router. The 
router is no longer able to establish a full connection with the server 
(logs and details below). We are not aware of any changes to the 
firewall or server at the Toronto end.

My challenge is that I have no technical resource in Singapore and do 
not know enough about OpenVPN internals to infer where the failure lies 
from the logs.

I have used OpenVPN for several years at home and in multiple commercial 
installations without significant problems. Google searches produced 
more pages of source code than real world issues.
Any pointers or assistance in narrowing down the actual issue would be 
appreciated.

regards,

Drew


server log (verb 3):-

Mon Oct 29 14:46:11 2007 MULTI: multi_create_instance called
Mon Oct 29 14:46:11 2007 Re-using SSL/TLS context
Mon Oct 29 14:46:11 2007 LZO compression initialized
Mon Oct 29 14:46:11 2007 Control Channel MTU parms [ L:1544 D:140 EF:40 
EB:0 ET:
0 EL:0 ]
Mon Oct 29 14:46:11 2007 Data Channel MTU parms [ L:1544 D:1450 EF:44 
EB:135 ET:
0 EL:0 AF:3/1 ]
Mon Oct 29 14:46:11 2007 Local Options hash (VER=V4): 'c0103fa8'
Mon Oct 29 14:46:11 2007 Expected Remote Options hash (VER=V4): '69109d17'
Mon Oct 29 14:46:11 2007 TCP connection established with 
nnn.zzz.yyy.xxx:3991
Mon Oct 29 14:46:11 2007 TCPv4_SERVER link local: [undef]
Mon Oct 29 14:46:11 2007 TCPv4_SERVER link remote: nnn.zzz.yyy.xxx:3991
Mon Oct 29 14:46:11 2007 nnn.zzz.yyy.xxx:3991 TLS: Initial packet from 
nnn.zzz.yyy.xxx:3991, sid=0ed9ec8d 04be5d9a
Mon Oct 29 14:46:16 2007 nnn.zzz.yyy.xxx:3991 Connection reset, 
restarting [0]
Mon Oct 29 14:46:16 2007 nnn.zzz.yyy.xxx:3991 
SIGUSR1[soft,connection-reset] rece
ived, client-instance restarting
Mon Oct 29 14:46:16 2007 TCP/UDP: Closing socket

...repeats after 5 seconds....

server.log (verb 6)

Mon Oct 29 14:48:11 2007 us=589149 MULTI: multi_create_instance called
Mon Oct 29 14:48:11 2007 us=589224 Re-using SSL/TLS context
Mon Oct 29 14:48:11 2007 us=589263 LZO compression initialized
Mon Oct 29 14:48:11 2007 us=589420 Control Channel MTU parms [ L:1544 
D:140 EF:40 EB:0 ET:0 EL:0 ]
Mon Oct 29 14:48:11 2007 us=589457 Data Channel MTU parms [ L:1544 
D:1450 EF:44 EB:135 ET:0 EL:0 AF:3/1 ]
Mon Oct 29 14:48:11 2007 us=589515 Local Options String: 'V4,dev-type 
tun,link-mtu 1544,tun-mtu 1500,proto TCPv4_SERVER,comp-lzo,cipher 
BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Mon Oct 29 14:48:11 2007 us=589532 Expected Remote Options String: 
'V4,dev-type tun,link-mtu 1544,tun-mtu 1500,proto 
TCPv4_CLIENT,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 
2,tls-client'
Mon Oct 29 14:48:11 2007 us=589568 Local Options hash (VER=V4): 'c0103fa8'
Mon Oct 29 14:48:11 2007 us=589595 Expected Remote Options hash 
(VER=V4): '69109d17'
Mon Oct 29 14:48:11 2007 us=589634 TCP connection established with 
nnn.zzz.yyy.xxx:4011
Mon Oct 29 14:48:11 2007 us=589677 Socket Buffers: R=[131072->131072] 
S=[131072->131072]
Mon Oct 29 14:48:11 2007 us=589710 TCPv4_SERVER link local: [undef]
Mon Oct 29 14:48:11 2007 us=589738 TCPv4_SERVER link remote: 
nnn.zzz.yyy.xxx:4011
Mon Oct 29 14:48:11 2007 us=589952 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [14] to nnn.zzz.yyy.xxx:4011: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 
[ ] pid=0 DATA len=0
Mon Oct 29 14:48:11 2007 us=590027 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [14] from nnn.zzz.yyy.xxx:4011: P_CONTROL_HARD_RESET_CLIENT_V2 
kid=0 [ ] pid=0 DATA len=0
Mon Oct 29 14:48:11 2007 us=590075 nnn.zzz.yyy.xxx:4011 TLS: Initial 
packet from nnn.zzz.yyy.xxx:4011, sid=fd591d08 75731378
Mon Oct 29 14:48:11 2007 us=590121 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [26] to nnn.zzz.yyy.xxx:4011: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 
[ 0 ] pid=0 DATA len=0
Mon Oct 29 14:48:11 2007 us=873662 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [26] from nnn.zzz.yyy.xxx:4011: P_CONTROL_HARD_RESET_CLIENT_V2 
kid=0 [ 0 ] pid=0 DATA len=0
Mon Oct 29 14:48:11 2007 us=873758 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [22] to nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 0 ]
Mon Oct 29 14:48:12 2007 us=196971 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 0 ]
Mon Oct 29 14:48:12 2007 us=197067 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [98] from nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=1 DATA 
len=84
Mon Oct 29 14:48:12 2007 us=215856 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [126] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ 1 ] pid=1 DATA 
len=100
Mon Oct 29 14:48:12 2007 us=215923 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=2 DATA 
len=100
Mon Oct 29 14:48:12 2007 us=215982 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=3 DATA 
len=100
Mon Oct 29 14:48:12 2007 us=216037 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=4 DATA 
len=100
Mon Oct 29 14:48:12 2007 us=768896 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 1 ]
Mon Oct 29 14:48:12 2007 us=769011 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=5 DATA 
len=100
Mon Oct 29 14:48:13 2007 us=62102 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER READ 
[30] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 2 3 4 ]
Mon Oct 29 14:48:13 2007 us=62225 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=6 DATA 
len=100
Mon Oct 29 14:48:13 2007 us=62349 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=7 DATA 
len=100
Mon Oct 29 14:48:13 2007 us=62444 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=8 DATA 
len=100
Mon Oct 29 14:48:13 2007 us=390663 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 5 ]
Mon Oct 29 14:48:13 2007 us=390783 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=9 DATA 
len=100
Mon Oct 29 14:48:13 2007 us=676009 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 6 ]
Mon Oct 29 14:48:13 2007 us=676123 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=10 DATA 
len=100
Mon Oct 29 14:48:13 2007 us=676174 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [26] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 7 8 ]
Mon Oct 29 14:48:13 2007 us=676246 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=11 DATA 
len=100
Mon Oct 29 14:48:13 2007 us=676300 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=12 DATA 
len=100
Mon Oct 29 14:48:13 2007 us=969565 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 9 ]
Mon Oct 29 14:48:13 2007 us=969661 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=13 DATA 
len=100
Mon Oct 29 14:48:14 2007 us=256026 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 10 ]
Mon Oct 29 14:48:14 2007 us=256136 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=14 DATA 
len=100
Mon Oct 29 14:48:14 2007 us=256191 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [26] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 11 12 ]
Mon Oct 29 14:48:14 2007 us=256250 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=15 DATA 
len=100
Mon Oct 29 14:48:14 2007 us=256303 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=16 DATA 
len=100
Mon Oct 29 14:48:14 2007 us=552976 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 13 ]
Mon Oct 29 14:48:14 2007 us=553056 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=17 DATA 
len=100
Mon Oct 29 14:48:14 2007 us=841565 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 14 ]
Mon Oct 29 14:48:14 2007 us=841668 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=18 DATA 
len=100
Mon Oct 29 14:48:15 2007 us=128401 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 15 ]
Mon Oct 29 14:48:15 2007 us=128497 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=19 DATA 
len=100
Mon Oct 29 14:48:15 2007 us=128545 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 16 ]
Mon Oct 29 14:48:15 2007 us=128608 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=20 DATA 
len=100
Mon Oct 29 14:48:15 2007 us=412105 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 17 ]
Mon Oct 29 14:48:15 2007 us=412207 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=21 DATA 
len=100
Mon Oct 29 14:48:15 2007 us=696577 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
READ [22] from nnn.zzz.yyy.xxx:4011: P_ACK_V1 kid=0 [ 18 ]
Mon Oct 29 14:48:15 2007 us=696682 nnn.zzz.yyy.xxx:4011 TCPv4_SERVER 
WRITE [114] to nnn.zzz.yyy.xxx:4011: P_CONTROL_V1 kid=0 [ ] pid=22 DATA 
len=100
Mon Oct 29 14:48:15 2007 us=715521 nnn.zzz.yyy.xxx:4011 Connection 
reset, restarting [0]
Mon Oct 29 14:48:15 2007 us=715544 nnn.zzz.yyy.xxx:4011 
SIGUSR1[soft,connection-reset] received, client-instance restarting
Mon Oct 29 14:48:15 2007 us=715691 TCP/UDP: Closing socket
Mon Oct 29 14:48:21 2007 us=43323 MULTI: multi_create_instance called

...repeats after 5 seconds....


server OS:-   Fedora Core 4
OpenVPN server:- openvpn-2.0.9-1.fc4.rf.rpm

client OS:- OpenWRT White Russian on Linksys WRT54GL
OpenVPN client:- openvpn - 2.0.8-1

server.conf

local 10.xx.1.1
port 1194
proto tcp
dev tun
ca /etc/openvpn/easy-rsa/keys/ca.crt
cert /etc/openvpn/easy-rsa/keys/xxxxx.crt
key /etc/openvpn/easy-rsa/keys/xxxxx.key  # This file should be kept secret
dh /etc/openvpn/easy-rsa/keys/dh1024.pem
server 10.xx.2.0 255.255.255.0
ifconfig-pool-persist ipp.txt
push "route 10.xx.1.0 255.255.255.0"
client-config-dir ccd
route 10.xx.3.0 255.255.255.0
keepalive 10 120
comp-lzo
user nobody
group nobody
persist-key
persist-tun
status openvpn-status.log
verb 3


ccd/singapore

iroute 10.xx.3.0 255.255.255.0
ifconfig-push 10.xx.2.6 10.xx.2.5


client.conf

client
dev tun
proto tcp
remote xx.yy.zz.nn
resolv-retry infinite
nobind
user nobody
group nogroup
persist-key
persist-tun
ca ca.crt
cert xxxxx.crt
key xxxxx.key
comp-lzo
verb 3


-- 
Drew Gibson

Systems Administrator

____________________________________________
Openvpn-users mailing list
Openvpn-users@xxxxxxxxxxxxxxxxxxxxx
https://lists.sourceforge.net/lists/listinfo/openvpn-users