[Staging only][Intermittent][iOS] “Server unavailable” modal is displayed when turning VPN on after making a IAP subscription

[data-sync-user]

Important details:

• The issue is resolved by closing and reopening the Mozilla VPN app
• The issue is also sometimes reproducible after signing in with an account with an active subscription and attempting to turn it ON.

Affected versions:

• 2.18.0 (2.202310172207);

Tested Platforms:

• iOS 15.7/16.5;

Prerequisites:

• Have an account with an expired IAP subscription for Mozilla VPN or start creating new account;

• Have Mozilla VPN app installed on your device;

• Be in “Subscribe to Mozilla VPN” screen

Steps to reproduce:

1. Select a subscription plan and press the “Subscribe now” button.
2. Press the “Subscribe” button.
3. Turn VPN on.

Expected result:

• The VPN is turned on.

Actual result:

• The VPN is not turned on and is stuck in connecting state, then it shows “Server unavailable” modal.

┆Issue is synchronized with this Jira Bug ┆Reporter: Raluca Monica Ilban

[data-sync-user]

➤ Matt Cleinman commented:

These are mostly notes for me.

(Questions I’m not asking yet, but if I’m stuck they may be helpful: How often does this happen? On fresh install, or only after reset and quit? Still happening in last couple days (wondering if it’s related to the old network extension lying around).)

I couldn’t replicate. I’m looking into logs.

Intriguing:

[18.10.2023 13:32:29.454] (NetworkRequest) Error: Network error: Error transferring https://stage.guardian.nonprod.cloudops.mozgcp.net/api/v1/vpn/purchases/ios - server replied: Bad Request status code: 400 - body: XXXXXXXX [18.10.2023 13:32:29.455] (NetworkRequest) Error: Failed to access: https://stage.guardian.nonprod.cloudops.mozgcp.net/api/v1/vpn/purchases/ios [18.10.2023 13:32:29.455] (IOSIAPHandler) Error: Purchase request failed QNetworkReply::ProtocolInvalidOperationErrorNotably, guardian has both /v2/vpn/purchases/ios and /v1/vpn/purchases/ios endpoints. The readme implies iOS should hitting the v2 endpoint, but, ummm, the iOS client actually hits v1.

Next:

• In this flow, what caused Guardian to throw a 400?
• Could it be a transient error in Guardian?
• Are we using the wrong endpoint (should we be using v2)?
• How are we handling this when we get a 400 back in the client? If we’re passing the user through to main screen, that is very very bad.
  • TaskPurchase::run is the one and only place we hit this endpoint. The failure of this request should trigger these pieces of code (Task has no default implementation for failed):
    • connect(request, &NetworkRequest::requestFailed, this, &TaskPurchase::failed);
    • connect(request, &NetworkRequest::requestFailed, this, &Task::completed, Qt::QueuedConnection);
    • IOSIAPHandler::processCompletedTransactions
    • the other two don’t actually lead anywhere, this is the one to follow up on here.
    • We can see this in log lines.
    • And we don’t catch the error anywhere in this block (roughly lines 340-375 of iosiaphandler.mm ( http://iosiaphandler.mm ), so we default to emit alreadySubscribed(). We can confirm this in the logs. This also seems like a potentially bad way to handle an unknown error.

I’m keeping on this, but this could be one of those two sided ones: Why are we handling it poorly on client? And why is Guardian throwing that 400?

Also, I really hope these log lines are the ones from when they had the issue - if not, I’m chasing a giant red herring.

[data-sync-user]

➤ Raluca Monica Ilban commented:

Hi Matt Cleinman

Verified using 2.19 build on iOS 15.7, the issue is reproducible after a fresh install and also after reset and quit action. Attached logs.

After fresh install:

• sign in and turn VPN on: Server unavailable modal was displayed at ~15.34 and 15.42
• make IAP subscription, then turn VPN on: Server unavailable modal was displayed, then the application crashed at ~16.38

After reset and quit:

• make IAP subscription, then turn VPN on: Server unavailable modal was displayed at ~19.09

[data-sync-user]

➤ Valentina Virlics commented:

I was able to reproduce this while using the client downloaded from Apple Store and making a subscription using a redeem code, while on Production server.

Attaching logs. (11:30 the aprox hour of the issue encounter)

[^mozillavpn (4).log]

cc: Matt Cleinman

[data-sync-user]

➤ Matt Cleinman commented:

Does it happen every time w/ a new IAP subscripton, or just some of the time? I’m trying to replicate this with just signing into a fresh install (which according to the ticket, happens sometimes), but despite trying it a handful of times (using a couple different accounts) I’m not able to replicate the issue - after signing in, it connects to the VPN just fine. If it happens more often via IAP I’ll try that route.

(One thing to note - I’m deleting the app in between attempts, not using reset and quit. You’ve said it happens in both contexts, and I’ve been focusing on the fresh install route, as that is what users are more likely to experience.)

Due to https://mozilla-hub.atlassian.net/browse/VPN-5792 ( https://mozilla-hub.atlassian.net/browse/VPN-5792|smart-link ), this is difficult for me to diagnose without being able to replicate.

If you experience this again, can you note the rough time (as you’ve been doing, which is very helpful - thanks) and pull the logs shortly after you experience the issue? Since we only keep the last while of logs, I can see the issue in the network extension logs (which are limited, per VPN-5792) but not in the main app’s logs, which would be very helpful.

[data-sync-user]

➤ Matt Cleinman commented:

Looking at the logs, they all seem to be from a network with a captive portals - In each case, had you already gone through the captive portal screen outside the app before you got the error? (If not it’s possible that the VPN turned on but the captive portal hadn’t been passed, and so that caused this issue.)

[data-sync-user]

➤ Raluca Monica Ilban commented:

Hi Matt Cleinman ,

I am not connected to a captive portal network.

Does it happen every time w/ a new IAP subscripton, or just some of the time? No, it doesn't happen every time, today we were not able to reproduce after making IAP subscription.

The issue was reproducing 3 times today (didn't perform reset and quit). Sign out, then sign back in and turn on the VPN. Attaching logs, the issues was reproducing at 9:33, 12:18 and 16.38.

[^9.33_mozillavpn.log] [^16.38_mozillavpn.log]

[data-sync-user]

➤ Matt Cleinman commented:

This part of the code is going to be re-worked in https://mozilla-hub.atlassian.net/browse/VPN-3575 ( https://mozilla-hub.atlassian.net/browse/VPN-3575|smart-link ) . I’m going to stop researching this for now, and we can see if that work fixes this issue.

[data-sync-user]

➤ Santiago Andrigo commented:

Downgrading this as this is not happening in a deterministic fashion. Please let us know if this is not true.

[data-sync-user]

➤ Bianca Hidecuti commented:

I was able to reproduce this using the 2.19 RC, after making an IAP subscription - attaching logs (check the logs at 11:40).

[^11-40 mozillavpn.log]

[data-sync-user]

➤ Bianca Hidecuti commented:

I’am able to reproduce the Connecting state of the VPN while using the 2.20 build, on iOS 17. After the VPN was ON for a while and turning it OFF and ON, the VPN stays in Connecting while attempting to connect to several servers.

I am attaching video and logs as well.

[^connecting mozillavpn.log]

!original-EEFB37A5-12DA-411D-B112-C03EC6FC899D.mp4|width=444,height=960!

[data-sync-user]

➤ Bianca Hidecuti commented:

I’ve encountered the “Connecting..” state followed by the server unavailable modal several times (3-4 times) while using the 2.20 RC (#3694 build from Testflight) on iOS 16.5 - regardless of the account used.

The VPN is unable to connect to any server until the app is swipe-killed and reopened.

Matt Cleinman, could you please take a look at the logs and let us know if this is the same issue? Thanks in advance!

[^ioss mozillavpn.log]

[data-sync-user]

➤ Matt Cleinman commented:

Is this after reset and quit, or on a fresh install?

[data-sync-user]

➤ Bianca Hidecuti commented:

Hey Matt Cleinman - the build was fresh installed from Testflight (no reset and quit) - but I’ve encountered the “Connecting..” state after a few hours of using Mozilla VPN, not at first turn ON.

[data-sync-user]

➤ Bianca Hidecuti commented:

I was able to reproduce this issue while using the latest 2.21 build of Mozilla VPN, on iOS 16.5 after making an IAP subscription and attempting to turn ON the VPN - the only difference is that now after swipe-killing the app the issus is not resolved - the VPN remains in Connecting state followed by the server unavailable modal, regardless of the selected server.

Valentina Virlics experienced the same issue after making an IAP subscription while using the 2.20 RC. I am attaching logs from both devices.

Beatriz Rizental Machado / Jeremy Swinarton, could you please take a look at logs and let us know if Guardian could impact this somehow or if we should track it separately? Thanks in advance!

[^iPhone mozillavpn.log] [^iPad mozillavpn (7).log]

[data-sync-user]

➤ Jeremy Swinarton commented:

Hi Bianca Hidecuti ,

Having reviewed the logs, it appears that all outbound HTTP connections the client is making are returning with the correct response codes. Therefore, I think it is unlikely that Guardian would be the cause of this.

[data-sync-user]

➤ Valentina Virlics commented:

Attaching another set of logs after reproducing the issue and performing a relog action.

[^mozillavpn (9).log]

[data-sync-user]

➤ Santiago Andrigo commented:

Valentina Virlics The thread on Slack this is only affecting Staging. Is that so?

[data-sync-user]

➤ Valentina Virlics commented:

Yes. We were not able to reproduce it on prod.

[data-sync-user]

➤ Bianca Hidecuti commented:

I was able to reproduce this with Mozilla VPN 2.21.0 (2.202402272206), on iOS 17.3.1 after making an IAP subscription while attempting to turn ON the VPN.

Attaching logs.

[^iOS mozillavpn.log]

[data-sync-user]

➤ Raluca Monica Ilban commented:

Was able to reproduce this using Mozilla VPN 2.23.0 (2.202405272208), on iOS 15 after making an IAP subscription.

Attaching logs.[^477bd93e-1c77-443b-8a49-127e6cfe593d]