id summary reporter owner description type status priority milestone component version severity resolution keywords cc 558 problem after server restart - client doesn't accept new ip leshik "When openvpn server restarts, in some cases some clients don't change their IPs to the new ones assigned by server, but still routinely exchange keepalives and think everything is ok (however, data packets aren't transmitted or received). The problem occurs rarely and is hard to catch. Below is my server log cleaned up to one of that particular client. This is the initial connection by 1-st client (note it's IP address 10.9.3.70): May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 Re-using SSL/TLS context May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 LZO compression initialized May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 Control Channel MTU parms [ L:1546 D:138 EF:38 EB:0 ET:0 EL:0 ] May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 Data Channel MTU parms [ L:1546 D:1200 EF:46 EB:135 ET:0 EL:0 AF:3/1 ] May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 Fragmentation MTU parms [ L:1546 D:1200 EF:45 EB:135 ET:1 EL:0 AF:3/1 ] May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 Local Options String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server' May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client' May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 Local Options hash (VER=V4): '8e7959c7' May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 Expected Remote Options hash (VER=V4): 'c086e1aa' May 29 09:59:53 www ovpn-server1[21681]: 89.151.172.78:10002 TLS: Initial packet from [AF_INET]89.151.172.78:10002, sid=48c7d4e6 d6477d7d May 29 09:59:55 www ovpn-server1[21681]: 89.151.172.78:10002 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden] May 29 09:59:55 www ovpn-server1[21681]: 89.151.172.78:10002 VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden] May 29 09:59:55 www ovpn-server1[21681]: 89.151.172.78:10002 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=69bd6a89-aeaf-4d10-bf74-0e53facb9d69 May 29 09:59:55 www ovpn-server1[21681]: 89.151.172.78:10002 VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=69bd6a89-aeaf-4d10-bf74-0e53facb9d69 May 29 09:59:56 www ovpn-server1[21681]: 89.151.172.78:10002 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key May 29 09:59:56 www ovpn-server1[21681]: 89.151.172.78:10002 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication May 29 09:59:56 www ovpn-server1[21681]: 89.151.172.78:10002 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key May 29 09:59:56 www ovpn-server1[21681]: 89.151.172.78:10002 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication May 29 09:59:56 www ovpn-server1[21681]: 89.151.172.78:10002 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA May 29 09:59:56 www ovpn-server1[21681]: 89.151.172.78:10002 [69bd6a89-aeaf-4d10-bf74-0e53facb9d69] Peer Connection Initiated with [AF_INET]89.151.172.78:10002 May 29 09:59:56 www ovpn-server1[21681]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:10002 MULTI_sva: pool returned IPv4=10.9.3.70, IPv6=(Not enabled) May 29 09:59:56 www ovpn-server1[21681]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:10002 MULTI: Learn: 10.9.3.70 -> 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:10002 May 29 09:59:56 www ovpn-server1[21681]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:10002 MULTI: primary virtual IP for 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:10002: 10.9.3.70 May 29 09:59:58 www ovpn-server1[21681]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:10002 PUSH: Received control message: 'PUSH_REQUEST' May 29 09:59:58 www ovpn-server1[21681]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:10002 send_push_reply(): safe_cap=940 May 29 09:59:58 www ovpn-server1[21681]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:10002 SENT CONTROL [69bd6a89-aeaf-4d10-bf74-0e53facb9d69]: 'PUSH_REPLY,route 10.8.0.0 255.255.0.0,route 91.189.94.4 255.255.255.255,route 91.189.89.199 255.255.255.255,route 194.186.207.162 255.255.255.255,route 10.9.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.9.3.70 10.9.3.69' (status=1) Here is server restart occurs (notice PID change) May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 Re-using SSL/TLS context May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 LZO compression initialized May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 Control Channel MTU parms [ L:1546 D:138 EF:38 EB:0 ET:0 EL:0 ] May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 Data Channel MTU parms [ L:1546 D:1200 EF:46 EB:135 ET:0 EL:0 AF:3/1 ] May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 Fragmentation MTU parms [ L:1546 D:1200 EF:45 EB:135 ET:1 EL:0 AF:3/1 ] May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 Local Options String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server' May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client' May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 Local Options hash (VER=V4): '8e7959c7' May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 Expected Remote Options hash (VER=V4): 'c086e1aa' May 30 04:01:59 www ovpn-server1[6896]: 89.151.172.78:21430 TLS: Initial packet from [AF_INET]89.151.172.78:21430, sid=2e03d667 4ec4a92f May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden] May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden] May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=69bd6a89-aeaf-4d10-bf74-0e53facb9d69 May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=69bd6a89-aeaf-4d10-bf74-0e53facb9d69 May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA May 30 04:02:01 www ovpn-server1[6896]: 89.151.172.78:21430 [69bd6a89-aeaf-4d10-bf74-0e53facb9d69] Peer Connection Initiated with [AF_INET]89.151.172.78:21430 May 30 04:02:01 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 MULTI_sva: pool returned IPv4=10.9.0.242, IPv6=(Not enabled) May 30 04:02:01 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 MULTI: Learn: 10.9.0.242 -> 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 New address assigned May 30 04:02:01 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 MULTI: primary virtual IP for 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430: 10.9.0.242 Another client connecting May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 Re-using SSL/TLS context May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 LZO compression initialized May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 Control Channel MTU parms [ L:1546 D:138 EF:38 EB:0 ET:0 EL:0 ] May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 Data Channel MTU parms [ L:1546 D:1200 EF:46 EB:135 ET:0 EL:0 AF:3/1 ] May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 Fragmentation MTU parms [ L:1546 D:1200 EF:45 EB:135 ET:1 EL:0 AF:3/1 ] May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 Local Options String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server' May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1546,tun-mtu 1500,proto UDPv4,comp-lzo,mtu-dynamic,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client' May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 Local Options hash (VER=V4): '8e7959c7' May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 Expected Remote Options hash (VER=V4): 'c086e1aa' May 30 04:02:04 www ovpn-server1[6896]: 188.133.184.6:50152 TLS: Initial packet from [AF_INET]188.133.184.6:50152, sid=444dad21 593d95fa May 30 04:02:11 www ovpn-server1[6896]: 188.133.184.6:50152 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden] May 30 04:02:11 www ovpn-server1[6896]: 188.133.184.6:50152 VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden] May 30 04:02:11 www ovpn-server1[6896]: 188.133.184.6:50152 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=8cde99a0-be9d-422b-8c6a-753095c5df87 May 30 04:02:11 www ovpn-server1[6896]: 188.133.184.6:50152 VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=8cde99a0-be9d-422b-8c6a-753095c5df87 May 30 04:02:11 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 TLS Error: local/remote TLS keys are out of sync: [AF_INET]89.151.172.78:21430 [3] May 30 04:02:12 www ovpn-server1[6896]: 188.133.184.6:50152 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key May 30 04:02:12 www ovpn-server1[6896]: 188.133.184.6:50152 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication May 30 04:02:12 www ovpn-server1[6896]: 188.133.184.6:50152 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key May 30 04:02:12 www ovpn-server1[6896]: 188.133.184.6:50152 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication May 30 04:02:12 www ovpn-server1[6896]: 188.133.184.6:50152 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA May 30 04:02:12 www ovpn-server1[6896]: 188.133.184.6:50152 [8cde99a0-be9d-422b-8c6a-753095c5df87] Peer Connection Initiated with [AF_INET]188.133.184.6:50152 May 30 04:02:12 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 MULTI_sva: pool returned IPv4=10.9.3.70, IPv6=(Not enabled) May 30 04:02:12 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 MULTI: Learn: 10.9.3.70 -> 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 The original IP of first client assigned to another client May 30 04:02:12 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 MULTI: primary virtual IP for 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152: 10.9.3.70 May 30 04:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 PUSH: Received control message: 'PUSH_REQUEST' May 30 04:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 send_push_reply(): safe_cap=940 May 30 04:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 SENT CONTROL [8cde99a0-be9d-422b-8c6a-753095c5df87]: 'PUSH_REPLY,route 10.8.0.0 255.255.0.0,route 91.189.94.4 255.255.255.255,route 91.189.89.199 255.255.255.255,route 194.186.207.162 255.255.255.255,route 10.9.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.9.3.70 10.9.3.69' (status=1) May 30 04:02:14 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 TLS Error: local/remote TLS keys are out of sync: [AF_INET]89.151.172.78:21430 [3] May 30 04:02:15 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 TLS Error: local/remote TLS keys are out of sync: [AF_INET]89.151.172.78:21430 [3] May 30 04:02:17 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 TLS Error: local/remote TLS keys are out of sync: [AF_INET]89.151.172.78:21430 [3] May 30 04:02:21 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 TLS Error: local/remote TLS keys are out of sync: [AF_INET]89.151.172.78:21430 [3] May 30 04:02:29 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 TLS Error: local/remote TLS keys are out of sync: [AF_INET]89.151.172.78:21430 [3] May 30 04:02:39 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 TLS Error: local/remote TLS keys are out of sync: [AF_INET]89.151.172.78:21430 [3] May 30 04:02:45 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 TLS Error: local/remote TLS keys are out of sync: [AF_INET]89.151.172.78:21430 [3] May 30 04:02:55 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 TLS Error: local/remote TLS keys are out of sync: [AF_INET]89.151.172.78:21430 [3] May 30 04:03:17 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 MULTI: bad source address from client [10.9.3.70], packet dropped May 30 04:03:17 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 MULTI: bad source address from client [10.9.3.70], packet dropped May 30 04:04:21 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 MULTI: bad source address from client [10.9.3.70], packet dropped May 30 04:04:22 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 MULTI: bad source address from client [10.9.3.70], packet dropped May 30 04:04:24 www ovpn-server1[6896]: 69bd6a89-aeaf-4d10-bf74-0e53facb9d69/89.151.172.78:21430 MULTI: bad source address from client [10.9.3.70], packet dropped ... etc. (this message lasts forever until the client gets killed) May 30 05:02:12 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 TLS: soft reset sec=0 bytes=2799031/0 pkts=6706/0 May 30 05:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden] May 30 05:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden] May 30 05:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=8cde99a0-be9d-422b-8c6a-753095c5df87 May 30 05:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=8cde99a0-be9d-422b-8c6a-753095c5df87 May 30 05:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key May 30 05:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication May 30 05:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key May 30 05:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication May 30 05:02:14 www ovpn-server1[6896]: 8cde99a0-be9d-422b-8c6a-753095c5df87/188.133.184.6:50152 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA There is nothing special in logs at the client side. More info in this forum thread: https://forums.openvpn.net/topic18311.html" Bug / Defect new major Networking OpenVPN 2.3.2 (Community Ed) Not set (select this one, unless your'e a OpenVPN developer) Steffan Karger tct