[macOS] possible bug

[macOS] possible bug

[Richard Werner]

Hi everyone.
We found a strange issue regarding macOS client and hope this is a proper way to start (and get some help debugging) a possible bug.
I’ve not been able to capture the actual error message shown to the user, but I have the a log file.

What seem to happen is something like this:
1. Have a working configuration.
2. Some unknown event happens (still investigating).
3. An error message is shown (something along the lines of "unable to read config”).
4. Orphaned configs are removed, but there seems to be more going on which we can’t identify.
5. No WG VPN's will work regardless of removing configs, keychains, etc.

Even if all tunnels are removed and added again, no traffic leaves the client. It effectively enters a state of not being able to use any wireguards vpns on the client.


Some entries from the log that shows going from working to not functioning will follow.
More complete log at https://pastebin.com/m2MqHhPF

-Working:
2022-01-17 17:55:59.292781: [NET] peer(ZY6x…1ZBc) - Sending handshake initiation
2022-01-17 17:55:59.337042: [NET] peer(ZY6x…1ZBc) - Received handshake response
2022-01-17 17:59:22.007634: [NET] peer(ZY6x…1ZBc) - Receiving keepalive packet

-Error message is shown:
2022-01-17 18:35:29.081737: [APP] App version: 1.0.15 (26)
2022-01-17 18:36:22.662281: [APP] startActivation: Entering (tunnel: VPN X)
2022-01-17 18:36:23.490825: [APP] Unable to open config from keychain: -25300
2022-01-17 18:36:23.491058: [APP] startActivation: Starting tunnel
2022-01-17 18:36:23.491288: [APP] startActivation: Success
2022-01-17 18:36:23.497349: [APP] Tunnel 'VPN X' connection status changed to 'connecting'
2022-01-17 18:36:23.582298: [APP] Unable to open config from keychain: -25300
2022-01-17 18:36:28.491285: [APP] Status update notification timeout for tunnel 'VPN X'. Tunnel status is now 'connecting'.
2022-01-17 18:36:29.517132: [APP] Unable to open config from keychain: -25300

-Tunnel config is removed:
2022-01-17 18:38:47.127836: [APP] App version: 1.0.15 (26)
2022-01-17 18:38:47.337355: [APP] Removing orphaned tunnel with non-verifying keychain entry: VPN X

-Tunnel now fails with same config (imported or manually entered)
2022-01-17 18:39:51.924221: [APP] Status update notification timeout for tunnel 'VPN X'. Tunnel status is now 'connected'.
2022-01-17 18:39:52.248987: [NET] peer(ZY6x…1ZBc) - Sending handshake initiation
2022-01-17 18:39:57.410547: [NET] peer(ZY6x…1ZBc) - Handshake did not complete after 5 seconds, retrying (try 2)
2022-01-17 18:39:57.410877: [NET] peer(ZY6x…1ZBc) - Sending handshake initiation
2022-01-17 18:39:57.411226: [NET] peer(ZY6x…1ZBc) - Failed to send handshake initiation: write udp4 0.0.0.0:52982-><server ip>:443: sendto: broken pipe
[…]
2022-01-17 18:40:00.396146: [APP] Tunnel 'VPN X' connection status changed to 'disconnected'
2022-01-17 18:41:27.735004: [APP] Tunnel 'VPN X' connection status changed to ‘invalid'


—Richard

Re: [macOS] possible bug

[Perry The Cynic]

FWIW, -25300 is errSecItemNotFound (keychain item not found). The MacOS keychain environment is much more complex than on iOS (in fact, there’s an iOS port inside it). Check whether the affected environments have multiple keychains (which can confuse the “exists” issue), and look (with Keychain Access.app) for broken items that keep the code from recreating good items with a particular primary key. The "Removing orphaned tunnel with non-verifying keychain entry” message points that way.

See if you can reproduce with a fresh user account (which comes with a fresh keychain configuration); if resetting the keychain environment cures the problem, you’re very likely looking at a broken item and/or broken cleanup code.

Cheers
  — perry


> On Jan 17, 2022, at 11:49 AM, Richard Werner <richard@netcore.se> wrote:
> 
> Hi everyone.
> We found a strange issue regarding macOS client and hope this is a proper way to start (and get some help debugging) a possible bug.
> I’ve not been able to capture the actual error message shown to the user, but I have the a log file.
> 
> What seem to happen is something like this:
> 1. Have a working configuration.
> 2. Some unknown event happens (still investigating).
> 3. An error message is shown (something along the lines of "unable to read config”).
> 4. Orphaned configs are removed, but there seems to be more going on which we can’t identify.
> 5. No WG VPN's will work regardless of removing configs, keychains, etc.
> 
> Even if all tunnels are removed and added again, no traffic leaves the client. It effectively enters a state of not being able to use any wireguards vpns on the client.
> 
> 
> Some entries from the log that shows going from working to not functioning will follow.
> More complete log at https://pastebin.com/m2MqHhPF
> 
> -Working:
> 2022-01-17 17:55:59.292781: [NET] peer(ZY6x…1ZBc) - Sending handshake initiation
> 2022-01-17 17:55:59.337042: [NET] peer(ZY6x…1ZBc) - Received handshake response
> 2022-01-17 17:59:22.007634: [NET] peer(ZY6x…1ZBc) - Receiving keepalive packet
> 
> -Error message is shown:
> 2022-01-17 18:35:29.081737: [APP] App version: 1.0.15 (26)
> 2022-01-17 18:36:22.662281: [APP] startActivation: Entering (tunnel: VPN X)
> 2022-01-17 18:36:23.490825: [APP] Unable to open config from keychain: -25300
> 2022-01-17 18:36:23.491058: [APP] startActivation: Starting tunnel
> 2022-01-17 18:36:23.491288: [APP] startActivation: Success
> 2022-01-17 18:36:23.497349: [APP] Tunnel 'VPN X' connection status changed to 'connecting'
> 2022-01-17 18:36:23.582298: [APP] Unable to open config from keychain: -25300
> 2022-01-17 18:36:28.491285: [APP] Status update notification timeout for tunnel 'VPN X'. Tunnel status is now 'connecting'.
> 2022-01-17 18:36:29.517132: [APP] Unable to open config from keychain: -25300
> 
> -Tunnel config is removed:
> 2022-01-17 18:38:47.127836: [APP] App version: 1.0.15 (26)
> 2022-01-17 18:38:47.337355: [APP] Removing orphaned tunnel with non-verifying keychain entry: VPN X
> 
> -Tunnel now fails with same config (imported or manually entered)
> 2022-01-17 18:39:51.924221: [APP] Status update notification timeout for tunnel 'VPN X'. Tunnel status is now 'connected'.
> 2022-01-17 18:39:52.248987: [NET] peer(ZY6x…1ZBc) - Sending handshake initiation
> 2022-01-17 18:39:57.410547: [NET] peer(ZY6x…1ZBc) - Handshake did not complete after 5 seconds, retrying (try 2)
> 2022-01-17 18:39:57.410877: [NET] peer(ZY6x…1ZBc) - Sending handshake initiation
> 2022-01-17 18:39:57.411226: [NET] peer(ZY6x…1ZBc) - Failed to send handshake initiation: write udp4 0.0.0.0:52982-><server ip>:443: sendto: broken pipe
> […]
> 2022-01-17 18:40:00.396146: [APP] Tunnel 'VPN X' connection status changed to 'disconnected'
> 2022-01-17 18:41:27.735004: [APP] Tunnel 'VPN X' connection status changed to ‘invalid'
> 
> 
> —Richard
>