|
From: Ralf H. <Ral...@ch...> - 2008-01-02 22:21:43
|
* Ralf Hildebrandt <Ral...@ch...>: > I'm debugging a strange "connection hanging" problem with our openvpn > setup here. Sometimes, the VPN connection would hang (no packet goes > through for about 10 seconds, according to the mtr output) > > One thing I noticed is that the connection is "hanging" whenever I see > this in the log: > > Jan 2 23:01:35 vpn-gw-int ovpn-server[12799]: aweima.vpn.charite.de/91.63.211.238:62245 PUSH: Received control message: 'PUSH_REQUEST' > Jan 2 23:01:35 vpn-gw-int ovpn-server[12799]: aweima.vpn.charite.de/91.63.211.238:62245 PUSH: Received control message: 'PUSH_REQUEST' > Jan 2 23:01:35 vpn-gw-int ovpn-server[12799]: aweima.vpn.charite.de/91.63.211.238:62245 PUSH: Received control message: 'PUSH_REQUEST' > Jan 2 23:01:36 vpn-gw-int ovpn-server[12799]: aweima.vpn.charite.de/91.63.211.238:62245 PUSH: Received control message: 'PUSH_REQUEST' > > (I didn't duplicate the lines, they were logged that way!) > > I'm seeing this with some clients only: > > Jan 2 23:03:50 vpn-gw-int ovpn-server[12799]: brost.vpn.charite.de/87.185.222.132:1155 PUSH: Received control message: 'PUSH_REQUEST' > Jan 2 23:03:50 vpn-gw-int ovpn-server[12799]: brost.vpn.charite.de/87.185.222.132:1155 PUSH: Received control message: 'PUSH_REQUEST' > Jan 2 23:03:50 vpn-gw-int ovpn-server[12799]: brost.vpn.charite.de/87.185.222.132:1155 PUSH: Received control message: 'PUSH_REQUEST' > Jan 2 23:03:50 vpn-gw-int ovpn-server[12799]: brost.vpn.charite.de/87.185.222.132:1155 PUSH: Received control message: 'PUSH_REQUEST' That user sent me his client's log: Wed Jan 02 23:03:19 2008 OpenVPN 2.0.9 Win32-MinGW [SSL] [LZO] built on Oct 1 2006 Wed Jan 02 23:03:25 2008 LZO compression initialized Wed Jan 02 23:03:25 2008 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ] Wed Jan 02 23:03:26 2008 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ] Wed Jan 02 23:03:26 2008 Local Options hash (VER=V4): '41690919' Wed Jan 02 23:03:26 2008 Expected Remote Options hash (VER=V4): '530fdded' Wed Jan 02 23:03:26 2008 UDPv4 link local: [undef] Wed Jan 02 23:03:26 2008 UDPv4 link remote: 193.175.73.100:1194 Wed Jan 02 23:03:26 2008 TLS: Initial packet from 193.175.73.100:1194, sid=132c8828 9699c433 Wed Jan 02 23:03:30 2008 VERIFY OK: depth=1, /C=DE/ST=BERLIN/L=BERLIN/O=OpenVPN-Charite/CN=OpenVPN-Charite-CA/ema...@ch... Wed Jan 02 23:03:30 2008 VERIFY OK: depth=0, /C=DE/ST=BERLIN/O=OpenVPN-Charite/CN=server/ema...@ch... Wed Jan 02 23:03:35 2008 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key Wed Jan 02 23:03:35 2008 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication Wed Jan 02 23:03:35 2008 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key Wed Jan 02 23:03:35 2008 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication Wed Jan 02 23:03:35 2008 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA Wed Jan 02 23:03:35 2008 [server] Peer Connection Initiated with 193.175.73.100:1194 Wed Jan 02 23:03:36 2008 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1) Wed Jan 02 23:03:41 2008 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1) Wed Jan 02 23:03:47 2008 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1) Wed Jan 02 23:03:51 2008 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1) Wed Jan 02 23:03:51 2008 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 193.175.66.33,dhcp-option DNS 193.175.70.246,dhcp-option DOMAIN charite.de,dhcp-option WINS 10.47.2.200,dhcp-option WINS 141.42.111.210,dhcp-option WINS 10.43.120.59,route 172.28.0.1,ping 10,ping-restart 120,redirect-gateway,ifconfig 172.28.20.69 172.28.20.70' Wed Jan 02 23:03:51 2008 OPTIONS IMPORT: timers and/or timeouts modified Wed Jan 02 23:03:51 2008 OPTIONS IMPORT: --ifconfig/up options modified Wed Jan 02 23:03:51 2008 OPTIONS IMPORT: route options modified Wed Jan 02 23:03:51 2008 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified Wed Jan 02 23:03:51 2008 TAP-WIN32 device [LAN-Verbindung 2] opened: \\.\Global\{7B4C4494-0C33-47C0-BD61-10817BBD2D42}.tap Wed Jan 02 23:03:51 2008 TAP-Win32 Driver Version 8.4 Wed Jan 02 23:03:51 2008 TAP-Win32 MTU=1500 Wed Jan 02 23:03:51 2008 Notified TAP-Win32 driver to set a DHCP IP/netmask of 172.28.20.69/255.255.255.252 on interface {7B4C4494-0C33-47C0-BD61-10817BBD2D42} [DHCP-serv: 172.28.20.70, lease-time: 31536000] Wed Jan 02 23:03:51 2008 Successful ARP Flush on interface [2] {7B4C4494-0C33-47C0-BD61-10817BBD2D42} Wed Jan 02 23:03:51 2008 TEST ROUTES: 0/0 succeeded len=1 ret=0 a=0 u/d=down Wed Jan 02 23:03:51 2008 Route: Waiting for TUN/TAP interface to come up... Wed Jan 02 23:03:51 2008 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 193.175.66.33,dhcp-option DNS 193.175.70.246,dhcp-option DOMAIN charite.de,dhcp-option WINS 10.47.2.200,dhcp-option WINS 141.42.111.210,dhcp-option WINS 10.43.120.59,route 172.28.0.1,ping 10,ping-restart 120,redirect-gateway,ifconfig 172.28.20.69 172.28.20.70' Wed Jan 02 23:03:51 2008 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 193.175.66.33,dhcp-option DNS 193.175.70.246,dhcp-option DOMAIN charite.de,dhcp-option WINS 10.47.2.200,dhcp-option WINS 141.42.111.210,dhcp-option WINS 10.43.120.59,route 172.28.0.1,ping 10,ping-restart 120,redirect-gateway,ifconfig 172.28.20.69 172.28.20.70' Wed Jan 02 23:03:51 2008 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 193.175.66.33,dhcp-option DNS 193.175.70.246,dhcp-option DOMAIN charite.de,dhcp-option WINS 10.47.2.200,dhcp-option WINS 141.42.111.210,dhcp-option WINS 10.43.120.59,route 172.28.0.1,ping 10,ping-restart 120,redirect-gateway,ifconfig 172.28.20.69 172.28.20.70' Wed Jan 02 23:03:53 2008 TEST ROUTES: 0/0 succeeded len=1 ret=0 a=0 u/d=down Wed Jan 02 23:03:53 2008 Route: Waiting for TUN/TAP interface to come up... Wed Jan 02 23:03:54 2008 TEST ROUTES: 0/0 succeeded len=1 ret=0 a=0 u/d=down Wed Jan 02 23:03:54 2008 Route: Waiting for TUN/TAP interface to come up... Wed Jan 02 23:03:55 2008 TEST ROUTES: 0/0 succeeded len=1 ret=0 a=0 u/d=down Wed Jan 02 23:03:55 2008 Route: Waiting for TUN/TAP interface to come up... Wed Jan 02 23:03:56 2008 TEST ROUTES: 0/0 succeeded len=1 ret=0 a=0 u/d=down Wed Jan 02 23:03:56 2008 Route: Waiting for TUN/TAP interface to come up... Wed Jan 02 23:03:57 2008 TEST ROUTES: 2/2 succeeded len=1 ret=1 a=0 u/d=up Wed Jan 02 23:03:57 2008 route ADD 193.175.73.100 MASK 255.255.255.255 192.168.2.1 Wed Jan 02 23:03:57 2008 Route addition via IPAPI succeeded Wed Jan 02 23:03:57 2008 route DELETE 0.0.0.0 MASK 0.0.0.0 192.168.2.1 Wed Jan 02 23:03:58 2008 Route deletion via IPAPI succeeded Wed Jan 02 23:03:58 2008 route ADD 0.0.0.0 MASK 0.0.0.0 172.28.20.70 Wed Jan 02 23:03:58 2008 Route addition via IPAPI succeeded Wed Jan 02 23:03:58 2008 route ADD 172.28.0.1 MASK 255.255.255.255 172.28.20.70 Wed Jan 02 23:03:58 2008 Route addition via IPAPI succeeded Wed Jan 02 23:03:58 2008 Initialization Sequence Completed -- Ralf Hildebrandt (i.A. des IT-Zentrums) Ral...@ch... Charite - Universitätsmedizin Berlin Tel. +49 (0)30-450 570-155 Gemeinsame Einrichtung von FU- und HU-Berlin Fax. +49 (0)30-450 570-962 IT-Zentrum Standort CBF send no mail to pl...@ch... |