|
|
Greetings We've been debugging our first foray into OpenVPn for the last 48 hours and after scouring the web, FAQ, Mailing Lists etc we're just about ready to ask for help. We have a dual homed linux server on our outer network running openvpn-2.1-0.10.beta14.fc5 and a Win-XP box running openvpn-2.0.7-gui-1.0.3. We've slavishly followed the How-To (a number of times) and this is the result we get with verb = 6. On the start of negotiation on the server: Jun 7 09:06:24 midgard openvpn[3123]: OpenVPN 2.1_beta14 i386-redhat-linux-gnu [SSL] [LZO1] [EPOLL] built on Apr 14 2006 Jun 7 09:06:24 midgard openvpn[3123]: Diffie-Hellman initialized with 1024 bit key Jun 7 09:06:24 midgard openvpn[3123]: TLS-Auth MTU parms [ L:1574 D:138 EF:38 EB:0 ET:0 EL:0 ] Jun 7 09:06:24 midgard openvpn[3123]: TUN/TAP device tap2 opened Jun 7 09:06:24 midgard openvpn[3123]: TUN/TAP TX queue length set to 100 Jun 7 09:06:24 midgard openvpn[3123]: Data Channel MTU parms [ L:1574 D:1450 EF:42 EB:135 ET:32 EL:0 AF:3/1 ] Jun 7 09:06:24 midgard openvpn[3127]: Socket Buffers: R=[107520->131072] S=[107520->131072] Jun 7 09:06:24 midgard openvpn[3127]: UDPv4 link local (bound): [undef]:1194 Jun 7 09:06:24 midgard openvpn[3127]: UDPv4 link remote: [undef] Jun 7 09:06:24 midgard openvpn[3127]: MULTI: multi_init called, r=256 v=256 Jun 7 09:06:24 midgard openvpn[3127]: IFCONFIG POOL: base=192.168.12.250 size=5 Jun 7 09:06:24 midgard openvpn[3127]: IFCONFIG POOL LIST Jun 7 09:06:24 midgard openvpn[3127]: Initialization Sequence Completed Jun 7 09:06:56 midgard openvpn[3127]: MULTI: multi_create_instance called Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 Re-using SSL/TLS context Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 LZO compression initialized Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 Control Channel MTU parms [ L:1574 D:138 EF:38 EB:0 ET:0 EL:0 ] Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 Data Channel MTU parms [ L:1574 D:1450 EF:42 EB:135 ET:32 EL:0 AF:3/1 ] Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 Local Options String: 'V4,dev-type tap,link-mtu 1574,tun-mtu 1532,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server' Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 Expected Remote Options String: 'V4,dev-type tap,link-mtu 1574,tun-mtu 1532,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client' Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 Local Options hash (VER=V4): 'f7df56b8' Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 Expected Remote Options hash (VER=V4): 'd79ca330' Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 READ [14] from 58.171.62.22:1301: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 TLS: Initial packet from 58.171.62.22:1301, sid=2d14972e e10d0b70 Jun 7 09:06:56 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 WRITE [26] to 58.171.62.22:1301: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ 0 ] pid=0 DATA len=0 Jun 7 09:06:58 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 WRITE [14] to 58.171.62.22:1301: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0 Jun 7 09:06:58 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 READ [14] from 58.171.62.22:1301: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Jun 7 09:06:58 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 WRITE [22] to 58.171.62.22:1301: P_ACK_V1 kid=0 [ 0 ] Jun 7 09:07:00 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 WRITE [14] to 58.171.62.22:1301: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0 Jun 7 09:07:01 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 READ [14] from 58.171.62.22:1301: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Jun 7 09:07:01 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 WRITE [22] to 58.171.62.22:1301: P_ACK_V1 kid=0 [ 0 ] Jun 7 09:07:02 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 WRITE [14] to 58.171.62.22:1301: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0 Jun 7 09:07:02 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 READ [14] from 58.171.62.22:1301: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Jun 7 09:07:02 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 WRITE [22] to 58.171.62.22:1301: P_ACK_V1 kid=0 [ 0 ] This is repeated until finally we get: Jun 7 09:07:55 midgard openvpn[3127]: 58.171.62.22:1301 UDPv4 WRITE [14] to 58.171.62.22:1301: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 [ ] pid=0 DATA len=0 Jun 7 09:07:57 midgard openvpn[3127]: 58.171.62.22:1301 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity) Jun 7 09:07:57 midgard openvpn[3127]: 58.171.62.22:1301 TLS Error: TLS handshake failed Jun 7 09:07:57 midgard openvpn[3127]: 58.171.62.22:1301 SIGUSR1[soft,tls-error] received, client-instance restarting Whilst on the client we get: Wed Jun 07 08:59:30 2006 us=719830 OpenVPN 2.0.7 Win32-MinGW [SSL] [LZO] built on Apr 12 2006 Wed Jun 07 08:59:30 2006 us=719929 IMPORTANT: OpenVPN's default port number is now 1194, based on an official port number assignment by IANA. OpenVPN 2.0-beta16 and earlier used 5000 as the default port. Wed Jun 07 08:59:30 2006 us=719943 WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info. Wed Jun 07 08:59:30 2006 us=733691 LZO compression initialized Wed Jun 07 08:59:30 2006 us=733786 Control Channel MTU parms [ L:1574 D:138 EF:38 EB:0 ET:0 EL:0 ] Wed Jun 07 08:59:30 2006 us=736966 Data Channel MTU parms [ L:1574 D:1450 EF:42 EB:135 ET:32 EL:0 AF:3/1 ] Wed Jun 07 08:59:30 2006 us=737005 Local Options String: 'V4,dev-type tap,link-mtu 1574,tun-mtu 1532,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client' Wed Jun 07 08:59:30 2006 us=737017 Expected Remote Options String: 'V4,dev-type tap,link-mtu 1574,tun-mtu 1532,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server' Wed Jun 07 08:59:30 2006 us=737045 Local Options hash (VER=V4): 'd79ca330' Wed Jun 07 08:59:30 2006 us=737061 Expected Remote Options hash (VER=V4): 'f7df56b8' Wed Jun 07 08:59:30 2006 us=737089 Socket Buffers: R=[8192->8192] S=[8192->8192] Wed Jun 07 08:59:30 2006 us=737105 UDPv4 link local: [undef] Wed Jun 07 08:59:30 2006 us=747127 UDPv4 link remote: 203.47.236.87:1194 Wed Jun 07 08:59:30 2006 us=747195 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:30 2006 us=781695 UDPv4 READ [-1] from [undef]: DATA UNDEF len=-1 Wed Jun 07 08:59:33 2006 us=290089 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:35 2006 us=801675 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:37 2006 us=58680 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:39 2006 us=569691 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:41 2006 us=873038 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:43 2006 us=969268 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:46 2006 us=65409 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:48 2006 us=161094 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:50 2006 us=257061 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:52 2006 us=710610 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:55 2006 us=166441 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 08:59:57 2006 us=619270 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 09:00:00 2006 us=72412 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 09:00:02 2006 us=165767 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Wed Jun 07 09:00:04 2006 us=259455 UDPv4 WRITE [14] to 203.47.236.87:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 [ ] pid=0 DATA len=0 Until we eventually get: Wed Jun 07 09:02:34 2006 us=765512 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity) Wed Jun 07 09:02:34 2006 us=765564 TLS Error: TLS handshake failed Wed Jun 07 09:02:34 2006 us=777209 TCP/UDP: Closing socket Wed Jun 07 09:02:34 2006 us=783083 SIGUSR1[soft,tls-error] received, process restarting Wed Jun 07 09:02:34 2006 us=783120 Restart pause, 2 second(s) Given by very scanty knowledge of OpenVPN and networking in general, there seems to be a blockage from the server in that writes from there are not reaching the client. So far, in the name of testing, we have: A) stopped iptables on the linux server. B) stopped all firewalling on the XP box C) made sure there are no firewall rules on the ADSL router that could interfere with the outgoing packets. Does anyone have any suggestions as to: A) Where the problem might be? B) Any debugging methods we could adopt to perhaps trace the packets from the server and see where they are being dropped? Any suggestions (short of taxidermy) would be gratefully received. TIA and Regards Nigel. Nigel Allen Senior Consultant Temisoft IT Phone: +61 2 9487 8188 Web: www.temisoftit.com.au Visit our online store at http://store.temisoftit.com.au for all your computer needs -- This message has been scanned for viruses and dangerous content by MailScanner, and is believed to be clean. _______________________________________________ Openvpn-users mailing list Openvpn-users@xxxxxxxxxxxxxxxxxxxxx https://lists.sourceforge.net/lists/listinfo/openvpn-users |