stale openvpn processes

I have been using Viscosity for years, and for a very long time it has worked flawlessly. In the last 6 months or so, I have started having problems. It will show that I am connected, yet no traffic will flow. When if first started happening I assumed it was a fluke and I would just reboot my system and things would start working again. However, this started happening more frequently to the point of being highly annoying, so I started looking into the problem more closely. As it turns out the problem is that I will get disconnected from the VPN, but the openvpn process (and associated tun device) remains running and Viscosity starts a second process. However, all of traffic continues to try and route over the stale openvpn process/tun device.

To fix this without rebooting, I have to disconnect from the vpn and thing kill off all of the stale openvpn processes. On my mac, I accomplish this with a ‘sudo killall openvpn’. Then I can reconnect to the vpn and everything works.

I would typically think that there was something specific to my system as other people don’t seem to be having the same problem, but this continues to occur after doing a fresh install of osx 10.10.1 (yosemite). Additionally, I also have a windows 8.1 machine which has the exact same problem and has ever since I first started using Viscosity on it about 6 months ago.

I am using the current version of viscosity (1.5.3).

Long tern I would like to see this problem resolved in Viscosity itself. Short term I suppose I could create a script that runs on before connect to look for stale processes and kill them.

Hi therevmj,

A couple of questions:

  1. Do you see this same behaviour with the latest beta version of Viscosity? It does not include anything to address such an issue, however using it should rule out any of the small bugs it addresses:
    https://www.sparklabs.com/forum/t/beta-latest-build-of-viscosity-for-mac/46/1

  2. For this to be occurring on both Mac and Windows it’s highly likely the problem lies with OpenVPN itself. Are you able to post a copy of your raw configuration file so we can see if we can replicate the issue with the same settings? You can find the raw configuration file for your connection at the path below. Please feel free to censor out any sensitive addresses or details.
    Your Home Folder/Library/Application Support/Viscosity/OpenVPN/#/config.conf

To get to your Library folder you’ll need to open the “Go” menu in the Finder while holding down the Option key on your keyboard and click the Library item. Your Library folder will open.

Cheers,
James

I’'ve installed the beta version on my Mac and will report back once I can determine if the problem occurs with it as well.

My raw config is as follows:

remote server1.domain.com 443 tcp-client
remote server2.domain.com 443 tcp-client
pull
comp-lzo yes
tls-auth ta.key 1
persist-key
ca ca.crt
dev tun
persist-tun
cert cert.crt
tls-client
nobind
key key.key
auth-nocache
script-security 2

Hi therevmj,

Thanks for providing your configuration. We haven’t managed to replicate any issues using a similar setup on either Mac or Windows. If you find you still have the same problem with the latest beta version please send along copies of your OpenVPN and Console logs covering from the time connecting until connection disconnects/dropouts (where an openvpn process appears to remain). Please feel free to censor these logs before posting, or email them to our support email address to avoid posting them publicly.

http://www.sparklabs.com/support/viewing_the_openvpn_log/
http://www.sparklabs.com/support/viewing_the_console_log/

Cheers,
James

Looks like it still happens with the beta version. Here is the (censored) openvpn log:

Feb 25 11:35:46: Initialization Sequence Completed
Feb 26 08:20:08: read TCPv4_CLIENT: Operation timed out (code=60)
Feb 26 08:20:08: Connection reset, restarting [0]
Feb 26 08:20:08: SIGUSR1[soft,connection-reset] received, process restarting
Feb 26 08:20:09: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Feb 26 08:20:44: RESOLVE: Cannot resolve host address: server1.domain.com: nodename nor servname provided, or not known
Feb 26 08:20:44: RESOLVE: Cannot resolve host address: server2.domain.com: nodename nor servname provided, or not known
Feb 26 08:20:44: SIGUSR1[soft,init_instance] received, process restarting
Feb 26 08:20:45: Viscosity Mac 1.5.4b10 (1265)
Feb 26 08:20:45: Viscosity OpenVPN Engine Started
Feb 26 08:20:45: Running on Mac OS X 10.10.1
Feb 26 08:20:45: ---------
Feb 26 08:20:45: Checking reachability status of connection…
Feb 26 08:20:45: Connection is reachable. Starting connection attempt.
Feb 26 08:20:45: OpenVPN 2.3.6 x86_64-apple-darwin [SSL (OpenSSL)] [LZO] [PKCS11] [MH] [IPv6] built on Jan 15 2015
Feb 26 08:20:45: library versions: OpenSSL 1.0.1k 8 Jan 2015, LZO 2.08
Feb 26 08:20:46: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
Feb 26 08:20:46: Control Channel Authentication: using ‘/var/folders/zz/zyxvpxvq6csfxvn_n0000000000000/T/connection.3s1nGK/ta.key’ as a OpenVPN static key file
Feb 26 08:20:46: Attempting to establish TCP connection with [AF_INET]XXX.XXX.XXX.XXX:443 [nonblock]
Feb 26 08:20:49: TCP connection established with [AF_INET]XXX.XXX.XXX.XXX:443
Feb 26 08:20:49: TCPv4_CLIENT link local: [undef]
Feb 26 08:20:49: TCPv4_CLIENT link remote: [AF_INET]XXX.XXX.XXX.XXX:443
Feb 26 08:20:51: [server] Peer Connection Initiated with [AF_INET]XXX.XXX.XXX.XXX:443
Feb 26 08:20:54: TUN/TAP device /dev/tun1 opened
Feb 26 08:20:54: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Feb 26 08:20:54: /sbin/ifconfig tun1 delete
Feb 26 08:20:54: NOTE: Tried to delete pre-existing tun/tap instance – No Problem if failure
Feb 26 08:20:54: /sbin/ifconfig tun1 XXX.XXX.XXX.XXX XXX.XXX.XXX.XXX mtu 1500 netmask 255.255.255.255 up
Feb 26 08:20:54: Initialization Sequence Completed

Here is the system log (filtered, but with all the relevant data I believe):

Feb 26 08:18:53 earth.local WindowServer[148]: CGXDisplayDidWakeNotification [34
1003684826626]: posting kCGSDisplayDidWake
Feb 26 08:18:53 earth.local WindowServer[148]: handle_will_sleep_auth_and_shield
_windows: Deferring.
Feb 26 08:18:53 earth.local apsd[16250]: Peer [pid=956] requested push wake but lacks APSPushWakeEntitlement
Feb 26 08:18:53 earth.local identityservicesd[970]: <IMMacNotificationCenterManager: 0x7ff84a712bb0>: notification observer: com.apple.iChat notification: __CFNotification 0x7ff84a70fbe0 {name = _NSDoNotDisturbDisabledNotification}
Feb 26 08:18:53 earth.local identityservicesd[970]: <IMMacNotificationCenterManager: 0x7ff84a712bb0>: NC Disabled: NO
Feb 26 08:18:53 earth.local identityservicesd[970]: <IMMacNotificationCenterManager: 0x7ff84a712bb0>: DND Enabled: NO
Feb 26 08:18:53 earth.local identityservicesd[970]: <IMMacNotificationCenterManager: 0x7ff84a712bb0>: Updating enabled: YES (Topics: (
Feb 26 08:19:27 — last message repeated 2 times —
Feb 26 08:19:50 — last message repeated 2 times —
Feb 26 08:19:50 earth kernel[0]: Google Chrome He (map: 0xffffff80429621e0) triggered DYLD shared region unnest for map: 0xffffff80429621e0, region 0x7fff8f200000->0x7fff8f400000. While not abnormal for debuggers, this increases system memory footprint until the target exits.
Feb 26 08:19:53 earth kernel[0]: aio_queue_async_request(): too many in flight for proc: 16.
Feb 26 08:20:08 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0” ***
Feb 26 08:20:08 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0/IPv4” ***
Feb 26 08:20:08 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0/IPv6” ***
Feb 26 08:20:08 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0/Interface” ***
Feb 26 08:20:08 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0/DNS” ***
Feb 26 08:20:08 earth.local discoveryd[51]: Basic RemoteControl com.apple.discoveryd XPC connection 0x7fc8ec96e280: Connection invalid
Feb 26 08:20:09 — last message repeated 1 time —
Feb 26 08:20:13 earth kernel[0]: wl0: Beacon Loss Event, last RSSI[-54]
Feb 26 08:20:13 earth kernel[0]: AirPort: Link Down on en0. Reason 4 (Disassociated due to inactivity).
Feb 26 08:20:13 earth kernel[0]: en0: BSSID changed to 00:00:00:00:00:00
Feb 26 08:20:13 earth kernel[0]: en0::IO80211Interface::postMessage bssid changed
Feb 26 08:20:13 earth.local discoveryd[51]: Basic DNSResolver UDNS Send(): UDP Sendto() failed to DNSNameServer 8.8.8.8 Port 53 errno 49, fd 73, ErrLogCount 1 ResolverIntf:4
Feb 26 08:20:13 earth.local discoveryd[51]: Basic DNSResolver UDNS Send(): UDP Sendto() failed to DNSNameServer 8.8.8.8 Port 53 errno 51, fd 73, ErrLogCount 2 ResolverIntf:4
Feb 26 08:20:13 earth.local discoveryd[51]: Basic DNSResolver UDNS Send(): UDP Sendto() failed to DNSNameServer 8.8.8.8 Port 53 errno 51, fd 73, ErrLogCount 3 ResolverIntf:4
Feb 26 08:20:13 earth.local discoveryd[51]: Basic DNSResolver UDNS Send(): UDP Sendto() failed to DNSNameServer 8.8.8.8 Port 53 errno 51, fd 73, ErrLogCount 4 ResolverIntf:4
Feb 26 08:20:13 earth.local networkd[361]: +[NETLedBelly stopFastFail] Clearing ledbelly failure cache
Feb 26 08:20:13 earth.local discoveryd[51]: Basic DNSResolver UDNS Send(): UDP Sendto() failed to DNSNameServer 8.8.8.8 Port 53 errno 51, fd 73, ErrLogCount 5 ResolverIntf:4
Feb 26 08:20:13 earth.local discoveryd[51]: Basic Bonjour stop listening on en0
Feb 26 08:20:13 earth.local discoveryd[51]: Basic WABServer NetResolverEvent no resolvers, resetting domains
Feb 26 08:20:13 earth.local configd[27]: network changed: v4(en0-:192.168.1.110) DNS- Proxy-
Feb 26 08:20:13 earth.local UserEventAgent[17]: Captive: CNPluginHandler en0: Inactive
Feb 26 08:20:14 earth.local com.sparklabs.ViscosityHelper[87201]: Invalid command
Feb 26 08:20:14 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0” ***
Feb 26 08:20:14 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0/IPv4” ***
Feb 26 08:20:14 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0/IPv6” ***
Feb 26 08:20:14 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0/Interface” ***
Feb 26 08:20:14 earth.local configd[27]: *** Non-configd process (pid=87201) attempting to modify “Setup:/Network/Service/com.sparklabs.Viscosity.tun0/DNS” ***
Feb 26 08:20:14 earth.local discoveryd[51]: Basic RemoteControl com.apple.discoveryd XPC connection 0x7fc8eae3d400: Connection invalid
Feb 26 08:20:14 earth.local discoveryd[51]: Basic RemoteControl com.apple.discoveryd XPC connection 0x7fc8ec838950: Connection invalid
Feb 26 08:20:14 earth.local awacsd[30328]: Starting awacsd connectivity_executables-112 (Sep 9 2014 16:16:55)
Feb 26 08:20:14 earth.local awacsd[30328]: InnerStore CopyAllZones: no info in Dynamic Store
Feb 26 08:20:14 earth.local apsd[30333]: Unable to bootstrap_look_up connection port ‘com.apple.ubd.system-push’ for user 501: Unknown service name
Feb 26 08:20:14 earth.local apsd[30333]: Attempt to set push wake topics without dark wake enabled: ()
Feb 26 08:20:14 — last message repeated 5 times —
Feb 26 08:20:14 earth.local apsd[30333]: Peer [pid=956] requested push wake but lacks APSPushWakeEntitlement
Feb 26 08:20:14 earth com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:14 earth.local apsd[30333]: Peer [pid=965] requested push wake but lacks APSPushWakeEntitlement
Feb 26 08:20:18 earth.local discoveryd[51]: None ClientIPC DNSServiceRemoveRecord: registrationId is 0 Client[netbiosd(10595)]
Feb 26 08:20:20 — last message repeated 1 time —
Feb 26 08:20:29 earth.local awacsd[30328]: Exiting
Feb 26 08:20:43 — last message repeated 1 time —
Feb 26 08:20:43 earth kernel[0]: IO80211AWDLPeerManager::setAwdlOperatingMode Setting the AWDL operation mode from AUTO to SUSPENDED
Feb 26 08:20:43 earth kernel[0]: IO80211AWDLPeerManager::setAwdlSuspendedMode() Suspending AWDL, enterQuietMode(true)
Feb 26 08:20:43 earth kernel[0]: ARPT: 341113.504834: MacAuthEvent en0 Auth result for: e0:3f:49:24:6e:64 MAC AUTH succeeded
Feb 26 08:20:43 earth kernel[0]: AirPort: Link Up on en0
Feb 26 08:20:43 earth kernel[0]: en0: BSSID changed to e0:3f:49:24:6e:64
Feb 26 08:20:43 earth kernel[0]: en0::IO80211Interface::postMessage bssid changed
Feb 26 08:20:43 earth kernel[0]: AirPort: RSN handshake complete on en0
Feb 26 08:20:43 earth.local sandboxd[417] ([32]): airportd(32) deny file-read-metadata /Library/Preferences/com.apple.security-common.plist
Feb 26 08:20:43 earth.local sandboxd[417] ([32]): airportd(32) deny file-read-data /Library/Preferences/com.apple.security-common.plist
Feb 26 08:20:44 earth kernel[0]: IO80211AWDLPeerManager::setAwdlOperatingMode Setting the AWDL operation mode from SUSPENDED to AUTO
Feb 26 08:20:44 earth kernel[0]: IO80211AWDLPeerManager::setAwdlAutoMode Resuming AWDL
Feb 26 08:20:44 earth.local networkd[361]: +[NETLedBelly stopFastFail] Clearing ledbelly failure cache
Feb 26 08:20:44 earth.local configd[27]: network changed: DNS* Proxy
Feb 26 08:20:44 earth.local UserEventAgent[17]: Captive: [CNInfoNetworkActive:1709] en0: SSID ‘apomorph_5g’ making interface primary (cache indicates network not captive)
Feb 26 08:20:44 earth.local UserEventAgent[17]: Captive: CNPluginHandler en0: Evaluating
Feb 26 08:20:44 earth.local SophosSXLD[1050]: [SMESXLInterface.m:437] no DNS addresses found
Feb 26 08:20:44 earth.local UserEventAgent[17]: Captive: en0: Not probing ‘apomorph_5g’ (cache indicates not captive)
Feb 26 08:20:44 earth.local UserEventAgent[17]: Captive: CNPluginHandler en0: Authenticated
Feb 26 08:20:44 earth.local configd[27]: network changed: v4(en0!:192.168.1.110) DNS+ Proxy+ SMB
Feb 26 08:20:44 earth kernel[0]: en0: BSSID changed to e0:3f:49:24:6e:64
Feb 26 08:20:44 earth.local networkd[361]: +[NETLedBelly stopFastFail] Clearing ledbelly failure cache
Feb 26 08:20:45 earth.local nsurlstoraged[408]: realpath() returned NULL for /var/root/Library/Caches/ocspd
Feb 26 08:20:45 earth.local nsurlstoraged[408]: The read-connection to the DB=/var/root/Library/Caches/ocspd/Cache.db is NOT valid. Unable to determine schema version.
Feb 26 08:20:45 earth.local nsurlstoraged[408]: realpath() returned NULL for /var/root/Library/Caches/ocspd
Feb 26 08:20:45 — last message repeated 1 time —
Feb 26 08:20:45 earth.local nsurlstoraged[408]: ERROR: unable to determine file-system usage for FS-backed cache at /var/root/Library/Caches/ocspd/fsCachedData. Errno=13
Feb 26 08:20:45 earth.local imagent[16252]: Quit - notifying about shutdown
Feb 26 08:20:45 earth.local imagent[16252]: Quit - shutting down daemon
Feb 26 08:20:45 earth.local apsd[32447]: Unable to bootstrap_look_up connection port ‘com.apple.ubd.system-push’ for user 501: Unknown service name
Feb 26 08:20:45 earth.local apsd[32447]: Attempt to set push wake topics without dark wake enabled: ()
Feb 26 08:20:45 — last message repeated 5 times —
Feb 26 08:20:45 earth.local apsd[32447]: Failed entitlement check ‘com.apple.private.aps-connection-initiate’ for [30335]
Feb 26 08:20:45 earth.local apsd[32447]: Peer connection [pid=30335] lacks APSConnectionInitiateEntitlement
Feb 26 08:20:45 earth.local apsd[32447]: Peer [pid=956] requested push wake but lacks APSPushWakeEntitlement
Feb 26 08:20:45 earth.local apsd[32447]: Peer [pid=965] requested push wake but lacks APSPushWakeEntitlement
Feb 26 08:20:45 earth.local storeaccountd[1798]: ADI: {
Feb 26 08:20:45 earth com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:46 earth.local storeaccountd[1798]: ADI: {
Feb 26 08:20:47 earth com.apple.xpc.launchd[1] (com.apple.imdmessageservices.IMDMessageServicesAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:47 earth com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:47 earth com.apple.xpc.launchd[1] (com.apple.imtransferservices.IMTransferAgent): The _DirtyJetsamPriority key is not available on this platform.
Feb 26 08:20:47 earth com.apple.xpc.launchd[1] (com.apple.imtransferservices.IMTransferAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:47 earth com.apple.xpc.launchd[1] (com.apple.imtranscoding.IMTranscoderAgent): The _DirtyJetsamPriority key is not available on this platform.
Feb 26 08:20:47 earth com.apple.xpc.launchd[1] (com.apple.imtranscoding.IMTranscoderAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:54 earth kernel[0]: tuntap: Fixing address family for tun1
Feb 26 08:20:54 earth com.apple.xpc.launchd[1] (com.apple.apsd): Service only ran for 9 seconds. Pushing respawn out by 1 seconds.
Feb 26 08:20:54 earth.local imagent[32456]: Quit - notifying about shutdown
Feb 26 08:20:54 earth.local imagent[32456]: Quit - shutting down daemon
Feb 26 08:20:56 earth.local apsd[33185]: Unable to bootstrap_look_up connection port ‘com.apple.ubd.system-push’ for user 501: Unknown service name
Feb 26 08:20:56 earth.local apsd[33185]: Attempt to set push wake topics without dark wake enabled: ()
Feb 26 08:20:56 — last message repeated 5 times —
Feb 26 08:20:56 earth.local apsd[33185]: Peer [pid=956] requested push wake but lacks APSPushWakeEntitlement
Feb 26 08:20:56 earth.local apsd[33185]: Peer [pid=965] requested push wake but lacks APSPushWakeEntitlement
Feb 26 08:20:56 earth com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:57 earth com.apple.xpc.launchd[1] (com.apple.imagent): Service only ran for 9 seconds. Pushing respawn out by 1 seconds.
Feb 26 08:20:58 earth com.apple.xpc.launchd[1] (com.apple.imdmessageservices.IMDMessageServicesAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:58 earth com.apple.xpc.launchd[1] (com.apple.imfoundation.IMRemoteURLConnectionAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:58 earth com.apple.xpc.launchd[1] (com.apple.imtransferservices.IMTransferAgent): The _DirtyJetsamPriority key is not available on this platform.
Feb 26 08:20:58 earth com.apple.xpc.launchd[1] (com.apple.imtransferservices.IMTransferAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:58 earth com.apple.xpc.launchd[1] (com.apple.imtranscoding.IMTranscoderAgent): The _DirtyJetsamPriority key is not available on this platform.
Feb 26 08:20:58 earth com.apple.xpc.launchd[1] (com.apple.imtranscoding.IMTranscoderAgent): The _DirtyJetsamMemoryLimit key is not available on this platform.
Feb 26 08:20:58 earth.local soagent[1779]: [Warning] IMLocalObject: Could not create server for listener: <IMDaemonListener: 0x7ff75aa024c0>

You can see that the “disconnect” was caused by my wifi connection dropping and then it attempts to do something related to tun0 and then shortly therafter brings up tun1.

I attempted to recreate this by manually disconnecting my wifi connection, but that seemed to work properly (no stale openvpn processes/tun devices).

Hi therevmj,

Thanks for posting your logs. Certainly something a little quirky is going on with the OpenVPN process. We haven’t been able to replicate what is going on, however we’ve added a workaround to the latest Mac beta (1.5.4b11) that should hopefully resolve the problem. Please give it a try when you get the chance and let us know how you get on.

We’ll also release an updated Windows beta with the same workaround fairly soon too.

Cheers,
James

I’ve installed the newest beta on my Mac. I’ll keep you posted. I’ll give it 3 days and sound the all clear if I’ve not had a recurrence. Thanks for looking into this!

As an update to this, in my organization we’re running Viscosity versions between 1.5.3 and 1.5.5 / 1.5.5b4, and all of these versions exhibit the problem of the multiple stale openvpn processes - our inventory system shows many dozens of computers that currently have this wonky multiple-openvpn process state.

We’re currently handling at least one request per day about somebody’s VPN connection no longer working, which often requires manual intervention. It’s getting pretty disruptive for our entire team. Are there any solutions / diagnoses on the horizon?

Sorry for the lengthy delay. The beta version does prevent the stale processes. However, it doesn’t seem to reconnect automatically for the most part. Although given the option between having to manually reconnect vs. finding stale VPN processes and then manually reconnecting, that’s not such a big deal. :slight_smile:

I’ve asked a couple people who reported problems to upgrade to 1.5.6b2, and that too seems to be having the same kind of issue. There are machines with 18 stale processes around.