MTU problems not fixed by the usual solutions

scourtney · Post by **scourtney** » Tue May 12, 2015 11:05 pm

Greetings, all

We're having a lot of problems with OpenVPN performance on TCP connections over a UDP tunnel, and I've been all over the 'Net to find solutions. Nothing seems to be solving this. The symptoms are the same thing everyone seems to encounter, namely that small payloads work fine but large file transfers or other high activity will kill the link. For small payloads, this link will literally run all day long with no problem, but try to SCP a large file up fails at about 10 to 11 megabytes, every single time.

Using ping with the no-fragment option, I've established that the physical MTU between client and server is 1472 bytes maximum.

The server is CentOS 6.6, running kernel 2.6.32. We've got OpenVPN version 2.1.3 on the server, and

Varying the MTU and fragmentation parameters gets me about +/- 10% data length before the failure (that is, it might go to 12 meg or 9 meg).

Doing the same file transfer to the public IP of the same server (that is, bypassing OpenVPN but still going between the same two computers over the same public Internet path) works perfectly, and reliably.

If I change from "proto udp" to "proto tcp" the problem is resolved, but then everything is slow because you're nesting TCP within TCP.

The problem can be replicated with clients running the same Linux version as the server, and with clients running OpenVPN on Mac OSX.

Here's a excerpt of my test server's config file:

Code: Select all

port 1194
proto udp
dev tun0

#mtu-test
link-mtu 1472
#tun-mtu 1500
#fragment 1442
mssfix 1300

### File paths for certs and keys omitted ...

# Multi-client server mode setup
server 192.168.222.0 255.255.255.0
client-config-dir /etc/openvpn/ccd

I've varied the link-mtu, tun-mtu, fragment, and mssfix parameters all over the place, including leaving out each of these. I've also tried using tap instead of tun. In every test, I match the parameters exactly on the client and the server.

The only real error in the server log is this: "Replay-window backtrack occurred [1]" which happens fairly often, and which my online reading suggests is related to the MTU.

I'm at a loss as to what else to try. Are there some "failsafe" settings for the MTU that will force my packet sizes down low enough to crawl through any ISP's network? I'd like to start with something that works, then gradually increase to tune performance, but so far no matter where I set the link and tunnel paramaters, I'm getting no success.

Thanks for any suggestions.

Traffic · Post by **Traffic** » Wed May 13, 2015 10:14 am

scourtney wrote:Using ping with the no-fragment option, I've established that the physical MTU between client and server is 1472 bytes maximum

This does not sound like mtu issue to me .. 1472 is fairly normal ..

For how long (time) does your file transfer run before it crashes ?

What messages are in the server and client log when the copy fails ?
Set --verb 4 for detailed logs ..

You could also try --mtu-disc yes and --mtu-test

scourtney · Post by **scourtney** » Wed May 13, 2015 5:30 pm

Traffic wrote:
scourtney wrote:Using ping with the no-fragment option, I've established that the physical MTU between client and server is 1472 bytes maximum
This does not sound like mtu issue to me .. 1472 is fairly normal ..

[/quote]

Thanks for the reply. I agree with your general assessment; the reason I call this an MTU problem is because all the documentation I have found on the Internet suggests that MTU is just about the only thing that causes issues like this. But I've tried all kinds of changes to MTU discovery and hardwired size, and it's not helping, so you are probably right that it's something else....but what could it be?

For how long (time) does your file transfer run before it crashes ?

Around 30 to 40 seconds. The time varies a little, but the byte count at the point of failure is consistently between 10 and 11 megabytes.

What messages are in the server and client log when the copy fails ?
Set --verb 4 for detailed logs ..

I'm working remotely right now, but I will reset my config to defaults and grab another set of logs tonight. I've been watching the logs closely, but I don't currently have an "initial conditions" failure log handy.

You could also try --mtu-disc yes and --mtu-test

[/quote]

I've actually used the mtu-test option to try to narrow this down. It shows a physical link MTU of 1500, with an allowed 1472 octet payload (which matches your comment earlier that 1472 is normal).

What is the default setting for mtu-disc? There is no default documented in the man page, as far as I can tell.

I'm going to post a separate append to this thread with my more detailed test notes, copied from our internal ticket system.

scourtney · Post by **scourtney** » Wed May 13, 2015 5:44 pm

Notes from our internal ticket log (some editing for privacy/security reasons):

Testing results so far:

File transfers from [two different remote sites] to anything inside the core network repeatably fail. This is true of destinations in [both of our corporate centers].
File transfers from [to remote sites] to a public NIC at the colo are successful. I tested up to about 400 megabytes with no problems.
File transfers from the OpenVPN hub through the router to the core network reliably succeed. Again, tested up to about 400 megabytes.
The problem only appears on UDP VPN connections. TCP connections run much slower than UDP, in my testing, but are reliable for large file transfers.

Analysis by inspection and research:

There are no iptables rules affecting the test VPN data path.
We accept all ICMP traffic on the public interfaces. One Internet posting suggested we might have this problem if we were refusing ICMP packets related to fragmentation.
According to VMware monitoring, the OpenVPN server uses about 150 MHz of host CPU at peak load. VMware's documentation says the numbers I'm seeing represent about 6% of a single physical core. I set its CPU reservation above this and set its share priority to the highest value, as recommended by VMware for latency-sensitive workloads. CPU usage did not increase as I added resources, so I conclude that the guest is not CPU starved.
According to online documentation, OpenVPN is monolithic process per instance. This means that our TCP and UDP versions can run on different cores, but each of those instances is single-threaded. (We two have separate OpenVPN instances running on our server.)
Some online articles suggested problems could result if wildly different Linux kernels were in use at client and server ends, because of slight changes to IP stacks. I verified that the kernels in client and server were identical versions, so this is ruled out.

Remedies tested during a scheduled outage:

Turned on the fragmentation option in OpenVPN at client and server configs. No matter what other parameters I set, if this option is on, I was not able to get the tunnel working at all. I found some online docs that predicted what I observed (it breaks everything), while others said turning this parameter on is essential to resolve our problem.
Tried tunnel MTU values of 1500, 1472, 1400, and 1300, based on various recommendations from the OpenVPN forums. Tried fragmentation values 40 bytes below these as recommended by the OpenVPN forums and documentation.
Tried setting the physical MTU of the NIC at client and server to 1400, and then setting the tunnel MTU to 1300.
Added the "mssfix" option to client and server configs. As far as I can tell, it had no effect.
Changed the send and receive buffer settings at client and server, matching values each time, and tested values of zero, 64K, and about 384K, based on published recommendations.
For most of my testing, I was the only one using the system, so for all practical purposes I was running on a dedicated VPN.

I have been doing all my recent tests on a dedicated physical server with about a 2 GHz multicore CPU and plenty of RAM, so I think we can rule out resource starvation as the culprit.

Traffic · Post by **Traffic** » Fri May 15, 2015 10:27 am

I would check all the physical routers used by the problem clients ..

scourtney · Post by **scourtney** » Fri Jun 05, 2015 1:25 am

Between travel and other projects, I am just now returning to this. Here is a "verbose 4" test log from both client and server.

This is with protocol UDP, and with *no* settings for MTU or related...defaults all around.

This particular test was done with OpenVPN 2.3 on a Mac, connecting to a Debian 6 test server (physical host, not virtual, and otherwise zero workload), but the behavior is identical if I run the same test with equivalent configs between Centos 6.5 and Centos 6.5, or between an Centos 6.5 client and this Debian server.

What I conclude from the above is that I have some kind of configuration problem and not a problem with OpenVPN or operating system versions.

Client log:

Code: Select all

Jun 04 20:55:22: Viscosity Mac 1.5.6 (1285)
Jun 04 20:55:22: Viscosity OpenVPN Engine Started
Jun 04 20:55:22: Running on Mac OS X 10.10.3
Jun 04 20:55:22: ---------
Jun 04 20:55:22: Checking reachability status of connection...
Jun 04 20:55:22: Connection is reachable. Starting connection attempt.
Jun 04 20:55:22: us=669079 Current Parameter Settings:
Jun 04 20:55:22: us=669749   config = '/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/connection.3up98A/config.conf'
Jun 04 20:55:22: us=669761   mode = 0
Jun 04 20:55:22: us=669770   show_ciphers = DISABLED
Jun 04 20:55:22: us=669777   show_digests = DISABLED
Jun 04 20:55:22: us=669785   show_engines = DISABLED
Jun 04 20:55:22: us=669793   genkey = DISABLED
Jun 04 20:55:22: us=669800   key_pass_file = '[UNDEF]'
Jun 04 20:55:22: us=669808   show_tls_ciphers = DISABLED
Jun 04 20:55:22: us=669814 Connection profiles [default]:
Jun 04 20:55:22: us=669824   proto = udp
Jun 04 20:55:22: us=669830   local = '[UNDEF]'
Jun 04 20:55:22: us=669836   local_port = 0
Jun 04 20:55:22: us=669843   remote = 'svc.MYDOMAIN'
Jun 04 20:55:22: us=669849   remote_port = 1194
Jun 04 20:55:22: us=669855   remote_float = DISABLED
Jun 04 20:55:22: us=669862   bind_defined = DISABLED
Jun 04 20:55:22: us=669869   bind_local = DISABLED
Jun 04 20:55:22: us=669876   connect_retry_seconds = 5
Jun 04 20:55:22: us=669883   connect_timeout = 10
Jun 04 20:55:22: us=669889   connect_retry_max = 0
Jun 04 20:55:22: us=669897   socks_proxy_server = '[UNDEF]'
Jun 04 20:55:22: us=669904   socks_proxy_port = 0
Jun 04 20:55:22: us=669911   socks_proxy_retry = DISABLED
Jun 04 20:55:22: us=669918   tun_mtu = 1500
Jun 04 20:55:22: us=669925   tun_mtu_defined = ENABLED
Jun 04 20:55:22: us=669932   link_mtu = 1500
Jun 04 20:55:22: us=669938   link_mtu_defined = DISABLED
Jun 04 20:55:22: us=669945   tun_mtu_extra = 0
Jun 04 20:55:22: us=669950   tun_mtu_extra_defined = DISABLED
Jun 04 20:55:22: us=669956   mtu_discover_type = -1
Jun 04 20:55:22: us=669962   fragment = 0
Jun 04 20:55:22: us=669968   mssfix = 1450
Jun 04 20:55:22: us=669975   explicit_exit_notification = 0
Jun 04 20:55:22: us=669981 Connection profiles END
Jun 04 20:55:22: us=669987   remote_random = DISABLED
Jun 04 20:55:22: us=669993   ipchange = '[UNDEF]'
Jun 04 20:55:22: us=669999   dev = 'tun'
Jun 04 20:55:22: us=670007   dev_type = '[UNDEF]'
Jun 04 20:55:22: us=670013   dev_node = 'tun'
Jun 04 20:55:22: us=670020   lladdr = '[UNDEF]'
Jun 04 20:55:22: us=670027   topology = 1
Jun 04 20:55:22: us=670033   tun_ipv6 = DISABLED
Jun 04 20:55:22: us=670040   ifconfig_local = '[UNDEF]'
Jun 04 20:55:22: us=670047   ifconfig_remote_netmask = '[UNDEF]'
Jun 04 20:55:22: us=670098   ifconfig_noexec = DISABLED
Jun 04 20:55:22: us=670110   ifconfig_nowarn = DISABLED
Jun 04 20:55:22: us=670117   ifconfig_ipv6_local = '[UNDEF]'
Jun 04 20:55:22: us=670123   ifconfig_ipv6_netbits = 0
Jun 04 20:55:22: us=670128   ifconfig_ipv6_remote = '[UNDEF]'
Jun 04 20:55:22: us=670134   shaper = 0
Jun 04 20:55:22: us=670144   mtu_test = 0
Jun 04 20:55:22: us=670153   mlock = DISABLED
Jun 04 20:55:22: us=670159   keepalive_ping = 0
Jun 04 20:55:22: us=670164   keepalive_timeout = 0
Jun 04 20:55:22: us=670174   inactivity_timeout = 0
Jun 04 20:55:22: us=670180   ping_send_timeout = 0
Jun 04 20:55:22: us=670186   ping_rec_timeout = 0
Jun 04 20:55:22: us=670191   ping_rec_timeout_action = 0
Jun 04 20:55:22: us=670197   ping_timer_remote = DISABLED
Jun 04 20:55:22: us=670202   remap_sigusr1 = 0
Jun 04 20:55:22: us=670209   persist_tun = ENABLED
Jun 04 20:55:22: us=670214   persist_local_ip = DISABLED
Jun 04 20:55:22: us=670223   persist_remote_ip = DISABLED
Jun 04 20:55:22: us=670231   persist_key = ENABLED
Jun 04 20:55:22: us=670237   passtos = DISABLED
Jun 04 20:55:22: us=670243   resolve_retry_seconds = 1000000000
Jun 04 20:55:22: us=670252   username = '[UNDEF]'
Jun 04 20:55:22: us=670262   groupname = '[UNDEF]'
Jun 04 20:55:22: us=670268   chroot_dir = '[UNDEF]'
Jun 04 20:55:22: us=670273   cd_dir = '/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/connection.3up98A'
Jun 04 20:55:22: us=670279   writepid = '[UNDEF]'
Jun 04 20:55:22: us=670284   up_script = '[UNDEF]'
Jun 04 20:55:22: us=670292   down_script = '[UNDEF]'
Jun 04 20:55:22: us=670299   down_pre = DISABLED
Jun 04 20:55:22: us=670304   up_restart = DISABLED
Jun 04 20:55:22: us=670309   up_delay = DISABLED
Jun 04 20:55:22: us=670315   daemon = DISABLED
Jun 04 20:55:22: us=670319   inetd = 0
Jun 04 20:55:22: us=670325   log = DISABLED
Jun 04 20:55:22: us=670330   suppress_timestamps = DISABLED
Jun 04 20:55:22: us=670335   nice = 0
Jun 04 20:55:22: us=670340   verbosity = 4
Jun 04 20:55:22: us=670347   mute = 0
Jun 04 20:55:22: us=670353   status_file = '[UNDEF]'
Jun 04 20:55:22: us=670362   status_file_version = 1
Jun 04 20:55:22: us=670368   status_file_update_freq = 60
Jun 04 20:55:22: us=670373   occ = ENABLED
Jun 04 20:55:22: us=670379   rcvbuf = 65536
Jun 04 20:55:22: us=670384   sndbuf = 65536
Jun 04 20:55:22: us=670389   sockflags = 0
Jun 04 20:55:22: us=670396   fast_io = DISABLED
Jun 04 20:55:22: us=670412   lzo = 1
Jun 04 20:55:22: us=670417   route_script = '[UNDEF]'
Jun 04 20:55:22: us=670423   route_default_gateway = '[UNDEF]'
Jun 04 20:55:22: us=670429   route_default_metric = 0
Jun 04 20:55:22: us=670435   route_noexec = DISABLED
Jun 04 20:55:22: us=670442   route_delay = 0
Jun 04 20:55:22: us=670448   route_delay_window = 30
Jun 04 20:55:22: us=670454   route_delay_defined = DISABLED
Jun 04 20:55:22: us=670460   route_nopull = DISABLED
Jun 04 20:55:22: us=670466   route_gateway_via_dhcp = DISABLED
Jun 04 20:55:22: us=670473   max_routes = 100
Jun 04 20:55:22: us=670479   allow_pull_fqdn = DISABLED
Jun 04 20:55:22: us=670485   management_addr = '127.0.0.1'
Jun 04 20:55:22: us=670494   management_port = 60791
Jun 04 20:55:22: us=670500   management_user_pass = '[UNDEF]'
Jun 04 20:55:22: us=670507   management_log_history_cache = 250
Jun 04 20:55:22: us=670512   management_echo_buffer_size = 100
Jun 04 20:55:22: us=670521   management_write_peer_info_file = '[UNDEF]'
Jun 04 20:55:22: us=670527   management_client_user = '[UNDEF]'
Jun 04 20:55:22: us=670533   management_client_group = '[UNDEF]'
Jun 04 20:55:22: us=670540   management_flags = 6
Jun 04 20:55:22: us=670547   shared_secret_file = '[UNDEF]'
Jun 04 20:55:22: us=670553   key_direction = 2
Jun 04 20:55:22: us=670560   ciphername_defined = ENABLED
Jun 04 20:55:22: us=670568   ciphername = 'BF-CBC'
Jun 04 20:55:22: us=670575   authname_defined = ENABLED
Jun 04 20:55:22: us=670582   authname = 'SHA1'
Jun 04 20:55:22: us=670589   prng_hash = 'SHA1'
Jun 04 20:55:22: us=670597   prng_nonce_secret_len = 16
Jun 04 20:55:22: us=670604   keysize = 0
Jun 04 20:55:22: us=670612   engine = DISABLED
Jun 04 20:55:22: us=670619   replay = ENABLED
Jun 04 20:55:22: us=670626   mute_replay_warnings = DISABLED
Jun 04 20:55:22: us=670633   replay_window = 64
Jun 04 20:55:22: us=670640   replay_time = 15
Jun 04 20:55:22: us=670647   packet_id_file = '[UNDEF]'
Jun 04 20:55:22: us=670654   use_iv = ENABLED
Jun 04 20:55:22: us=670661   test_crypto = DISABLED
Jun 04 20:55:22: us=670668   tls_server = DISABLED
Jun 04 20:55:22: us=670675   tls_client = ENABLED
Jun 04 20:55:22: us=670682   key_method = 2
Jun 04 20:55:22: us=670689   ca_file = '/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/connection.3up98A/ca.crt'
Jun 04 20:55:22: us=670696   ca_path = '[UNDEF]'
Jun 04 20:55:22: us=670703   dh_file = '[UNDEF]'
Jun 04 20:55:22: us=670710   cert_file = '/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/connection.3up98A/cert.crt'
Jun 04 20:55:22: us=670717   priv_key_file = '/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/connection.3up98A/key.key'
Jun 04 20:55:22: us=670724   pkcs12_file = '[UNDEF]'
Jun 04 20:55:22: us=670731   cipher_list = '[UNDEF]'
Jun 04 20:55:22: us=670738   tls_verify = '[UNDEF]'
Jun 04 20:55:22: us=670745   tls_export_cert = '[UNDEF]'
Jun 04 20:55:22: us=670752   verify_x509_type = 0
Jun 04 20:55:22: us=670760   verify_x509_name = '[UNDEF]'
Jun 04 20:55:22: us=670767   crl_file = '[UNDEF]'
Jun 04 20:55:22: us=670775   ns_cert_type = 0
Jun 04 20:55:22: us=670782   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670789   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670796   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670803   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670811   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670818   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670825   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670832   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670838   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670845   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670851   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670858   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670865   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670872   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670878   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670885   remote_cert_ku[i] = 0
Jun 04 20:55:22: us=670893   remote_cert_eku = '[UNDEF]'
Jun 04 20:55:22: us=670900   ssl_flags = 0
Jun 04 20:55:22: us=670907   tls_timeout = 2
Jun 04 20:55:22: us=670913   renegotiate_bytes = 0
Jun 04 20:55:22: us=670920   renegotiate_packets = 0
Jun 04 20:55:22: us=670927   renegotiate_seconds = 3600
Jun 04 20:55:22: us=670933   handshake_window = 60
Jun 04 20:55:22: us=670940   transition_window = 3600
Jun 04 20:55:22: us=670946   single_session = DISABLED
Jun 04 20:55:22: us=670952   push_peer_info = DISABLED
Jun 04 20:55:22: us=670959   tls_exit = DISABLED
Jun 04 20:55:22: us=670965   tls_auth_file = '/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/connection.3up98A/ta.key'
Jun 04 20:55:22: us=670971   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=670978   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671051   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671060   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671066   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671074   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671082   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671089   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671096   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671152   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671162   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:22: us=671169   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:23: us=671183   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:23: us=671191   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:23: us=671197   pkcs11_protected_authentication = DISABLED
Jun 04 20:55:23: us=671205   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671212   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671219   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671227   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671234   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671242   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671248   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671256   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671263   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671271   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671278   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671284   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671290   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671296   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671303   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671310   pkcs11_private_mode = 00000000
Jun 04 20:55:23: us=671317   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671325   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671332   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671339   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671346   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671353   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671361   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671367   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671373   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671381   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671388   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671394   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671399   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671405   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671409   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671413   pkcs11_cert_private = DISABLED
Jun 04 20:55:23: us=671417   pkcs11_pin_cache_period = -1
Jun 04 20:55:23: us=671421   pkcs11_id = '[UNDEF]'
Jun 04 20:55:23: us=671425   pkcs11_id_management = DISABLED
Jun 04 20:55:23: us=671439   server_network = 0.0.0.0
Jun 04 20:55:23: us=671446   server_netmask = 0.0.0.0
Jun 04 20:55:23: us=671458   server_network_ipv6 = ::
Jun 04 20:55:23: us=671462   server_netbits_ipv6 = 0
Jun 04 20:55:23: us=671467   server_bridge_ip = 0.0.0.0
Jun 04 20:55:23: us=671471   server_bridge_netmask = 0.0.0.0
Jun 04 20:55:23: us=671476   server_bridge_pool_start = 0.0.0.0
Jun 04 20:55:23: us=671481   server_bridge_pool_end = 0.0.0.0
Jun 04 20:55:23: us=671485   ifconfig_pool_defined = DISABLED
Jun 04 20:55:23: us=671490   ifconfig_pool_start = 0.0.0.0
Jun 04 20:55:23: us=671494   ifconfig_pool_end = 0.0.0.0
Jun 04 20:55:23: us=671499   ifconfig_pool_netmask = 0.0.0.0
Jun 04 20:55:23: us=671503   ifconfig_pool_persist_filename = '[UNDEF]'
Jun 04 20:55:23: us=671507   ifconfig_pool_persist_refresh_freq = 600
Jun 04 20:55:23: us=671511   ifconfig_ipv6_pool_defined = DISABLED
Jun 04 20:55:23: us=671515   ifconfig_ipv6_pool_base = ::
Jun 04 20:55:23: us=671519   ifconfig_ipv6_pool_netbits = 0
Jun 04 20:55:23: us=671523   n_bcast_buf = 256
Jun 04 20:55:23: us=671527   tcp_queue_limit = 64
Jun 04 20:55:23: us=671531   real_hash_size = 256
Jun 04 20:55:23: us=671535   virtual_hash_size = 256
Jun 04 20:55:23: us=671539   client_connect_script = '[UNDEF]'
Jun 04 20:55:23: us=671543   learn_address_script = '[UNDEF]'
Jun 04 20:55:23: us=671546   client_disconnect_script = '[UNDEF]'
Jun 04 20:55:23: us=671550   client_config_dir = '[UNDEF]'
Jun 04 20:55:23: us=671554   ccd_exclusive = DISABLED
Jun 04 20:55:23: us=671558   tmp_dir = '/tmp'
Jun 04 20:55:23: us=671562   push_ifconfig_defined = DISABLED
Jun 04 20:55:23: us=671567   push_ifconfig_local = 0.0.0.0
Jun 04 20:55:23: us=671575   push_ifconfig_remote_netmask = 0.0.0.0
Jun 04 20:55:23: us=671579   push_ifconfig_ipv6_defined = DISABLED
Jun 04 20:55:23: us=671584   push_ifconfig_ipv6_local = ::/0
Jun 04 20:55:23: us=671589   push_ifconfig_ipv6_remote = ::
Jun 04 20:55:23: us=671596   enable_c2c = DISABLED
Jun 04 20:55:23: us=671603   duplicate_cn = DISABLED
Jun 04 20:55:23: us=671609   cf_max = 0
Jun 04 20:55:23: us=671615   cf_per = 0
Jun 04 20:55:23: us=671622   max_clients = 1024
Jun 04 20:55:23: us=671629   max_routes_per_client = 256
Jun 04 20:55:23: us=671635   auth_user_pass_verify_script = '[UNDEF]'
Jun 04 20:55:23: us=671641   auth_user_pass_verify_script_via_file = DISABLED
Jun 04 20:55:23: us=671647   port_share_host = '[UNDEF]'
Jun 04 20:55:23: us=671651   port_share_port = 0
Jun 04 20:55:23: us=671655   client = DISABLED
Jun 04 20:55:23: us=671659   pull = ENABLED
Jun 04 20:55:23: us=671663   auth_user_pass_file = '[UNDEF]'
Jun 04 20:55:23: us=671672 OpenVPN 2.3.6 x86_64-apple-darwin [SSL (OpenSSL)] [LZO] [PKCS11] [MH] [IPv6] built on Apr  5 2015
Jun 04 20:55:23: us=671682 library versions: OpenSSL 1.0.2a 19 Mar 2015, LZO 2.09
Jun 04 20:55:23: us=672683 MANAGEMENT: TCP Socket listening on [AF_INET]127.0.0.1:60791
Jun 04 20:55:23: us=672702 Need hold release from management interface, waiting...
Jun 04 20:55:23: us=656036 MANAGEMENT: Client connected from [AF_INET]127.0.0.1:60791
Jun 04 20:55:23: us=656153 MANAGEMENT: CMD 'pid'
Jun 04 20:55:23: us=656213 MANAGEMENT: CMD 'log on'
Jun 04 20:55:23: us=656269 MANAGEMENT: CMD 'state on'
Jun 04 20:55:23: us=656307 MANAGEMENT: CMD 'hold release'
Jun 04 20:55:23: us=656453 WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Jun 04 20:55:23: us=657376 Control Channel Authentication: using '/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/connection.3up98A/ta.key' as a OpenVPN static key file
Jun 04 20:55:23: us=657397 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Jun 04 20:55:23: us=657408 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Jun 04 20:55:23: us=657441 LZO compression initialized
Jun 04 20:55:23: us=657541 Control Channel MTU parms [ L:1542 D:166 EF:66 EB:0 ET:0 EL:0 ]
Jun 04 20:55:23: us=657596 Socket Buffers: R=[196724->65536] S=[9216->65536]
Jun 04 20:55:23: us=658321 MANAGEMENT: >STATE:1433465723,RESOLVE,,,
Jun 04 20:55:23: us=659201 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Jun 04 20:55:23: us=659296 Local Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Jun 04 20:55:23: us=659313 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Jun 04 20:55:23: us=659338 Local Options hash (VER=V4): '504e774e'
Jun 04 20:55:23: us=659355 Expected Remote Options hash (VER=V4): '14168603'
Jun 04 20:55:23: us=659379 UDPv4 link local: [undef]
Jun 04 20:55:23: us=659395 UDPv4 link remote: [AF_INET]((MY_SERVER_IP)):1194
Jun 04 20:55:23: us=659423 MANAGEMENT: >STATE:1433465723,WAIT,,,
Jun 04 20:55:23: us=707078 MANAGEMENT: >STATE:1433465723,AUTH,,,
Jun 04 20:55:23: us=707110 TLS: Initial packet from [AF_INET]((MY_SERVER_IP)):1194, sid=ab562631 235a8f78
Jun 04 20:55:24: us=83226 VERIFY OK: depth=1, C=US, ((( REDACTED )))
Jun 04 20:55:24: us=83503 VERIFY OK: depth=0, C=US, ((( REDACTED )))
Jun 04 20:55:24: us=163678 MANAGEMENT: CMD 'hold release'
Jun 04 20:55:24: us=664660 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jun 04 20:55:24: us=664692 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jun 04 20:55:24: us=664771 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jun 04 20:55:24: us=664800 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jun 04 20:55:24: us=664936 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Jun 04 20:55:24: us=664975 [((MY_KEY_NAME))] Peer Connection Initiated with [AF_INET]199.167.73.135:1194
Jun 04 20:55:24: us=665358 MANAGEMENT: CMD 'state on'
Jun 04 20:55:25: us=171515 MANAGEMENT: CMD 'hold release'
Jun 04 20:55:25: us=171561 MANAGEMENT: >STATE:1433465725,GET_CONFIG,,,
Jun 04 20:55:25: us=172122 MANAGEMENT: CMD 'pid'
Jun 04 20:55:25: us=179044 MANAGEMENT: CMD 'pid'
Jun 04 20:55:25: us=686252 MANAGEMENT: CMD 'hold release'
Jun 04 20:55:25: us=686850 MANAGEMENT: CMD 'pid'
Jun 04 20:55:25: us=689470 MANAGEMENT: CMD 'pid'
Jun 04 20:55:26: us=821974 SENT CONTROL [(( MY KEY NAME ))]: 'PUSH_REQUEST' (status=1)
Jun 04 20:55:26: us=868863 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 192.168.96.6,dhcp-option DNS 192.168.96.4,dhcp-option DNS 192.168.70.6,dhcp-option DOMAIN ((MY_DOMAIN)),tun-ipv6,route 192.168.222.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 192.168.222.6 192.168.222.5'
Jun 04 20:55:26: us=869005 OPTIONS IMPORT: timers and/or timeouts modified
Jun 04 20:55:26: us=869013 OPTIONS IMPORT: --ifconfig/up options modified
Jun 04 20:55:26: us=869020 OPTIONS IMPORT: route options modified
Jun 04 20:55:26: us=869027 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Jun 04 20:55:26: us=871168 TUN/TAP device /dev/tun0 opened
Jun 04 20:55:26: us=871191 do_ifconfig, tt->ipv6=1, tt->did_ifconfig_ipv6_setup=0
Jun 04 20:55:26: us=871216 MANAGEMENT: >STATE:1433465726,ASSIGN_IP,,192.168.222.6,
Jun 04 20:55:26: us=871245 /sbin/ifconfig tun0 delete
Jun 04 20:55:26: us=873555 NOTE: Tried to delete pre-existing tun/tap instance -- No Problem if failure
Jun 04 20:55:26: us=873619 /sbin/ifconfig tun0 192.168.222.6 192.168.222.5 mtu 1500 netmask 255.255.255.255 up
Jun 04 20:55:26: us=876259 MANAGEMENT: >STATE:1433465726,ADD_ROUTES,,,
Jun 04 20:55:26: us=876304 /sbin/route add -net 192.168.222.0 192.168.222.5 255.255.255.0
Jun 04 20:55:26: us=880650 Initialization Sequence Completed
Jun 04 20:55:26: us=880694 MANAGEMENT: >STATE:1433465726,CONNECTED,SUCCESS,192.168.222.6,((MY_SERVER_IP))
Jun 04 20:55:27: us=78772 MANAGEMENT: CMD 'status'
Jun 04 20:55:28: us=81259 MANAGEMENT: CMD 'status'
Jun 04 20:55:29: us=83863 MANAGEMENT: CMD 'status'

#### Deleted about 100 of these, all the same except for the timestamp.

Jun 04 20:57:22: us=476672 MANAGEMENT: CMD 'status'
Jun 04 20:57:23: us=481178 MANAGEMENT: CMD 'status'
Jun 04 20:57:23: us=541003 MANAGEMENT: CMD 'signal SIGTERM'
Jun 04 20:57:23: us=541424 MANAGEMENT: TCP send error: Broken pipe
Jun 04 20:57:23: us=541439 MANAGEMENT: Client disconnected
Jun 04 20:57:23: us=541443 TCP/UDP: Closing socket
Jun 04 20:57:23: us=541502 /sbin/route delete -net 192.168.222.0 192.168.222.5 255.255.255.0
Jun 04 20:57:23: us=543758 Closing TUN/TAP interface
Jun 04 20:57:23: us=544007 SIGTERM[hard,] received, process exiting
Jun 04 20:57:23: us=544033 MANAGEMENT: >STATE:1433465843,EXITING,SIGTERM,,

The disconnect at the end was a manual shutdown of the client OpenVPN instance; the error happened at 20:56.

And the server log:

Code: Select all

Jun  4 20:09:09 svc ntpd_intres[9181]: host name not found: ntp01.MYDOMAIN.net
Jun  4 20:09:09 svc ntpd_intres[9181]: host name not found: ntp02.MYDOMAIN.net
Jun  4 20:25:44 svc ntpd_intres[9181]: host name not found: ntp01.MYDOMAIN.net
Jun  4 20:25:44 svc ntpd_intres[9181]: host name not found: ntp02.MYDOMAIN.net
Jun  4 20:42:19 svc ntpd_intres[9181]: host name not found: ntp01.MYDOMAIN.net
Jun  4 20:42:19 svc ntpd_intres[9181]: host name not found: ntp02.MYDOMAIN.net
Jun  4 20:44:28 svc ovpn-test[9779]: Current Parameter Settings:
Jun  4 20:44:28 svc ovpn-test[9779]:   config = '/etc/openvpn/test.conf'
Jun  4 20:44:28 svc ovpn-test[9779]:   mode = 1
Jun  4 20:44:28 svc ovpn-test[9779]:   persist_config = DISABLED
Jun  4 20:44:28 svc ovpn-test[9779]:   persist_mode = 1
Jun  4 20:44:28 svc ovpn-test[9779]:   show_ciphers = DISABLED
Jun  4 20:44:28 svc ovpn-test[9779]:   show_digests = DISABLED
Jun  4 20:44:28 svc ovpn-test[9779]:   show_engines = DISABLED
Jun  4 20:44:28 svc ovpn-test[9779]:   genkey = DISABLED
Jun  4 20:44:28 svc ovpn-test[9779]:   key_pass_file = '[UNDEF]'
Jun  4 20:44:28 svc ovpn-test[9779]:   show_tls_ciphers = DISABLED
Jun  4 20:44:28 svc ovpn-test[9779]: Connection profiles [default]:
Jun  4 20:44:28 svc ovpn-test[9779]:   proto = udp
Jun  4 20:44:28 svc ovpn-test[9779]:   local = '[UNDEF]'
Jun  4 20:44:28 svc ovpn-test[9779]:   local_port = 1194
Jun  4 20:44:28 svc ovpn-test[9779]:   remote = '[UNDEF]'
Jun  4 20:44:28 svc ovpn-test[9779]:   remote_port = 1194
Jun  4 20:44:28 svc ovpn-test[9779]:   remote_float = DISABLED
Jun  4 20:44:28 svc ovpn-test[9779]:   bind_defined = DISABLED
Jun  4 20:44:28 svc ovpn-test[9779]:   bind_local = ENABLED
Jun  4 20:44:28 svc ovpn-test[9779]: NOTE: --mute triggered...
Jun  4 20:44:28 svc ovpn-test[9779]: 251 variation(s) on previous 20 message(s) suppressed by --mute
Jun  4 20:44:28 svc ovpn-test[9779]: OpenVPN 2.1.3 i486-pc-linux-gnu [SSL] [LZO2] [EPOLL] [PKCS11] [MH] [PF_INET6] [eurephia] built on Dec  2 2014
Jun  4 20:44:28 svc ovpn-test[9779]: NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
Jun  4 20:44:28 svc ovpn-test[9779]: Diffie-Hellman initialized with 2048 bit key
Jun  4 20:44:28 svc ovpn-test[9779]: /usr/bin/openssl-vulnkey -q -b 2048 -m <modulus omitted>
Jun  4 20:44:28 svc ovpn-test[9779]: WARNING: file '/etc/openvpn/easy-rsa/keys/ta.bm1vsrv01.key' is group or others accessible
Jun  4 20:44:28 svc ovpn-test[9779]: Control Channel Authentication: using '/etc/openvpn/easy-rsa/keys/ta.bm1vsrv01.key' as a OpenVPN static key file
Jun  4 20:44:28 svc ovpn-test[9779]: Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Jun  4 20:44:28 svc ovpn-test[9779]: Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
Jun  4 20:44:28 svc ovpn-test[9779]: TLS-Auth MTU parms [ L:1542 D:166 EF:66 EB:0 ET:0 EL:0 ]
Jun  4 20:44:28 svc ovpn-test[9779]: Socket Buffers: R=[112640->131072] S=[112640->131072]
Jun  4 20:44:28 svc ovpn-test[9779]: ROUTE default_gateway=((MY_SERVER_IP))
Jun  4 20:44:28 svc ovpn-test[9779]: TUN/TAP device tun0 opened
Jun  4 20:44:28 svc ovpn-test[9779]: TUN/TAP TX queue length set to 100
Jun  4 20:44:28 svc ovpn-test[9779]: /sbin/ifconfig tun0 192.168.222.1 pointopoint 192.168.222.2 mtu 1500
Jun  4 20:44:28 svc zebra[9840]: warning: PtP interface tun0 with addr 192.168.222.1/32 needs a peer address
Jun  4 20:44:28 svc ovpn-test[9779]: /sbin/route add -net 192.168.222.0 netmask 255.255.255.0 gw 192.168.222.2
Jun  4 20:44:28 svc ovpn-test[9779]: Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Jun  4 20:44:28 svc ovpn-test[9788]: GID set to nobody
Jun  4 20:44:28 svc ovpn-test[9788]: UID set to nobody
Jun  4 20:44:28 svc ovpn-test[9788]: UDPv4 link local (bound): [undef]
Jun  4 20:44:28 svc ovpn-test[9788]: UDPv4 link remote: [undef]
Jun  4 20:44:28 svc ovpn-test[9788]: MULTI: multi_init called, r=256 v=256
Jun  4 20:44:28 svc ovpn-test[9788]: IFCONFIG POOL: base=192.168.222.4 size=62
Jun  4 20:44:28 svc ovpn-test[9788]: Initialization Sequence Completed
Jun  4 20:49:06 svc ntpd[9171]: Listen normally on 15 tun0 192.168.222.1 UDP 123
Jun  4 20:49:08 svc ntpd_intres[9181]: host name not found: ntp01.MYDOMAIN.net
Jun  4 20:49:08 svc ntpd_intres[9181]: host name not found: ntp02.MYDOMAIN.net
[...]
Jun  4 20:55:23 svc ovpn-test[9788]: MULTI: multi_create_instance called
Jun  4 20:55:23 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Re-using SSL/TLS context
Jun  4 20:55:23 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 LZO compression initialized
Jun  4 20:55:23 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Control Channel MTU parms [ L:1542 D:166 EF:66 EB:0 ET:0 EL:0 ]
Jun  4 20:55:23 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Jun  4 20:55:23 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Local Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-server'
Jun  4 20:55:23 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher BF-CBC,auth SHA1,keysize 128,tls-auth,key-method 2,tls-client'
Jun  4 20:55:23 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Local Options hash (VER=V4): '14168603'
Jun  4 20:55:23 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Expected Remote Options hash (VER=V4): '504e774e'
Jun  4 20:55:23 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 TLS: Initial packet from [AF_INET]((MY_IPADDRESS)):61629, sid=cc3734a4 f38f12d9
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Replay-window backtrack occurred [1]
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 CRL CHECK OK: /C=US ((( REDACTED )))
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 VERIFY OK: depth=1, /C=US ((( REDACTED )))
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 CRL CHECK OK: /C=US ((( REDACTED )))
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 VERIFY OK: depth=0, /C=US ((( REDACTED )))
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Jun  4 20:55:24 svc ovpn-test[9788]: ((MY_IPADDRESS)):61629 [((MY_KEYNAME))-temp] Peer Connection Initiated with [AF_INET]((MY_IPADDRESS)):61629
Jun  4 20:55:24 svc ovpn-test[9788]: MULTI: new connection by client '((MY_KEYNAME))-temp' will cause previous active sessions by this client to be dropped.  Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
Jun  4 20:55:24 svc ovpn-test[9788]: MULTI: Learn: 192.168.222.6 -> ((MY_KEYNAME))-temp/((MY_IPADDRESS)):61629
Jun  4 20:55:24 svc ovpn-test[9788]: MULTI: Learn: 192.168.222.6 -> ((MY_KEYNAME))-temp/((MY_IPADDRESS)):61629
Jun  4 20:55:24 svc ovpn-test[9788]: MULTI: primary virtual IP for ((MY_KEYNAME))-temp/((MY_IPADDRESS)):61629: 192.168.222.6
Jun  4 20:55:26 svc ovpn-test[9788]: ((MY_KEYNAME))-temp/((MY_IPADDRESS)):61629 PUSH: Received control message: 'PUSH_REQUEST'
Jun  4 20:55:26 svc ovpn-test[9788]: ((MY_KEYNAME))-temp/((MY_IPADDRESS)):61629 SENT CONTROL [((MY_KEYNAME))-temp]: 'PUSH_REPLY,dhcp-option DNS 192.168.96.6,dhcp-option DNS 192.168.96.4,dhcp-option DNS 192.168.70.6,dhcp-option DOMAIN sinenomine.net,tun-ipv6,route 192.168.222.0 255.255.255.0,topology net30,ping 10,ping-restart 120,ifconfig 192.168.222.6 192.168.222.5' (status=1)
Jun  4 20:57:24 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:57:34 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:57:44 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:57:54 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:58:04 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:58:14 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:58:24 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:58:34 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:58:44 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:58:54 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:59:04 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:59:14 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:59:25 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:59:35 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:59:45 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Jun  4 20:59:55 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)

The file transfer test was started just a few seconds after the VPN connected, and it failed at 20:56, which in the server log is when those ECONNREFUSED errors start appearing.

In the client log, there was *nothing* of note other than more of those status check messages. I looked very carefully before redacting that section of the log, for length, to make sure I wasn't deleting the one message that would hold a vital clue.

Thanks for any help here. I'm at wit's end.

Traffic · Post by **Traffic** » Fri Jun 05, 2015 12:53 pm

scourtney wrote:Jun 04 20:55:22: us=670353 status_file = '[UNDEF]'
Jun 04 20:55:22: us=670362 status_file_version = 1
Jun 04 20:55:22: us=670368 status_file_update_freq = 60

define a status file and then see what is reported.
Also, update_freq = 60 but:

scourtney wrote:Jun 04 20:55:27: us=78772 MANAGEMENT: CMD 'status'
Jun 04 20:55:28: us=81259 MANAGEMENT: CMD 'status'
Jun 04 20:55:29: us=83863 MANAGEMENT: CMD 'status'

#### Deleted about 100 of these, all the same except for the timestamp.

updated every second ?

For testing

scourtney wrote:'PUSH_REPLY,dhcp-option DNS 192.168.96.6,dhcp-option DNS 192.168.96.4,dhcp-option DNS 192.168.70.6,dhcp-option DOMAIN ((MY_DOMAIN)),tun-ipv6 ...

remove these directives from your server config.

As your server is a test config remove the --mute directive and capture complete logs.

Is this the most up to date version for your server distro ?

scourtney wrote:OpenVPN 2.1.3 i486-pc-linux-gnu [SSL] [LZO2] [EPOLL] [PKCS11] [MH] [PF_INET6] [eurephia] built on Dec 2 2014

This is unusual:

scourtney wrote:Jun 4 20:44:28 svc ovpn-test[9779]: /sbin/ifconfig tun0 192.168.222.1 pointopoint 192.168.222.2 mtu 1500
Jun 4 20:44:28 svc zebra[9840]: warning: PtP interface tun0 with addr 192.168.222.1/32 needs a peer address
Jun 4 20:44:28 svc ovpn-test[9779]: /sbin/route add -net 192.168.222.0 netmask 255.255.255.0 gw 192.168.222.2

please post the full server config used.

scourtney wrote:Jun 4 20:55:24 svc ovpn-test[9788]: MULTI: new connection by client '((MY_KEYNAME))-temp' will cause previous active sessions by this client to be dropped. Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.

indicating the client end dropped the connection without informing the server .. try --explicit-exit-notify in the client config.

For testing remove this:

scourtney wrote:Jun 4 20:44:28 svc ovpn-test[9788]: GID set to nobody
Jun 4 20:44:28 svc ovpn-test[9788]: UID set to nobody

and finally this:

scourtney wrote:Jun 4 20:57:24 svc ovpn-test[9788]: read UDPv4 [ECONNREFUSED]: Connection refused (code=111)

both client and server have not detected that a network error has occurred and the VPN connection is no longer available .. under these circumstances I suspect a router between server & client has timed out the UDP NAT port.

scourtney wrote:Doing the same file transfer to the public IP of the same server (that is, bypassing OpenVPN but still going between the same two computers over the same public Internet path) works perfectly, and reliably.

which is using TCP not UDP.

scourtney wrote:If I change from "proto udp" to "proto tcp" the problem is resolved, but then everything is slow because you're nesting TCP within TCP.

more evidence that it is a UDP NAT timeout ..

Traffic wrote:I would check all the physical routers used by the problem clients ..

check UDP settings.

I think you are expecting OpenVPN to diagnose your network problems for you .. it will not do that.

You clearly have a network problem related to UDP not an OpenVPN problem.

scourtney · Post by **scourtney** » Sat Jun 06, 2015 11:20 pm

Traffic wrote:I would check all the physical routers used by the problem clients .. check UDP settings.

I think you are expecting OpenVPN to diagnose your network problems for you .. it will not do that.

You clearly have a network problem related to UDP not an OpenVPN problem.

Thanks much for the detailed post, Traffic. I am only quoting an excerpt above, but I did read all of carefully.

Based on your comments, I decided rather than doing further OpenVPN testing, I would take your suggestion about looking at the underlying UDP. I had assumed that the physical network was okay, because the destination is at a commercial colo site, but it turns out you are correct.

I can replicate packet loss a few megabytes into a simple "netcat" UDP data transfer test, with OpenVPN being entirely out of the picture.

I checked the kernel settings for things like netcat_dev_backlog, and I checked to make sure iptables wasn't limiting UDP traffic. All of our company's routers and firewalls are out of the pathway of my test today, so we can rule those out. It seems I need to pursue this with our Internet provider at the colo. I will open a support ticket with them.

Thanks for the input. I guess I should not have assumed that since most of the connectivity is fine, that there was not a problem with the underlying pathway. I'll pursue this at the next level down the stack rather than continuing to try to solve it in OpenVPN configs.

scourtney · Post by **scourtney** » Fri Jun 19, 2015 1:31 pm

We worked with our upstream provider, and Traffic's comments proved correct. They had made a change to a network security appliance that was incorrectly treating our UDP 1194 traffic as an attempted DoS attack. Once they opened that filter, our OpenVPN now works just fine with all the default settings for MTU and related.

This ISP has been so absolutely perfect in our long relationship, that trouble from their end was the *last* thing we expected, but....there it is.

Thanks to those who responded here and steered us in the right direction. I consider this problem to be closed.

Traffic · Post by **Traffic** » Fri Jun 19, 2015 7:11 pm

Thank you very much for your concise and informative feed back

What is it they say: "It is always in the last place you look"

Shall we close this thread as Solved ?

OpenVPN Support Forum

MTU problems not fixed by the usual solutions

MTU problems not fixed by the usual solutions

Re: MTU problems not fixed by the usual solutions

Re: MTU problems not fixed by the usual solutions

Re: MTU problems not fixed by the usual solutions

Re: MTU problems not fixed by the usual solutions

Re: MTU problems not fixed by the usual solutions

Re: MTU problems not fixed by the usual solutions

Re: MTU problems not fixed by the usual solutions

Re: MTU problems not fixed by the usual solutions

Re: MTU problems not fixed by the usual solutions