xanoni commented 3 years ago

Issue report

Operating system: iOS 14.4.1

App version: 2021.1

Issue description

The Mulllvad iOS app does not reliably recover after temporary connection losses. Even though this happens very often (daily), I haven't fully understood the issue, yet (e.g., why it sometimes occurs but other times it doesn't).

I've stopped using the Mullvad app as a result of this problem, but am available for testing if needed. Please let me know.

For comparison, the generic WireGuard app with a Mullvad profile works smoothly.

Generally, this is how it happens:

Phone is connected to WiFi with Mullvad enabled & connected
WiFi connection is lost, e.g., due to a physical location change
Phone restores its network connection eventually
Internet is blocked, Mullvad app UI is partially frozen (e.g., can't select a different server from server list, connect/disconnect button does nothing)
(I have not isolated yet whether this occurs only when the new connection is a LTE/3G connection, or if the same happens with a new WiFI connection)

Only known way to resolve the situation is to go to the iOS VPN settings and briefly switch to a different connection before turning Mullvad back on.

pronebird commented 3 years ago

Hi @M09NST3R,

I am investigating this and I realise that you wouldn't be able to send us a problem report if the tunnel is jammed.

However I think you should be able to copy the problem report and send it to us via email or here (it should be anonymised). This would greatly help us in finding the culprit of the freeze.

This can be done from Settings > Report a problem > View app logs, then select the text, copy and save it somewhere offline and pass it over once you manage to get the working connection.

On a side note, I realised that "Select all" option is not available when viewing app logs. We'll fix that too in the upcoming update.

Cheers, Andrej

midi commented 3 years ago

Hi, also experiencing the same issue on multiple iPhones and: Operating system: iOS 14.4.1/12.4.5 App version: 2021.1

The UI freezing happens to me if I press disconnect, then I can fix by either just waiting 30 seconds or so, or switching to another server after a bit, then selecting the previous choice, then it will connect again. Will try to get logs the next time it happens.

midi commented 3 years ago

Managed to get the issue again. No Internet and frozen UI.

System information: id: mullvad-product-version: 2021.1 os: iOS 14.4.2

==================== [REDACTED CONTAINER PATH]/Logs/net.mullvad.MullvadVPN.log

[2021-04-04 02:29:44.954][TunnelManager][info] Set tunnel state: connected [2021-04-04 02:29:45.773][TunnelManager][info] Set tunnel state: disconnecting [2021-04-04 02:29:46.131][TunnelManager][info] Set tunnel state: disconnected [2021-04-04 02:30:00.074][TunnelManager][info] Set tunnel state: connecting [2021-04-04 02:30:00.414][TunnelManager][info] Set tunnel state: connected [2021-04-04 11:23:01.983][TunnelManager][info] Set tunnel state: reconnecting [2021-04-04 11:23:02.084][TunnelManager][info] Set tunnel state: connected [2021-04-04 11:23:03.772][TunnelManager][info] Set tunnel state: reconnecting [2021-04-04 11:23:03.876][TunnelManager][info] Set tunnel state: connected [2021-04-04 11:25:44.676][TunnelManager][info] Set tunnel state: disconnecting [2021-04-04 11:25:45.024][TunnelManager][info] Set tunnel state: disconnected [2021-04-04 11:25:45.981][TunnelManager][info] Set tunnel state: connecting [2021-04-04 11:25:46.298][TunnelManager][info] Set tunnel state: connected [2021-04-04 23:09:16.663][TunnelManager][info] Set tunnel state: connected [2021-04-04 23:09:17.187][TunnelManager][info] Set tunnel state: disconnecting [2021-04-04 23:09:37.239][TunnelManager][info] Set tunnel state: disconnected [2021-04-04 23:09:37.435][TunnelManager][info] Set tunnel state: connecting [2021-04-04 23:09:37.702][TunnelManager][info] Set tunnel state: connected [2021-04-04 23:09:37.827][TunnelManager][info] Set tunnel state: disconnecting [2021-04-04 23:09:37.944][TunnelManager][info] Set tunnel state: disconnected [2021-04-04 23:09:38.748][TunnelManager][info] Set tunnel state: connecting [2021-04-04 23:09:38.985][TunnelManager][info] Set tunnel state: connected

==================== [REDACTED CONTAINER PATH]/Logs/net.mullvad.MullvadVPN.PacketTunnel.log

[2021-04-04 23:09:38.793][PacketTunnelProvider][info] Start the tunnel [2021-04-04 23:09:38.797][PacketTunnelProvider][info] New tunnel state: PacketTunnelState.connecting(nil) [2021-04-04 23:09:38.831][PacketTunnelProvider][info] New tunnel state: PacketTunnelState.connecting(Optional({ ipv4Relay: [REDACTED]:53, ipv6Relay: nil, hostname: "sg8-wireguard",location: PacketTunnel.Location(country: "Singapore", countryCode: "sg", city: "Singapore", cityCode: "sin", latitude: 1.2930556, longitude: 103.8558333) })) [2021-04-04 23:09:38.945][WireGuard][debug] DNS64: mapped [REDACTED] to itself. [2021-04-04 23:09:38.947][WireGuard][info] Attaching to interface [2021-04-04 23:09:38.948][WireGuard][debug] Routine: decryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: encryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: handshake worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: encryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: encryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: decryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: handshake worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: handshake worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: encryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: decryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: handshake worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: decryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: encryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: handshake worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: decryption worker - started [2021-04-04 23:09:38.948][WireGuard][debug] Routine: decryption worker - started [2021-04-04 23:09:38.949][WireGuard][debug] Routine: encryption worker - started [2021-04-04 23:09:38.949][WireGuard][debug] Routine: handshake worker - started [2021-04-04 23:09:38.949][WireGuard][debug] Routine: TUN reader - started [2021-04-04 23:09:38.949][WireGuard][debug] Routine: event worker - started [2021-04-04 23:09:38.949][WireGuard][debug] UAPI: Updating private key [2021-04-04 23:09:38.949][WireGuard][debug] UAPI: Updating listen port [2021-04-04 23:09:38.949][WireGuard][debug] UAPI: Removing all peers [2021-04-04 23:09:38.949][WireGuard][debug] UAPI: Transition to peer configuration [2021-04-04 23:09:38.950][WireGuard][debug] peer(VxRO…GbkE) - UAPI: Created [2021-04-04 23:09:38.950][WireGuard][debug] peer(VxRO…GbkE) - UAPI: Updating endpoint [2021-04-04 23:09:38.950][WireGuard][debug] peer(VxRO…GbkE) - UAPI: Updating persistent keepalive interval [2021-04-04 23:09:38.950][WireGuard][debug] peer(VxRO…GbkE) - UAPI: Removing all allowedips [2021-04-04 23:09:38.950][WireGuard][debug] peer(VxRO…GbkE) - UAPI: Adding allowedip [2021-04-04 23:09:38.950][WireGuard][debug] peer(VxRO…GbkE) - UAPI: Adding allowedip [2021-04-04 23:09:38.950][WireGuard][debug] UDP bind has been updated [2021-04-04 23:09:38.950][WireGuard][debug] peer(VxRO…GbkE) - Starting... [2021-04-04 23:09:38.951][WireGuard][debug] Routine: receive incoming IPv4 - started [2021-04-04 23:09:38.951][WireGuard][debug] Routine: receive incoming IPv6 - started [2021-04-04 23:09:38.951][WireGuard][debug] peer(VxRO…GbkE) - Routine: nonce worker - started [2021-04-04 23:09:38.951][WireGuard][debug] peer(VxRO…GbkE) - Routine: sequential sender - started [2021-04-04 23:09:38.951][WireGuard][debug] peer(VxRO…GbkE) - Routine: sequential receiver - started [2021-04-04 23:09:38.951][WireGuard][info] Device started [2021-04-04 23:09:38.952][WireGuard][debug] Network change detected with satisfied route and interface order [en0, pdp_ip1] [2021-04-04 23:09:38.952][WireGuard][debug] DNS64: mapped [REDACTED] to itself. [2021-04-04 23:09:38.952][WireGuard][debug] UAPI: Transition to peer configuration [2021-04-04 23:09:38.953][WireGuard][debug] peer(VxRO…GbkE) - UAPI: Updating endpoint [2021-04-04 23:09:38.953][WireGuard][debug] Routine: receive incoming IPv4 - stopped [2021-04-04 23:09:38.953][WireGuard][debug] Routine: receive incoming IPv6 - stopped [2021-04-04 23:09:38.953][WireGuard][debug] UDP bind has been updated [2021-04-04 23:09:38.953][WireGuard][debug] Routine: receive incoming IPv4 - started [2021-04-04 23:09:38.953][WireGuard][debug] Routine: receive incoming IPv6 - started [2021-04-04 23:09:38.974][AutomaticKeyRotationManager][info] Start automatic key rotation [2021-04-04 23:09:38.979][AutomaticKeyRotationManager][info] Next private key rotation on 2021-04-08 13:20:17 +0000 [2021-04-04 23:09:38.979][PacketTunnelProvider][info] New tunnel state: PacketTunnelState.connected({ ipv4Relay: [REDACTED]:53, ipv6Relay: nil, hostname: "sg8-wireguard",location: PacketTunnel.Location(country: "Singapore", countryCode: "sg", city: "Singapore", cityCode: "sin", latitude: 1.2930556, longitude: 103.8558333) }) [2021-04-04 23:09:38.979][PacketTunnelProvider][info] Started the tunnel [2021-04-04 23:09:39.269][WireGuard][debug] Network change detected with satisfied route and interface order [en0, utun1, pdp_ip1] [2021-04-04 23:09:39.270][WireGuard][debug] DNS64: mapped [REDACTED] to itself. [2021-04-04 23:09:39.270][WireGuard][debug] UAPI: Transition to peer configuration [2021-04-04 23:09:39.270][WireGuard][debug] peer(VxRO…GbkE) - UAPI: Updating endpoint [2021-04-04 23:09:39.271][WireGuard][debug] Routine: receive incoming IPv4 - stopped [2021-04-04 23:09:39.271][WireGuard][debug] Routine: receive incoming IPv6 - stopped [2021-04-04 23:09:39.272][WireGuard][debug] UDP bind has been updated [2021-04-04 23:09:39.272][WireGuard][debug] Routine: receive incoming IPv4 - started [2021-04-04 23:09:39.272][WireGuard][debug] Routine: receive incoming IPv6 - started [2021-04-04 23:09:39.291][WireGuard][debug] peer(VxRO…GbkE) - Sending handshake initiation [2021-04-04 23:09:39.293][WireGuard][debug] peer(VxRO…GbkE) - Awaiting keypair [2021-04-04 23:09:39.317][WireGuard][debug] Received message with unknown type [2021-04-04 23:09:44.345][WireGuard][debug] peer(VxRO…GbkE) - Sending handshake initiation [2021-04-04 23:09:44.356][WireGuard][debug] Received message with unknown type

xanoni commented 3 years ago

Hi, also experiencing the same issue on multiple iPhones and: Operating system: iOS 14.4.1/12.4.5 App version: 2021.1

The UI freezing happens to me if I press disconnect, then I can fix by either just waiting 30 seconds or so, or switching to another server after a bit, then selecting the previous choice, then it will connect again. Will try to get logs the next time it happens.

Interesting. I thought it was permanently frozen, but maybe I was just not patient enough. I switched to the generic WireGuard App already, but I will switch back to Mullvad to hopefully reproduce this a few more times.

narration-sd commented 2 years ago

Just to note, this is ongoing and just as originally described, in newish iPad Air 4, running final RC iPadOS 15.1 (it releases Monday, and has long been stable).

I’ve just completed a solid week of no drops whatever, and instant re-connect if the wifi has been restarted, using the standard iOS WireGuard app.

With Mullvad app, typically several times a day to get the blocked situation, and no amount of trying things alters this.

I’ve reported all, with logs, to Support, who’ve been courteously receiving, also informing that the iOS/iPadOS Mullvad app is a separate development, thus missing features and no doubt internals that the mainline has. I would think some comparison to the WireGuard app code should be very helpful, no?

As of a day or two ago, it’s no longer possible even to set exit location from the Mullvad app Beta that I’ve been running, as it has expired with Apple….greetings :)

xanoni commented 2 years ago

Unfortunately I didn't create a report, but just wanted to confirm that I still had the same issue when I was briefly using Mullvad VPN instead of the official WG app 2-3 weeks ago.

narration-sd commented 2 years ago

Crossed fingers, but after several days, it may be that you’ve cured this on the most recent iOS/iPadOS beta, 2021.4-beta1.

The problem very solidly on iPadOS, was very often a complete near-dropout of Mullvad vpn tunnel, occurring sometimes as often as several times a day.

To relieve it took changing servers, stopping and restarting Mullvad, or sometimes also reboot of the iPad (Air 4).

Now on this beta, it’s been running for days solidly, across incidents like wifi drops and restarts both, and expected incidents any time of day on a US cable internet.

Very well done, it appears, and hoping it stays true :)

Mullvad’s app may also be operating more smoothly (avoiding delays) than the WireGuard iOS app I have been using for some weeks also. This is more subtle, but I think so, thus again, appreciated.

All this so reported on the Feedback app.

narration-sd commented 2 years ago

Coming back on this, because patience over a long term proves the issue is still present.

the latest iOS Beta, which summarily expired this morning, had notes saying it had some improvements on reconnecting.
in fact, I thought I noticed things being slighthly better...but in fact, maybe not, as the disconnects seem to become more definite, with complete loss of data transfer even while seeming connected.
how this happens: Mullvad appears to lose its dataflow, after the wifi connection drops and itself reconnects.
- I am clear now that here I have the personal situation of a problematic wifi which I can't access to adjust, if it is quite fast when it's working (ca. 200Mbps). But it drops, sometimes several unpredictable times in a day , and restarts.
- I suspect you can duplicate the condition either by turning off an access point momentarily, or quite possibly using the Control Panel on the iDevice to turn off wifi for a moment.
- The symptoms are peculiar, and may possibly be on your server end(!)
- with the latest beta, the Mullvad internal disconnect appears a hard loss of channel, even though the UX shows it's connected.
- in fact, it is probably not lying. Most times of wifi back up, invisible continuance or reconnection, the channel actually will be there...at an exceedingly slow rate, measured by speed tests.
- often enough, you can watch the speed ramp up over the 20 seconds or so for the downstream measurement. It might even get to 80% or so of full speed. But such a 'recovered' connection will almost always fail entirely within minutes. As well, often enough the download side will show such 'recovery', but then the upload which runs affer on the tester will pass no data at all. while it should be a fixed speed of ca. 11 Mbps.
- what move will solve this, bring back a working connection?
- On some of your server portals, Los Angeles for example, there are apparently some server groups which are distinct, and show so by having a different band of ip addresses. Often first disconnecting Mullvad (needed step I think, rather than just tapping a different connection), then choosing a server in the different IP range will achieve a solid connection, which immediately evidences that it is so, by running at full speed down and up. Then we can relax for...a day...or,...an hour...or once in a while, minutes only before bad things happen again.
- A more reliable move is to again fully disconnect Mullvad on its UX, then choose a server ip from a different server location. I use Phoenix, less reliably the possibly more loaded San Jose, which is actually a better steady speeds connection, but may be quite locally loaded.
- what might we imagine might be really going on?
- having once designed TCP-IP-style protocols, there is something about the often-enough seen ramping up of speed on attempting channel recovery which tempts one to think of protocol rate windows. I realize this is quite far from UX design or using libraries, but it is reality in that world, someone on your team will well understand.
- where is the negotiated window being damaged, if that's true? Here we have unfotunately layers and layers of participating network equipment. There is some hint that one of these is involved, in that your physical server sites seem to differ a bit in how they act around the losses of connections and possible recoveries.
- I might have seen a little of the bad loss/reconnect behavior actually on the stock Wireguard client, configured to work with a few of your servers. I try this occasionally on the iPad (Air 4 256, plenty of resources), and use it all the time on my Android phone, whose no-further-upgrades Android release you have stopped supporting.
- what about solutions?
- I think you do recognize there's a problem here, given the recently outdated iOS/iPadOS Beta's release notes.
- Of course, of all platforms, Apple is both most desirable to have flawless operation, and equally very problematic to work with, having all its restrictions and opinionations
- I feel you are on the right track in some of the wording of that release.
  - Some kind of recognizing the channel is down...or maybe you don't yet recognise when it is actually severely attenuated...is a great first step. Just I think you need to be sure about those attenuated, not apparently lost, channels, as that is where I've almost always seen the problem immediately, per above.
  - And in fact the channel absolutely never shows disconnected.
  - What kind of restart should you think of? I feel this should be an entire disconnect and full channel creation, not any intermediate way. It should be as if one has just turned on Mullvad from non-VPN iDevice operation.
  - The reason for that intuition is two-fold. Apple's interfaces tend to be quite opaque, so you don't really know what is going on or what you can affect, so better to destroy and rebuild entirely the connection, then form your new channel. But it's actually primarily thought of because of that 'ghostly' appearance that intermediate network hardware,or even the Wireguard protocol itself are not resilient...that they actually lodge a trickle-down for example in protocol window rate capability, as seems perhaps to be observed as above, and then are not good about fully recovering such health, also as observed.
  - in summary, we don't know nor reasonably can know everything in a path throw he world, so best is the 'nuclear' approach. This means sensitive detection for those incoming rockets, and then complete removal and reconstruction for the target they may have it.
  - Somehow this language is creeping in :). Probably not a surprise for such problems, as we are all human. But then patience is the watchword, in constructing a mechanism so that we don't need to worry them more, not so?

I wish you all good fortune on this, and hope to enjoy it here also :)

/s/ by an old enough hand, you can tell, gamle... Clive

mullvad / mullvadvpn-app

[iOS/iPhone] Internet connection is (often) permanently blocked after temporary connection losses #2622

Issue report

Issue description

==================== [REDACTED CONTAINER PATH]/Logs/net.mullvad.MullvadVPN.log

==================== [REDACTED CONTAINER PATH]/Logs/net.mullvad.MullvadVPN.PacketTunnel.log