openvpn exec reconnect loop

[dpb587]

Recently it seems like openvpn has started going into a reconnect loop after a period of time (when run via ssoca openvpn exec). The user is required to manually interrupt/kill the process before it successfully reconnects.

This seems to be limited to cases which use the server-side, time-based verification of the client certificate with the ssoca-openvpn-verify option (which disables the connection if the cert is a few minutes after its validity start). This is probably compounded by cases where the network was interrupted and a fresh connection is attempted.

Things to consider...

• why has this recently become an issue? does openssl 1.1.1 change how these errors are propagated to openvpn [did it previously exit]? was there some exit behavior changes in recent ssoca versions?
• is this existing reconnect logic relevant? is it not working, or should it be expanded?
• configuring openvpn to exit after a fixed number of retries.
• configuring --reconnect as the default behavior? probably not; better to rely on process manager?

Client-side logs look like the following.

Tue Oct  1 17:02:43 2019 Socket Buffers: R=[131072->131072] S=[131072->131072]
Tue Oct  1 17:02:43 2019 Attempting to establish TCP connection with [AF_INET]192.0.2.123:1194 [nonblock]
Tue Oct  1 17:02:44 2019 TCP connection established with [AF_INET]192.0.2.123:1194
Tue Oct  1 17:02:44 2019 TCP_CLIENT link local: (not bound)
Tue Oct  1 17:02:44 2019 TCP_CLIENT link remote: [AF_INET]192.0.2.123:1194
Tue Oct  1 17:02:44 2019 TLS: Initial packet from [AF_INET]192.0.2.123:1194, sid=acaf88cf ff10484b
Tue Oct  1 17:02:45 2019 VERIFY OK: depth=1, C=USA, O=Cloud Foundry, CN=openvpn
Tue Oct  1 17:02:45 2019 VERIFY KU OK
Tue Oct  1 17:02:45 2019 Validating certificate extended key usage
Tue Oct  1 17:02:45 2019 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Tue Oct  1 17:02:45 2019 VERIFY EKU OK
Tue Oct  1 17:02:45 2019 VERIFY OK: depth=0, C=USA, O=Cloud Foundry, CN=server
Tue Oct  1 17:02:45 2019 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1560', remote='link-mtu 1559'
Tue Oct  1 17:02:45 2019 WARNING: 'comp-lzo' is present in local config but missing in remote config, local='comp-lzo'
Tue Oct  1 17:02:45 2019 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
Tue Oct  1 17:02:45 2019 [server] Peer Connection Initiated with [AF_INET]192.0.2.123:1194
Tue Oct  1 17:02:46 2019 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Tue Oct  1 17:02:46 2019 PUSH: Received control message: 'PUSH_REPLY,route 172.172.0.0 255.255.192.0,ping 15,ping-restart 60,route-gateway 172.172.172.1,topology subnet,ping 15,ping-restart 60,compress lz4-v2,ifconfig 172.172.172.2 255.255.255.0,peer-id 0,cipher AES-256-GCM'
Tue Oct  1 17:02:46 2019 OPTIONS IMPORT: timers and/or timeouts modified
Tue Oct  1 17:02:46 2019 OPTIONS IMPORT: compression parms modified
Tue Oct  1 17:02:46 2019 OPTIONS IMPORT: --ifconfig/up options modified
Tue Oct  1 17:02:46 2019 OPTIONS IMPORT: route options modified
Tue Oct  1 17:02:46 2019 OPTIONS IMPORT: route-related options modified
Tue Oct  1 17:02:46 2019 OPTIONS IMPORT: peer-id set
Tue Oct  1 17:02:46 2019 OPTIONS IMPORT: adjusting link_mtu to 1627
Tue Oct  1 17:02:46 2019 OPTIONS IMPORT: data channel crypto options modified
Tue Oct  1 17:02:46 2019 Data Channel: using negotiated cipher 'AES-256-GCM'
Tue Oct  1 17:02:46 2019 NCP: overriding user-set keysize with default
Tue Oct  1 17:02:46 2019 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Tue Oct  1 17:02:46 2019 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
Tue Oct  1 17:02:46 2019 Preserving previous TUN/TAP instance: utun5
Tue Oct  1 17:02:46 2019 Initialization Sequence Completed
# v data channel renegotiate
Tue Oct  1 18:02:46 2019 VERIFY OK: depth=1, C=USA, O=Cloud Foundry, CN=openvpn
Tue Oct  1 18:02:46 2019 VERIFY KU OK
Tue Oct  1 18:02:46 2019 Validating certificate extended key usage
Tue Oct  1 18:02:46 2019 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Tue Oct  1 18:02:46 2019 VERIFY EKU OK
Tue Oct  1 18:02:46 2019 VERIFY OK: depth=0, C=USA, O=Cloud Foundry, CN=server
Tue Oct  1 18:02:46 2019 Connection reset, restarting [0]
Tue Oct  1 18:02:46 2019 SIGUSR1[soft,connection-reset] received, process restarting
Tue Oct  1 18:02:46 2019 Restart pause, 5 second(s)
# ^ first failure
Tue Oct  1 18:02:51 2019 TCP/UDP: Preserving recently used remote address: [AF_INET]192.0.2.123:1194
Tue Oct  1 18:02:51 2019 Socket Buffers: R=[131072->131072] S=[131072->131072]
Tue Oct  1 18:02:51 2019 Attempting to establish TCP connection with [AF_INET]192.0.2.123:1194 [nonblock]
Tue Oct  1 18:02:52 2019 TCP connection established with [AF_INET]192.0.2.123:1194
Tue Oct  1 18:02:52 2019 TCP_CLIENT link local: (not bound)
Tue Oct  1 18:02:52 2019 TCP_CLIENT link remote: [AF_INET]192.0.2.123:1194
Tue Oct  1 18:02:52 2019 TLS: Initial packet from [AF_INET]192.0.2.123:1194, sid=b6e9698a 4f97696a
Tue Oct  1 18:02:52 2019 VERIFY OK: depth=1, C=USA, O=Cloud Foundry, CN=openvpn
Tue Oct  1 18:02:52 2019 VERIFY KU OK
Tue Oct  1 18:02:52 2019 Validating certificate extended key usage
Tue Oct  1 18:02:52 2019 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Tue Oct  1 18:02:52 2019 VERIFY EKU OK
Tue Oct  1 18:02:52 2019 VERIFY OK: depth=0, C=USA, O=Cloud Foundry, CN=server
Tue Oct  1 18:02:52 2019 Connection reset, restarting [0]
Tue Oct  1 18:02:52 2019 SIGUSR1[soft,connection-reset] received, process restarting
Tue Oct  1 18:02:52 2019 Restart pause, 5 second(s)
# ^ second failure; continues in backoff failure up to 5m