Use the same setup as in the Troubleshooting MTU and tun-mtu issues recipe earlier in this chapter. For this recipe, the server computer was running CentOS 6 Linux and OpenVPN 2.3.11, and the client was running Fedora 22 Linux and OpenVPN 2.3.11. Keep the configuration file, basic-udp-server.conf, from the Server-side routing recipe from Chapter 2, Client-server IP-only Networks. For the client, keep the configuration file, example6-5-client.conf, from the Troubleshooting MTU and tun-mtu issues recipe at hand.

The first part of the log file contains the configuration as specified in the configuration file and from the command-line parameters. This is the section starting with the following line:

Current Parameter Settings: 
  config = 'example6-5-client.conf' 

It ends with the following line:

OpenVPN 2.3.11 x86_64-redhat-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [PKCS11] [MH] [IPv6] built on May 10 2016 

This section is about 275 lines long depending on the configuration and it contains what OpenVPN thinks is the configuration. Check this section carefully to make sure that you agree.

The next interesting section is as follows:

Control Channel Authentication: using '/etc/openvpn/cookbook/ta.key' as a OpenVPN static key file 
Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication 
Outgoing Control Channel Authentication: HMAC KEY: 51cc24c0 ... 
Outgoing Control Channel Authentication: HMAC size=20 ... Incoming Control Channel Authentication: Using 160 bit ... 
Incoming Control Channel Authentication: HMAC KEY: 1c748f91 ...  
Incoming Control Channel Authentication: HMAC size=20 ...  

This part shows that a tls-auth key is read and used and that the two separate HMAC keys are derived. The keys are actually printed in the log file, so you can reference them with the output from the server log file. The server incoming key should be the same as the client outgoing key and vice versa. The misconfiguration from the Key mismatches recipe earlier in this chapter would have appeared here.

Right after this section is the warning that is the root cause of the misconfiguration from the Troubleshooting MTU and tun-mtu issues recipe earlier in this chapter:

WARNING: normally if you use --mssfix and/or --fragment, you should also set --tun-mtu 1500 (currently it is 1400) 

Log file messages starting with WARNING should always be given special attention to. In some cases, they can be ignored, but in this case, it was the root cause of the VPN connection not working properly.

After this warning comes a whole range of messages of the following form:

UDPv4 link remote: [AF_INET]server-ip:1194 
UDPv4 WRITE [42] to [AF_INET]server-ip:1194: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #1 ] [ ] pid=0 DATA len=0 
UDPv4 READ [54] from [AF_INET]server-ip:1194: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 pid=[ #1 ] [ 0 ] pid=0 DATA len=0 
TLS: Initial packet from [AF_INET]server-ip:1194, sid=c483bcc9 a60cc834 
PID_TEST [0] [TLS_AUTH-0] [] 0:0 1469290891:1 t=1469290891[0] r=[0,64,15,0,1] sl=[0,0,64,528] 
UDPv4 WRITE [50] to [AF_INET]server-ip:1194: P_ACK_V1 kid=0 pid=[ #2 ] [ 0 ] 
UDPv4 WRITE [249] to [AF_INET]server-ip:1194: P_CONTROL_V1 kid=0 pid=[ #3 ] [ ] pid=1 DATA len=207 

These messages are all part of the initial handshake between the client and the server to exchange configuration information, encryption keys, and other information for setting up the VPN connection. Right after this is another hint about the misconfiguration:

WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1441', remote='link-mtu 1541' 
WARNING: 'tun-mtu' is used inconsistently, local='tun-mtu 1400', remote='tun-mtu 1500'  

We skip forward over a lot of TLS_prf messages to come to the end of the connection handshake:

Control Channel: TLSv1.2, cipher TLSv1/SSLv3 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA 
[openvpnserver] Peer Connection Initiated with [AF_INET]server-ip:1194 

At this point, the OpenVPN client has established the initial connection with the server and it is now ready to process the configuration directives pushed by the server, if any:

PUSH: Received control message: 'PUSH_REPLY,route-gateway 10.200.0.1,topology subnet,ping 10,ping-restart 60,ifconfig 10.200.0.2 255.255.255.0' 

This is another important line to check for, as it shows what the server has actually pushed to the client. Verify that this actually matches what you thought the server should push.

After this, the local TUN adapter is opened and initialized and the first packets can begin to flow.

The first ping command worked fine, as we can see from this part:

TUN READ [84] 
... 
UDPv4 WRITE [125] to server-ip:1194: P_DATA_V1 kid=0 DATA len=124 
UDPv4 READ [125] from server-ip:1194: P_DATA_V1 kid=0 DATA len=124 
TLS: tls_pre_decrypt, key_id=0, IP=server-ip:1194 
TUN WRITE [84] 

The TUN READ is the ping command being read from the TUN interface, followed by a write over the encrypted channel to the remote server. Notice the difference in packet size: the packet sent over the encrypted tunnel is 125 bytes, which is 41- bytes larger than the original packet read from the TUN interface. This exactly matches the difference between the link-mtu and tun-mtu options as shown earlier in the log file.

Next comes the section where the ping -s 1450 command breaks down. A ping of 1450 bytes cannot be read in one piece if the MTU of the interface is set to 1400, hence two TUN READS are necessary to capture all data:

TUN READ [1396] 
... 
UDPv4 WRITE [1437] to server-ip:1194: P_DATA_V1 kid=0 DATA len=1436 
TUN READ [102] 
... 
UDPv4 WRITE [141] to server-ip:1194: P_DATA_V1 kid=0 DATA len=140 

Notice that the data is actually sent as two separate packets to the server. This is perfectly normal behavior, as the packet needs to be fragmented. Calculation of the packet sizes versus the MTU sizes breaks down in this case, as the second packet is not a complete IP packet.

The server receives the large ping command and sends an equally large reply. As the server has an MTU setting of 1500, there is no need to fragment the data, so it arrives at the client as a single packet:

UDPv4 READ [1441] from server-ip:1194: P_DATA_V1 kid=0 DATA len=1440 
TLS: tls_pre_decrypt, key_id=0, IP=server-ip:1194 
Authenticate/Decrypt packet error: packet HMAC authentication failed 

The client, however, is expecting a packet with a maximum size of 1400 bytes. It is not able to properly decode the larger packet and write out the packet HMAC authentication failed message.

Finally, when we abort the client, we see an interrupted system call message (in this case,  Ctrl +  C was used to abort the client, along with a range of clean-up messages before the client actually stops):

event_wait : Interrupted system call (code=4) 
PID packet_id_free 
... 
TCP/UDP: Closing socket 
Closing TUN/TAP interface 
/sbin/ip addr del dev tun0 10.200.0.2/24 
PID packet_id_free 
SIGINT[hard,] received, process exiting 

Consider that the client configuration had included this:

user nobody 

Then, we would also have seen messages of this form:

SIOCSIFADDR: Permission denied 
SIOCSIFFLAGS: Permission denied 
Linux ip addr del failed: external program exited with error status: 255 

In this case, these are harmless.

On UNIX-based operating systems, it is also possible to send the OpenVPN log output via syslog. This allows a system administrator to effectively manage a large set of computers using a single system logging interface. To send log messages via syslog, replace the directive log-append with the following:

syslog [name] 

Here, name is an optional parameter to specify the name of the OpenVPN instance in the syslog log files. This is particularly useful if there are multiple instances of OpenVPN running on a single host, and they are all using syslog to log their output and error messages.