openvpn troubleshoot

最後更新: 2018-12-10

 


<Msg 1>

TLS Error: TLS key negotiation failed to occur within 60 seconds

* Network 很 Busy, 否 GFW 扞擾就會有這個問題.

<Msg 2>

Wed May 06 13:27:05 2015 TLS Error: local/remote TLS keys are out of sync: [AF_INET]x.x.x.x:2194 [0]

This message can occur when running OpenVPN in UDP mode, as UDP is not connection-oriented,

so there's no easy way for one side of the connection to know that the other side has gone down or restarted. 

This error will almost never occur when running in TCP mode,

because TCP enforces solid client/server semantics and connection-reset when either side of the connection goes down.

Suppose you have a UDP OpenVPN connection between "Client" and "Server".  

If Client is restarted, because it is a client, it will renegotiate new TLS keys with the server, and the keys will immediately be in sync.  

However if the Server is restarted, it will not know that it must force a key renegotiation with a previously connected client

because servers don't initiate connections, they wait for them to be initiated by clients.

The current solution uses ping/ping-restart or keepalive

which will cause the client to renegotiate with the server if the server is restarted after a specified period of silence

without any ping messages coming from the server.

The disadvantage of this approach is that it is not immediate.  

If the server goes down, it may take a minute or more for clients to recognize this and renegotiate new keys with the restarted server.

You can reduce the time-lag by using a small ping-restart value,

but then you may restart based on "false posititve" triggers such as short-term network outages which last less that 60 seconds.

<Msg 3>

Softether

... On the TCP Listener (Port 5555), a Client (IP address R.R.R.R, Host name "R-R-R-R.static.pccw-hkt.com", Port number 45493) has connected.
... For the client (IP address: R.R.R.R, host name: "R-R-R-R.static.pccw-hkt.com", port number: 45493), connection "CID-36" has been created.
... OpenVPN Module: The OpenVPN Server Module is starting.
... OpenVPN Session 1 (R.R.R.R:45493 -> 192.168.1.201:5555): A new session is created. Protocol: TCP
... OpenVPN Session 1 (R.R.R.R:45493 -> 192.168.1.201:5555) Channel 0: A new channel is created.
... OpenVPN Session 1 (R.R.R.R:45493 -> 192.168.1.201:5555) Channel 0: Option Strings Received: 
      "V4,dev-type tap,link-mtu 1591,tun-mtu 1532,proto TCPv4_CLIENT,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-client"
... OpenVPN Session 1 (R.R.R.R:45493 -> 192.168.1.201:5555) Channel 0: Option Strings to Send: 
      "V4,dev-type tap,link-mtu 1591,tun-mtu 1532,proto TCPv4_SERVER,cipher AES-128-CBC,auth SHA1,keysize 128,key-method 2,tls-server"
... OpenVPN Module: The OpenVPN Server Module is stopped.
... Connection "CID-36" has been terminated.
... The connection with the client (IP address R.R.R.R, Port number 45493) has been disconnected.

OpenVPN

... TCP connection established with [AF_INET]R.R.R.R:8793
... R.R.R.R:8793 TLS: Initial packet from [AF_INET]R.R.R.R:8793, sid=e9cfcbd7 c6278dda
... R.R.R.R:8793 Connection reset, restarting [-1]
... R.R.R.R:8793 SIGUSR1[soft,connection-reset] received, client-instance restarting

Client log

...: WARNING: No server certificate verification method has been enabled.  ...
...: Socket Buffers: R=[87380->87380] S=[16384->16384]
...: Attempting to establish TCP connection with [AF_INET]R.R.R.R:5555 [nonblock]
...: TCP connection established with [AF_INET]R.R.R.R:5555
...: TCPv4_CLIENT link local: [undef]
...: TCPv4_CLIENT link remote: [AF_INET]R.R.R.R:5555
...: TLS: Initial packet from [AF_INET]R.R.R.R:5555, sid=fc4b074b eaa9b69a
...: VERIFY OK: depth=2, ...
...: VERIFY OK: depth=1, ...
...: VERIFY OK: depth=0, ...
...: Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
...: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
...: Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
...: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
...: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
...: [server.local] Peer Connection Initiated with [AF_INET]R.R.R.R:5555
...: [server.local] Inactivity timeout (--ping-restart), restarting
...: SIGUSR1[soft,ping-restart] received, process restarting
...: Restart pause, 5 second(s)

In most cases this means that either the machine itself is sending TCP_RST packets or that an intermediary firewall is blocking things.