ping-restart not recovering

ras

I have a number of clients (openwrt and Debian wheezy) connecting to a couple of Debian Wheezy servers. Every so often seemingly random intervals (measured in days) clients will drop out. When you look at the client everything appears to be OK - openvpn is running and it is retrying to connect to the server at regular intervals. When this happening restarting or rebooting the client does not help. Restarting the server does fix the problem, as does killing that clients connection using the management interface. When the server isn't in this "mode" clients can restart at will.

The server config is:

dev tun
management 127.0.0.1 1196
mssfix 1400
nice -10
ping 60
ping-exit 300

proto tcp-server
server 172.17.18.0 255.255.255.0
script-security 2
client-connect /etc/openvpn/openvpn-client-connect.sh
client-disconnect /etc/openvpn/openvpn-client-disconnect.sh
client-to-client
float

dh dh1024.pem
cipher none
ca openvpn-ROOT-cert.pem
cert openvpn-server-cert.pem
hand-window 300
key openvpn-server-key.pem

The client config is:

remote PRIVATE.com
dev tun
float
fragment 1400
management 127.0.0.1 1195
mssfix
mtu-test
passtos
ping 60
ping-restart 300
proto udp
up /etc/openvpn/connected.sh

pull
tls-client
cipher none
ca /etc/openvpn/openvpn-ROOT-cert.pem
cert /etc/openvpn/openvpn-10.31.0.2-cert.pem
key /etc/openvpn/openvpn-10.31.0.2-key.pem
ns-cert-type server
hand-window 300

When this happens, the server logs lots of entries of like this every time a packet is sent to a dead client. It you use the management interface to kill the connection for a client that client starts working, and messages for it stop (but messages for any other dead clients continue):

Apr  5 15:14:09 HOST ovpn-openvpn-udp[6695]: 10.74.0.2/1.1.1.1:1194 write UDPv4 []: No such device (code=19)

Prior to that, the server often writes line like this for each dead client:

Apr  5 14:26:29 HOST ovpn-openvpn-udp[6695]: 10.74.0.2/1.1.1.1:1194 write UDPv4 []: Invalid argument (code=22)

In the particular case I am looking at, I can see what triggered this. The ADSL connection OpenWrt dropped out. When the ADSL connection dropped out the packets will be routed by the kernel over the backup connection (which has a different IP, of course). The ADSL connection has now been automatically been brought back up, and the routes have been restored, but now all of OpenVpn's clients are dead. I don't particularly care what happens while the ADSL connection is dead, but it would be nice if OpenVpn recovered when it came back up.

This also happens on a non-multihomed host, but I don't know whether it happens when it's connection goes down.

This is the log the client's print while they are trying to reconnect when the server is in this "mode". It appears to be identical to when the client's connect successfully:

Apr  5 16:01:13 (none) daemon.notice openvpn[789]: [server] Inactivity timeout (--ping-restart), restarting
Apr  5 16:01:13 (none) daemon.notice openvpn[789]: SIGUSR1[soft,ping-restart] received, process restarting
Apr  5 16:01:15 (none) daemon.warn openvpn[789]: IMPORTANT: OpenVPN's default port number is now 1194, based on an official port number assignment by IANA.  OpenVPN 2.0-beta16 and earlier used 5000 as the default port.
Apr  5 16:01:15 (none) daemon.warn openvpn[789]: WARNING: file '/etc/openvpn/openvpn-10.31.0.2-key.pem' is group or others accessible
Apr  5 16:01:15 (none) daemon.warn openvpn[789]: ******* WARNING *******: null cipher specified, no encryption will be used
Apr  5 16:01:15 (none) daemon.notice openvpn[789]: UDPv4 link local (bound): [undef]:1194
Apr  5 16:01:15 (none) daemon.notice openvpn[789]: UDPv4 link remote: 1.1.1.1:1194
Apr  5 16:01:18 (none) daemon.notice openvpn[789]: [server] Peer Connection Initiated with 1.1.1.1:1194
Apr  5 16:01:19 (none) daemon.err openvpn[789]: Options error: Unrecognized option or missing parameter(s) in [PUSH-OPTIONS]:2: topology (2.0.9)
Apr  5 16:01:19 (none) daemon.notice openvpn[789]: TUN/TAP device tun0 opened
Apr  5 16:01:19 (none) daemon.notice openvpn[789]: /sbin/ifconfig tun0 172.17.17.18 pointopoint 172.17.17.17 mtu 1500
Apr  5 16:01:19 (none) daemon.notice openvpn[789]: /etc/openvpn/connected.sh tun0 1500 1529 172.17.17.18 172.17.17.17 init
Apr  5 16:01:20 (none) daemon.notice openvpn[789]: Initialization Sequence Completed

maikcat

please post your CORRECT configs (your server uses tcp & your client udp?)

also post the version of openvpn used both server/client

Michael.

ras

Bugger - sorry. I run both tcp and udp, and posted the wrong one.

dev tun
fragment 1400
management 127.0.0.1 1195
mssfix 1400
multihome
nice -10
ping 60
ping-exit 300

proto udp
server 172.17.17.0 255.255.255.0
script-security 2
client-connect /etc/openvpn/openvpn-client-connect.sh
client-disconnect /etc/openvpn/openvpn-client-disconnect.sh
client-to-client
float

dh dh1024.pem
cipher none
ca openvpn-ROOT-cert.pem
cert openvpn-server-cert.pem
key openvpn-server-key.pem

udp is the one with the problem. tcp is only used rarely - mostly on nated 3G connections where the UDP nat timeout is very short.

ras

Hmmm. No replies.

Well for now the work-around is to restart it when the ADSL connection comes back up.

Should I report this as a bug?

ras

I'll start accumulating information for a bug report here. The server is running on Debian Squeeze, the package is openvpn-2.2.1-8. The kernel is Linux 2.6.32-5-amd64.

I set verb=11, and waited for it to happen. After a few days, the ADSL dies, rapidly followed by openvpn's UDP returning EINVAL which is not unexpected:

Apr 23 02:11:29 hostxxxx pppoe[15021]: read (asyncReadFromPPP): Session 1348: Input/output error
Apr 23 02:11:29 hostxxxx pppoe[15021]: Sent PADT
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 0
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0020
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 FRAG_OUT len=16 type=0 seq_id=0 frag_id=0 frag_size=0 flags=0x00000000
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 TLS: tls_pre_encrypt: key_id=2
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 SENT PING
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 TIMER: coarse timer wakeup 60 seconds
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 RANDOM USEC=5953
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 SCHEDULE: schedule_add_modify wakeup=[Tue Apr 23 02:11:33 2013 us=5926] pri=775323775
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: SCHEDULE: schedule_find_least wakeup=[Tue Apr 23 02:11:30 2013 us=207887] pri=1739488838
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0002 ev=6 arg=0x0068cdf0
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0000 ev=7 arg=0x0068cce8
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT Tr|Tw|Sr|SW [0/207914]
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: PO_WAIT[0,0] fd=6 rev=0x00000004 rwflags=0x0002 arg=0x0068cdf0 
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 1
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0002
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 UDPv4 WRITE [45] to [AF_INET]1.1.1.1:1194 (via [AF_INET]1.1.1.2%[undef]): P_DATA_V1 kid=2 DATA ca3f1101 bc63089a aee00372 0beb2a40 b0823b59 0000002b 00000000 2a187bf[more...]
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 UDPv4 write returned -1
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 write UDPv4 []: Invalid argument (code=22)
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=6 arg=0x0068cdf0
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=7 arg=0x0068cce8
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:11:29 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT TR|Tw|SR|Sw [0/207914]
Apr 23 02:11:30 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 0
Apr 23 02:11:30 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0020
Apr 23 02:11:30 hostxxxx ovpn-openvpn-udp[18600]: MULTI: REAP range 48 -> 64
Apr 23 02:11:30 hostxxxx ovpn-openvpn-udp[18600]: 10.26.0.2/124.171.96.9:1194 SCHEDULE: schedule_add_modify wakeup=[Tue Apr 23 02:11:36 2013 us=207887] pri=1739488838

A short white latter the ADSL comes back up. But then the very next write after the new ppp connection comes back up, and most UDP writes thereafter gets errno 19, ENODEV:

Apr 23 02:11:59 hostxxxx pppoe[20347]: PADS: Service-Name: ''
Apr 23 02:11:59 hostxxxx pppoe[20347]: PPP session is 8567 (0x2177)
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 0
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0020
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: MULTI: REAP range 176 -> 192
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 RANDOM USEC=201488
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 SCHEDULE: schedule_add_modify wakeup=[Tue Apr 23 02:12:06 2013 us=152885] pri=502834358
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: SCHEDULE: schedule_find_least wakeup=[Tue Apr 23 02:12:01 2013 us=51145] pri=1288504809
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=6 arg=0x0068cdf0
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=7 arg=0x0068cce8
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT TR|Tw|SR|Sw [0/51172]
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 0
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0020
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: 10.74.0.2/211.26.11.236:1194 SCHEDULE: schedule_add_modify wakeup=[Tue Apr 23 02:12:06 2013 us=51145] pri=1288504809
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: SCHEDULE: schedule_find_least wakeup=[Tue Apr 23 02:12:01 2013 us=89592] pri=784426272
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=6 arg=0x0068cdf0
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=7 arg=0x0068cce8
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT TR|Tw|SR|Sw [0/89619]
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 0
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0020
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: 10.26.0.2/1.1.1.4:1194 SCHEDULE: schedule_add_modify wakeup=[Tue Apr 23 02:12:05 2013 us=89592] pri=784426272
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: SCHEDULE: schedule_find_least wakeup=[Tue Apr 23 02:12:01 2013 us=156323] pri=1645465618
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=6 arg=0x0068cdf0
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=7 arg=0x0068cce8
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT TR|Tw|SR|Sw [0/156350]
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 0
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0020
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: 10.75.0.2/210.15.202.50:1194 RANDOM USEC=31923
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: 10.75.0.2/210.15.202.50:1194 SCHEDULE: schedule_add_modify wakeup=[Tue Apr 23 02:12:05 2013 us=31896] pri=1645465618
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: SCHEDULE: schedule_find_least wakeup=[Tue Apr 23 02:12:03 2013 us=84619] pri=1739694724
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=6 arg=0x0068cdf0
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=7 arg=0x0068cce8
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:12:00 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT TR|Tw|SR|Sw [2/84646]
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 0
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0020
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: MULTI: REAP range 192 -> 208
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 TLS: tls_multi_process: i=0 state=S_NORMAL_OP, mysid=6b6944fe 1e5e6c49, stored-sid=9cebbb22 6122e09b, stored-ip=[AF_INET]1.1.1.1:1194 (via [AF_INET]1.1.1.2%[undef])
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 TLS: tls_process: chg=0 ks=S_NORMAL_OP lame=S_NORMAL_OP to_link->len=0 wakeup=1288
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 STATE S_NORMAL_OP
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 ACK reliable_can_send active=0 current=0 : [38]
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 ACK reliable_send_timeout 604800 [38]
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 TLS: tls_process: timeout set to 1288
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=b8790e92 a00adcae, stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: 10.25.0.2/1.1.1.1:1194 SCHEDULE: schedule_add_modify wakeup=[Tue Apr 23 02:12:05 2013 us=84619] pri=1739694724
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: SCHEDULE: schedule_find_least wakeup=[Tue Apr 23 02:12:04 2013 us=31033] pri=1920699894
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=6 arg=0x0068cdf0
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=7 arg=0x0068cce8
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:12:02 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT TR|Tw|SR|Sw [1/31060]
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_WAIT[0,0] fd=6 rev=0x00000001 rwflags=0x0001 arg=0x0068cdf0 
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 1
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0001
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: MULTI: REAP range 208 -> 224
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: UDPv4 read returned 45
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: GET INST BY REAL: 1.1.1.4:1194 [succeeded]
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.26.0.2/1.1.1.4:1194 UDPv4 READ [45] from [AF_INET]1.1.1.4:1194 (via [AF_INET]1.1.1.2%ppp0): P_DATA_V1 kid=3 DATA 9139048c 821490e0 aea8df2e 4769d0d8 0e08f7f6 00000032 00000000 2a187bf[more...]
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.26.0.2/1.1.1.4:1194 TLS: tls_pre_decrypt, key_id=3, IP=[AF_INET]1.1.1.4:1194 (via [AF_INET]1.1.1.2%ppp0)
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.26.0.2/1.1.1.4:1194 PID TEST 0:49 0:50
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.26.0.2/1.1.1.4:1194 FRAG_IN buf->len=16 type=FRAG_WHOLE flags=0x00000000
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.26.0.2/1.1.1.4:1194 RECEIVED PING PACKET
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=6 arg=0x0068cdf0
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=7 arg=0x0068cce8
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT TR|Tw|SR|Sw [0/31060]
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 0
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0020
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.31.0.2/1.1.1.5:1194 SCHEDULE: schedule_add_modify wakeup=[Tue Apr 23 02:12:09 2013 us=31033] pri=1920699894
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: SCHEDULE: schedule_find_least wakeup=[Tue Apr 23 02:12:04 2013 us=192451] pri=1217364424
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=6 arg=0x0068cdf0
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=7 arg=0x0068cce8
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT TR|Tw|SR|Sw [0/192478]
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_WAIT[1,0] fd=7 rev=0x00000001 rwflags=0x0001 arg=0x0068cce8 
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 1
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0004
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]:  read from TUN/TAP returned 84
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: GET INST BY VIRT: 10.24.0.2 -> 10.24.0.2/1.1.1.3:1194 via 10.24.0.2
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TUN READ [84]
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 FRAG_OUT len=84 type=0 seq_id=0 frag_id=0 frag_size=0 flags=0x00000000
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: tls_pre_encrypt: key_id=3
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0002 ev=6 arg=0x0068cdf0
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0000 ev=7 arg=0x0068cce8
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT Tr|Tw|Sr|SW [0/192478]
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_WAIT[0,0] fd=6 rev=0x00000004 rwflags=0x0002 arg=0x0068cdf0 
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 1
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0002
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 UDPv4 WRITE [113] to [AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%[undef]): P_DATA_V1 kid=3 DATA e392ee22 3ecb43ce 1d62b76d dc943b7a ae6757ff 0000000d 00000000 4500005[more...]
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 UDPv4 write returned -1
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 write UDPv4 []: No such device (code=19)
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=6 arg=0x0068cdf0
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=7 arg=0x0068cce8
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:12:03 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT TR|Tw|SR|Sw [0/192478]

Oddly the occasional packet does manage to get sent. Eg:

Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: PO_WAIT[0,0] fd=6 rev=0x00000001 rwflags=0x0001 arg=0x0068cdf0 
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 1
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0001
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: MULTI: REAP range 144 -> 160
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: UDPv4 read returned 14
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: GET INST BY REAL: 1.1.1.3:1194 [succeeded]
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 UDPv4 READ [14] from [AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%ppp0): P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 sid=d43d29c0 4106547e [ ] pid=0 DATA 
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: control channel, op=P_CONTROL_HARD_RESET_CLIENT_V2, IP=[AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%ppp0)
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: initial packet test, i=0 state=S_NORMAL_OP, mysid=6fe9d811 8a1adf57, rec-sid=d43d29c0 4106547e, rec-ip=[AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%ppp0), stored-sid=4436b9b8 2dd9430c, stored-ip=[AF_INET]1.1.1.3:1194 (via [AF_INET]58.108.240.218%[undef])
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: initial packet test, i=1 state=S_INITIAL, mysid=b3adfd26 5747f982, rec-sid=d43d29c0 4106547e, rec-ip=[AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%ppp0), stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: initial packet test, i=2 state=S_UNDEF, mysid=00000000 00000000, rec-sid=d43d29c0 4106547e, rec-ip=[AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%ppp0), stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: new session incoming connection from [AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%ppp0)
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK read ID 0 (buf->len=0)
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK RWBS rel->size=8 rel->packet_id=00000000 id=00000000 ret=1
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK mark active incoming ID 0
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK acknowledge ID 0 (ack->len=1)
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: tls_multi_process: i=0 state=S_NORMAL_OP, mysid=6fe9d811 8a1adf57, stored-sid=4436b9b8 2dd9430c, stored-ip=[AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%[undef])
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: tls_process: chg=0 ks=S_NORMAL_OP lame=S_NORMAL_OP to_link->len=0 wakeup=2779
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 STATE S_NORMAL_OP
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK reliable_can_send active=0 current=0 : [38]
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK reliable_send_timeout 604800 [38]
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: tls_process: timeout set to 2779
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=b3adfd26 5747f982, stored-sid=d43d29c0 4106547e, stored-ip=[AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%ppp0)
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: tls_process: chg=0 ks=S_INITIAL lame=S_UNDEF to_link->len=0 wakeup=2779
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK mark active outgoing ID 0
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: Initial Handshake, sid=b3adfd26 5747f982
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK reliable_can_send active=1 current=1 : [1] 0
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK reliable_send ID 0 (size=4 to=2)
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK write ID 0 (ack->len=1, n=1)
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 Reliable -> TCP/UDP
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 ACK reliable_send_timeout 2 [1] 0
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: tls_process: timeout set to 2
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0002 ev=6 arg=0x0068cdf0
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0000 ev=7 arg=0x0068cce8
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT Tr|Tw|Sr|SW [1/56386]
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: PO_WAIT[0,0] fd=6 rev=0x00000004 rwflags=0x0002 arg=0x0068cdf0 
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 1
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0002
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 UDPv4 WRITE [26] to [AF_INET]1.1.1.3:1194 (via [AF_INET]1.1.1.2%ppp0): P_CONTROL_HARD_RESET_SERVER_V2 kid=0 sid=b3adfd26 5747f982 [ 0 sid=d43d29c0 4106547e ] pid=0 DATA 
Apr 23 02:15:05 hostxxxx ovpn-openvpn-udp[18600]: 10.24.0.2/1.1.1.3:1194 UDPv4 write returned 26

At this point the VPN is down for all clients. The clients notice this and repeatedly try to reconnect, but it doesn't work as this server gets an ENODEV whenever it tries to write it's response. This is at 2 AM. By 7 AM I am getting phone calls. Eventually I get into work, address the other fires, then fix the problem by executing "kill" commands on every connection using openvpn's telnet management interface. The others continue to get ENODEV until I also kill them via the management interface:

Apr 23 08:22:22 hostxxxx ovpn-openvpn-udp[18600]: MANAGEMENT: CMD 'kill 1.1.1.5:1194'
Apr 23 08:22:22 hostxxxx ovpn-openvpn-udp[18600]: 10.31.0.2/1.1.1.5:1194 SIGTERM[soft,] received, client-instance exiting
Apr 23 08:22:22 hostxxxx ovpn-openvpn-udp[18600]: MULTI: multi_close_instance called
Apr 23 08:22:22 hostxxxx ovpn-openvpn-udp[5403]: PKCS#11: __pkcs11h_forkFixup entry pid=5403, activate_slotevent=1
Apr 23 08:22:22 hostxxxx ovpn-openvpn-udp[5403]: PKCS#11: __pkcs11h_forkFixup return

After the connection is killed in the management interface the next time the client's ping-restart attempts to reconnect, it succeeds:

Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 1
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0001
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: UDPv4 read returned 14
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: MULTI: multi_create_instance called
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 Re-using SSL/TLS context
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 MTU DYNAMIC mtu=0, flags=1, 0 -> 138
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_session_init: entry
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 PID packet_id_init seq_backtrack=64 time_backtrack=15
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 PID packet_id_init seq_backtrack=64 time_backtrack=15
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_session_init: new session object, sid=1d233120 6e45b016
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_session_init: entry
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 PID packet_id_init seq_backtrack=64 time_backtrack=15
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 PID packet_id_init seq_backtrack=64 time_backtrack=15
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_session_init: new session object, sid=1a961a52 76651544
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 Control Channel MTU parms [ L:1529 D:138 EF:38 EB:0 ET:0 EL:0 ]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 MTU DYNAMIC mtu=1400, flags=2, 1529 -> 1400
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 MTU DYNAMIC mtu=1400, flags=2, 1529 -> 1400
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 Data Channel MTU parms [ L:1529 D:1400 EF:29 EB:4 ET:0 EL:0 AF:14/29 ]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 Fragmentation MTU parms [ L:1529 D:1400 EF:29 EB:4 ET:0 EL:0 AF:14/29 ]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 Local Options String: 'V4,dev-type tun,link-mtu 1529,tun-mtu 1500,proto UDPv4,mtu-dynamic,cipher [null-cipher],auth SHA1,keysize 0,key-method 2,tls-server'
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1529,tun-mtu 1500,proto UDPv4,mtu-dynamic,cipher [null-cipher],auth SHA1,keysize 0,key-method 2,tls-client'
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 Local Options hash (VER=V4): '61802901'
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 Expected Remote Options hash (VER=V4): '014bdc04'
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 SENT PING
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TIMER: coarse timer wakeup 1 seconds
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_multi_process: i=0 state=S_INITIAL, mysid=1d233120 6e45b016, stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=1a961a52 76651544, stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 RANDOM USEC=239796
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 SCHEDULE: schedule_add_modify wakeup=[Tue Apr 23 08:25:49 2013 us=191205] pri=0
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 GET INST BY REAL: 1.1.1.5:1194 [created]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 UDPv4 READ [14] from [AF_INET]1.1.1.5:1194 (via [AF_INET]1.1.1.2%ppp0): P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 sid=a23d9406 55f712bc [ ] pid=0 DATA 
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: control channel, op=P_CONTROL_HARD_RESET_CLIENT_V2, IP=[AF_INET]1.1.1.5:1194 (via [AF_INET]1.1.1.2%ppp0)
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: initial packet test, i=0 state=S_INITIAL, mysid=1d233120 6e45b016, rec-sid=a23d9406 55f712bc, rec-ip=[AF_INET]1.1.1.5:1194 (via [AF_INET]1.1.1.2%ppp0), stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: initial packet test, i=1 state=S_INITIAL, mysid=1a961a52 76651544, rec-sid=a23d9406 55f712bc, rec-ip=[AF_INET]1.1.1.5:1194 (via [AF_INET]1.1.1.2%ppp0), stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: initial packet test, i=2 state=S_UNDEF, mysid=00000000 00000000, rec-sid=a23d9406 55f712bc, rec-ip=[AF_INET]1.1.1.5:1194 (via [AF_INET]1.1.1.2%ppp0), stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: Initial packet from [AF_INET]1.1.1.5:1194 (via [AF_INET]1.1.1.2%ppp0), sid=a23d9406 55f712bc
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: received control channel packet s#=0 sid=a23d9406 55f712bc
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK reliable_schedule_now
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK read ID 0 (buf->len=0)
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK RWBS rel->size=8 rel->packet_id=00000000 id=00000000 ret=1
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK mark active incoming ID 0
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK acknowledge ID 0 (ack->len=1)
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_multi_process: i=0 state=S_INITIAL, mysid=1d233120 6e45b016, stored-sid=a23d9406 55f712bc, stored-ip=[AF_INET]1.1.1.5:1194 (via [AF_INET]1.1.1.2%ppp0)
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_process: chg=0 ks=S_INITIAL lame=S_UNDEF to_link->len=0 wakeup=604800
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK mark active outgoing ID 0
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: Initial Handshake, sid=1d233120 6e45b016
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK reliable_can_send active=1 current=1 : [1] 0
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK reliable_send ID 0 (size=4 to=2)
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK write ID 0 (ack->len=1, n=1)
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 Reliable -> TCP/UDP
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 ACK reliable_send_timeout 2 [1] 0
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_process: timeout set to 2
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_multi_process: i=1 state=S_INITIAL, mysid=1a961a52 76651544, stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 TLS: tls_multi_process: i=2 state=S_UNDEF, mysid=00000000 00000000, stored-sid=00000000 00000000, stored-ip=[undef]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: SCHEDULE: schedule_find_least wakeup=[Tue Apr 23 08:25:49 2013 us=20750] pri=1024425946
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0002 ev=6 arg=0x0068cdf0
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0000 ev=7 arg=0x0068cce8
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: PO_CTL rwflags=0x0001 ev=4 arg=0x0068cce4
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT Tr|Tw|Sr|SW [1/20765]
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: PO_WAIT[0,0] fd=6 rev=0x00000004 rwflags=0x0002 arg=0x0068cdf0 
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]:  event_wait returned 1
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: I/O WAIT status=0x0002
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 UDPv4 WRITE [26] to [AF_INET]1.1.1.5:1194 (via [AF_INET]1.1.1.2%ppp0): P_CONTROL_HARD_RESET_SERVER_V2 kid=0 sid=1d233120 6e45b016 [ 0 sid=a23d9406 55f712bc ] pid=0 DATA 
Apr 23 08:25:47 hostxxxx ovpn-openvpn-udp[18600]: 1.1.1.5:1194 UDPv4 write returned 26

One peculiar thing about this setup is the host is multi homed, meaning it has two connecitons to the internet. In order to ensure a packet gets routed over the correct interface, the kernel has some routing rules:

$ ip rule show
0:	from all lookup local 
12345:	from 1.1.1.2 lookup 50 
12345:	from 1.1.1.9 lookup 51 
32766:	from all lookup main 
32767:	from all lookup default

And the routing tables are:

$ ip route show table 50
172.17.18.2 dev tun0  proto kernel  scope link  src 172.17.18.1 
10.2.0.3 via 10.7.0.2 dev eth0  src 10.7.0.4 
192.168.216.27 via 1.1.1.10 dev eth0  src 1.1.1.9 
172.17.17.2 dev tun1  proto kernel  scope link  src 172.17.17.1 
10.24.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.26.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.88.0.0/24 dev tunAdl  scope link  src 10.7.0.4 
10.2.0.0/24 dev tunSyd  scope link  src 10.7.0.4 
10.74.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
192.168.1.0/24 dev eth1  proto kernel  scope link  src 192.168.1.63 
10.87.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.23.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.25.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.89.0.0/24 dev tunPer  scope link  src 10.7.0.4 
10.31.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
172.17.18.0/24 via 172.17.18.2 dev tun0 
10.3.0.0/24 dev tunMlb  scope link  src 10.7.0.4 
10.7.0.0/24 dev eth0  proto kernel  scope link  src 10.7.0.4 
10.75.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
172.17.17.0/24 via 172.17.17.2 dev tun1 
10.200.0.0/22 via 10.7.0.5 dev eth0  src 10.7.0.4 
172.27.176.0/22 via 10.7.0.2 dev eth0  src 10.7.0.4 
default dev ppp0  scope link  src 1.1.1.2 
default dev ppp0  scope link  src 1.1.1.2  metric 1
$ ip route show table 51
172.17.18.2 dev tun0  proto kernel  scope link  src 172.17.18.1 
10.2.0.3 via 10.7.0.2 dev eth0  src 10.7.0.4 
192.168.216.27 via 1.1.1.10 dev eth0  src 1.1.1.9 
172.17.17.2 dev tun1  proto kernel  scope link  src 172.17.17.1 
10.88.0.0/24 dev tunAdl  scope link  src 10.7.0.4 
10.24.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.26.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.2.0.0/24 dev tunSyd  scope link  src 10.7.0.4 
10.74.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
192.168.1.0/24 dev eth1  proto kernel  scope link  src 192.168.1.63 
10.87.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.23.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.89.0.0/24 dev tunPer  scope link  src 10.7.0.4 
10.25.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.31.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
10.3.0.0/24 dev tunMlb  scope link  src 10.7.0.4 
172.17.18.0/24 via 172.17.18.2 dev tun0 
10.7.0.0/24 dev eth0  proto kernel  scope link  src 10.7.0.4 
10.75.0.0/24 via 172.17.17.2 dev tun1  src 10.7.0.4 
172.17.17.0/24 via 172.17.17.2 dev tun1 
10.200.0.0/22 via 10.7.0.5 dev eth0  src 10.7.0.4 
172.27.176.0/22 via 10.7.0.2 dev eth0  src 10.7.0.4 
default via 1.1.1.10 dev eth0  src 1.1.1.9 metric 20