leshik
Hi,
I'm seeing strange behavior with some clients when openvpn server is restarted. Client doesn't change it's IP to new one assigned by server, but still routinely exchange keepalives and thinks everything is ok (however, data packets aren't transmitted or received).
Here is my server log cleaned up to that particular client:
This is initial connection by 1st client (note it's IP address 10.9.2.2)
Feb 27 13:02:08 www ovpn-server1[23154]: 95.78.118.23:48612 TLS: Initial packet from [AF_INET]95.78.118.23:48612, sid=3131a981 13ecb0c8
Feb 27 13:02:13 www ovpn-server1[23154]: 95.78.118.23:48612 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Feb 27 13:02:13 www ovpn-server1[23154]: 95.78.118.23:48612 VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Feb 27 13:02:13 www ovpn-server1[23154]: 95.78.118.23:48612 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=164410db-b350-4a2b-bf89-8bcdaa5ead29
Feb 27 13:02:13 www ovpn-server1[23154]: 95.78.118.23:48612 VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=164410db-b350-4a2b-bf89-8bcdaa5ead29
Feb 27 13:02:14 www ovpn-server1[23154]: 95.78.118.23:48612 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Feb 27 13:02:14 www ovpn-server1[23154]: 95.78.118.23:48612 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Feb 27 13:02:14 www ovpn-server1[23154]: 95.78.118.23:48612 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Feb 27 13:02:14 www ovpn-server1[23154]: 95.78.118.23:48612 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Feb 27 13:02:14 www ovpn-server1[23154]: 95.78.118.23:48612 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Feb 27 13:02:14 www ovpn-server1[23154]: 95.78.118.23:48612 [164410db-b350-4a2b-bf89-8bcdaa5ead29] Peer Connection Initiated with [AF_INET]95.78.118.23:48612
Feb 27 13:02:14 www ovpn-server1[23154]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 MULTI_sva: pool returned IPv4=10.9.2.2, IPv6=(Not enabled)
Feb 27 13:02:14 www ovpn-server1[23154]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 MULTI: Learn: 10.9.2.2 -> 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612
Feb 27 13:02:14 www ovpn-server1[23154]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 MULTI: primary virtual IP for 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612: 10.9.2.2
Feb 27 13:02:16 www ovpn-server1[23154]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 PUSH: Received control message: 'PUSH_REQUEST'
Feb 27 13:02:16 www ovpn-server1[23154]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 send_push_reply(): safe_cap=940
Feb 27 13:02:16 www ovpn-server1[23154]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 SENT CONTROL [164410db-b350-4a2b-bf89-8bcdaa5ead29]: 'PUSH_REPLY,route 10.8.0.0 255.255.0.0,route 10.9.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.9.2.2 10.9.2.1' (status=1)
Here is server restart occurs (notice PID change)
Mar 1 10:04:41 www ovpn-server1[7334]: 95.78.118.23:48612 TLS: Initial packet from [AF_INET]95.78.118.23:48612, sid=eb5f5a98 9fd247dc
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=164410db-b350-4a2b-bf89-8bcdaa5ead29
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=164410db-b350-4a2b-bf89-8bcdaa5ead29
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Mar 1 10:04:42 www ovpn-server1[7334]: 95.78.118.23:48612 [164410db-b350-4a2b-bf89-8bcdaa5ead29] Peer Connection Initiated with [AF_INET]95.78.118.23:48612
Mar 1 10:04:42 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 MULTI_sva: pool returned IPv4=10.9.0.70, IPv6=(Not enabled)
Mar 1 10:04:42 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 MULTI: Learn: 10.9.0.70 -> 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612
New address assigned
Mar 1 10:04:42 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 MULTI: primary virtual IP for 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612: 10.9.0.70
Mar 1 10:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 TLS Error: local/remote TLS keys are out of sync: [AF_INET]95.78.118.23:48612 [2]
Mar 1 10:04:53 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 TLS Error: local/remote TLS keys are out of sync: [AF_INET]95.78.118.23:48612 [2]
Mar 1 10:05:03 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 TLS Error: local/remote TLS keys are out of sync: [AF_INET]95.78.118.23:48612 [2]
Mar 1 10:05:07 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 TLS Error: local/remote TLS keys are out of sync: [AF_INET]95.78.118.23:48612 [2]
Another client connecting
Mar 1 10:05:16 www ovpn-server1[7334]: 78.138.130.196:45610 TLS: Initial packet from [AF_INET]78.138.130.196:45610, sid=e4100959 332f4832
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=5569482b-9569-4356-8699-dbc210fbafe9
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=5569482b-9569-4356-8699-dbc210fbafe9
Mar 1 10:05:17 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 TLS Error: local/remote TLS keys are out of sync: [AF_INET]95.78.118.23:48612 [2]
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Mar 1 10:05:17 www ovpn-server1[7334]: 78.138.130.196:45610 [5569482b-9569-4356-8699-dbc210fbafe9] Peer Connection Initiated with [AF_INET]78.138.130.196:45610
Mar 1 10:05:17 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 MULTI_sva: pool returned IPv4=10.9.2.2, IPv6=(Not enabled)
Mar 1 10:05:17 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 MULTI: Learn: 10.9.2.2 -> 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610
The original IP of first client assigned to another client
Mar 1 10:05:17 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 MULTI: primary virtual IP for 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610: 10.9.2.2
Mar 1 10:05:20 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 PUSH: Received control message: 'PUSH_REQUEST'
Mar 1 10:05:20 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 send_push_reply(): safe_cap=940
Mar 1 10:05:20 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 SENT CONTROL [5569482b-9569-4356-8699-dbc210fbafe9]: 'PUSH_REPLY,route 10.8.0.0 255.255.0.0,route 10.9.0.1,topology net30,ping 10,ping-restart 120,ifconfig 10.9.2.2 10.9.2.1' (status=1)
Mar 1 10:05:27 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 TLS Error: local/remote TLS keys are out of sync: [AF_INET]95.78.118.23:48612 [2]
Mar 1 10:05:37 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 TLS Error: local/remote TLS keys are out of sync: [AF_INET]95.78.118.23:48612 [2]
Mar 1 11:04:42 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 TLS: soft reset sec=0 bytes=179912/0 pkts=1939/0
Mar 1 11:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 11:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 11:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=164410db-b350-4a2b-bf89-8bcdaa5ead29
Mar 1 11:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=164410db-b350-4a2b-bf89-8bcdaa5ead29
Mar 1 11:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 11:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 11:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 11:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 11:04:43 www ovpn-server1[7334]: 164410db-b350-4a2b-bf89-8bcdaa5ead29/95.78.118.23:48612 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Mar 1 11:05:17 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 TLS: soft reset sec=0 bytes=47257/0 pkts=740/0
Mar 1 11:05:18 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 11:05:18 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 11:05:18 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 CRL CHECK OK: C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=5569482b-9569-4356-8699-dbc210fbafe9
Mar 1 11:05:18 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], OU=[hidden], CN=5569482b-9569-4356-8699-dbc210fbafe9
Mar 1 11:05:19 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 11:05:19 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 11:05:19 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 11:05:19 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 11:05:19 www ovpn-server1[7334]: 5569482b-9569-4356-8699-dbc210fbafe9/78.138.130.196:45610 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Here is what's going on at the client side:
Mar 1 10:03:25 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: TLS: tls_process: killed expiring key
Mar 1 10:03:26 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: TLS: soft reset sec=0 bytes=2052286/0 pkts=5351/0
Mar 1 10:04:26 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mar 1 10:04:26 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: TLS Error: TLS handshake failed
Mar 1 10:04:26 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
Mar 1 10:04:41 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: TLS: Initial packet from [AF_INET]1.2.3.4:1201, sid=84d60c59 061713e6
Mar 1 10:04:41 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 10:04:41 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: VERIFY OK: nsCertType=SERVER
Mar 1 10:04:41 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], CN=server, emailAddress=[hidden]
Mar 1 10:04:42 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 10:04:42 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 10:04:42 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 10:04:42 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 10:04:42 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Mar 1 11:03:26 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: TLS: tls_multi_process: killed expiring key
Mar 1 11:04:42 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: VERIFY OK: depth=1, C=[hidden], L=[hidden], O=[hidden], CN=[hidden], emailAddress=[hidden]
Mar 1 11:04:42 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: VERIFY OK: nsCertType=SERVER
Mar 1 11:04:42 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: VERIFY OK: depth=0, C=[hidden], L=[hidden], O=[hidden], CN=server, emailAddress=[hidden]
Mar 1 11:04:43 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 11:04:43 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 11:04:43 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Mar 1 11:04:43 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Mar 1 11:04:43 164410db-b350-4a2b-bf89-8bcdaa5ead29 ovpn-client[3453]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
The IP address at the client is not changed and data packets stop transmitting & receiving. IP remains 10.9.2.2 until I manually restart openvpn at the client.
Here is my server config:
proto udp
port 1201
dev tun1
server 10.9.0.0 255.255.0.0
push "route 10.8.0.0 255.255.0.0"
ca ca.crt
cert server.crt
key server.key
dh dh2048.pem
keepalive 10 120
comp-lzo
fragment 1200
mssfix 1200
txqueuelen 1000
user nobody
group nogroup
persist-key
persist-tun
verb 3
client-config-dir ccd
crl-verify crl.pem
max-clients 2048
And here is the client config:
client
dev tun0
proto udp
remote 1.2.3.4 1201
remote-random
resolv-retry infinite
nobind
persist-key
persist-tun
ca ca.crt
cert client.crt
key client.key
ns-cert-type server
comp-lzo
verb 3
mssfix 1200
fragment 1200
What can I try to resolve the issue?
leshik
Hi,
Encountered this bug again, now with verb 4. The case is very similar.
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
As usual, there is nothing special in logs at the client side.