Solved

Debugging hanging purchase request & PurchaseErrorCode.operationAlreadyInProgress

  • 15 October 2021
  • 22 replies
  • 701 views
Steph
Userlevel 1
Badge +9

We have the combined issues of 1) purchase requests hanging and 2) PurchaseErrorCode.operationAlreadyInProgress for our flutter app. Haven’t been able to reproduce on our side but have several users recently report this.

Example of a recent Android report: https://finch.hellonext.co/b/Bugs/p/can-t-sign-up-for-trial-with-monthly-billing.

 

We always display the error code that is returned (like in the bug report screenshot) but it sounds like some users can have requestToPurchaseProduct effectively hang without an error code returned. Is requestToPurchaseProduct always supposed to throw an error to timeout, or are we expected to handle timing out purchase requests ourselves?

After the hanging, users who close the app and retry again end up getting stuck with PurchaseErrorCode.operationAlreadyInProgress. The error documentation said to wait but the user has been stuck with PurchaseErrorCode.operationAlreadyInProgress for a while, so is there any recommended ways to debug/handle this state? 

 

 

 

 

icon

Best answer by Cesar 15 October 2021, 22:42

View original

22 replies

Cesar
Rank
Userlevel 3
Badge +3

Hi @Steph !

We are looking into this. We had some instances where we were trying to return from a thread instead of the main thread and Flutter would just hang forever without returning, I think that’s what it’s going on here. We just need to figure out where we are not returning from the main thread :grin:

I am confused about the `PurchaseErrorCode.operationAlreadyInProgress` error though. We only return that if `purchase` is called more than once. I think an easy way to reproduce that one would be to try to repeatedly press the purchase button. If you are not preventing the purchase button from being pressed after the first press, you could see that error.

I will report back with any findings.

Steph
Userlevel 1
Badge +9

@Cesar Got it, thanks for the update!

We do disable our button while the purchase request is in process. But for the bug report, they killed the app because of the hanging issue and went back to the subscription screen to try to repurchase. It sounds like `PurchaseErrorCode.operationAlreadyInProgress` is likely a weird side effect of the hanging issue so we can wait on your update!

Cesar
Rank
Userlevel 3
Badge +3

@Steph I noticed how they say:
 

The screen initially got hung on the Start Trial button after I switched to the monthly plan.

 

Are you offering a way to change subscriptions? Like a way to switch from an annual to a monthly plan? Or is this happening to users that go from a free to a paid plan?

By the way, I forgot to ask in my previous post, which version of purchases-flutter are you using? Has this started happening in a particular version?

My theory about the threads doesn’t look promising :sweat_smile:


Thanks!

Steph
Userlevel 1
Badge +9

@Cesar Sorry missed the last message! We offer both annual and monthly subscriptions (screenshots attached) and the bug report is for people who are on the free version and want to try the monthly subscription trial for the first time. When the user says they switch, they are referring to how our subscription screen defaults to annual so they switch to monthly to initiate the free trial.

 

Here’s our version data:

// flutter version
Flutter 2.5.1 • channel stable • https://github.com/flutter/flutter.git
Framework • revision ffb2ecea52 (5 weeks ago) • 2021-09-17 15:26:33 -0400
Engine • revision b3af521a05
Tools • Dart 2.14.2

// pubspec.yaml
purchases_flutter: ^3.3.1


// pubspec.lock
purchases_flutter:
    dependency: "direct main"
    description:
      name: purchases_flutter
      url: "https://pub.dartlang.org"
    source: hosted
    version: "3.4.5"

 

 

 

 

 

Users get 2 subscription options and the bug report chose monthly (as a user who doesn’t have a subscription yet)

 

After they choose the monthly option, they confirm by starting the 3 day trial.
Cesar
Rank
Userlevel 3
Badge +3

I saw you’re getting more reports of the same in your bug report system. You haven’t been able to reproduce it yet right? I am going to download your app and see if I can reproduce it myself. 

Steph
Userlevel 1
Badge +9

@Cesar Just wanted to double check that you received the last post or if there were any updates, thanks!

Cesar
Rank
Userlevel 3
Badge +3

@Steph yes, sorry I took a little bit to reply. I actually had just sent a message right when you sent yours :sweat_smile:

Steph
Userlevel 1
Badge +9

@Cesar Haha funny timing! Yes we got another report although still haven’t been able to reproduce their issue when we tried several times. :( So far it seems like reports so far are coming from Android users (although hard to say if it’s specific to Android). 

What are the exact conditions for `PurchaseErrorCode.operationAlreadyInProgress` getting triggered? Is this when RevenueCat is waiting on Google Play/App Store to process? And is there no way to reset the “operation” state?

Cesar
Rank
Userlevel 3
Badge +3

@Steph  I have reproduced it with an emulator. The emulator is a Pixel 4 API 31 with target Android 12 (Google Play), CPU x86_64. I got the hanging spinning button, then I reopened the app (without closing it) and went through the purchase screen again, and of course I tried to purchase again and I got the `OperationAlreadyInProgress` error.

The reason is that it looks like for some strange reason I still don’t know when RevenueCat calls the BillingClient function to start the billing flow, the BillingClient just hangs forever. The first time I reproed it, the app actually crashed. I wonder if you could see these crashes in your crash report system. I have the logs, but since it’s the full logcat, I don’t know which exception is the one that crashed the app.

What’s more interesting is that after I forced closed the app and reopened it, the purchase worked! 

I have some questions for you. Can you please share your list of flutter plugins? I have a feeling there’s something breaking either the network requests or either billing client itself.

Cesar
Rank
Userlevel 3
Badge +3

Update: I uninstalled the app and reinstalled it in the emulator and I am seeing it again. I am just going to the paywall through the Learn More in the top banner in the main screen then pressing the See All Plans and then choosing the monthly and pressing start trial. Hopefully you can reproduce it too in a Debug build and we can get more logs :upside_down:

Cesar
Rank
Userlevel 3
Badge +3

Another update @Steph : Looks like it doesn’t have to be the monthly plan, it happens with the annual too. I found some interesting logs:

​
2021-10-22 14:04:26.615 8777-8930/? D/EGL_emulation: eglMakeCurrent: 0x71789c45d490: ver 3 0 (tinfo 0x717ab70c0280) (first time)
2021-10-22 14:04:26.616 551-670/? D/ConnectivityService: NetReassign [171 : null → 102]
2021-10-22 14:04:26.625 8777-8917/? E/h.a.b.n: Encountered an error connecting to Google Play Services for advertising id
  java.lang.NoSuchMethodException: h.d.a.c.a.a.a.getAdvertisingIdInfo [class android.content.Context]
  at java.lang.Class.getMethod(Class.java:2103)
  at java.lang.Class.getMethod(Class.java:1724)
  at h.a.b.n$b.q(Unknown Source:16)
  at h.a.b.n$b.o(Unknown Source:17)
  at h.a.b.n$b.<init>(Unknown Source:5)
  at h.a.b.n$b.<init>(Unknown Source:0)
  at h.a.b.n.g(Unknown Source:7)
  at h.a.b.n.u(Unknown Source:0)
  at h.a.b.e.I(Unknown Source:54)
  at h.a.b.a.run(Unknown Source:8)
  at android.os.Handler.handleCallback(Handler.java:938)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loopOnce(Looper.java:201)
  at android.os.Looper.loop(Looper.java:288)
  at android.os.HandlerThread.run(HandlerThread.java:67)
2021-10-22 14:04:26.630 551-663/? D/WifiNetworkFactory: got request NetworkRequest [ REQUEST id=171, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10149 RequestorUid: 10149 RequestorPkg: com.finch.finch] ]
2021-10-22 14:04:26.633 551-663/? D/UntrustedWifiNetworkFactory: got request NetworkRequest [ REQUEST id=171, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10149 RequestorUid: 10149 RequestorPkg: com.finch.finch] ]
2021-10-22 14:04:26.636 551-663/? D/OemPaidWifiNetworkFactory: got request NetworkRequest [ REQUEST id=171, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10149 RequestorUid: 10149 RequestorPkg: com.finch.finch] ]
2021-10-22 14:04:26.690 8777-8917/? W/h.a.b.n: Google Play Services not available
2021-10-22 14:04:26.692 8777-8917/? W/h.a.b.n: Google Play Services SDK not found for app set id!
2021-10-22 14:04:26.707 1404-1404/? D/BoundBrokerSvc: onBind: Intent { act=com.google.android.gms.common.BIND_SHARED_PREFS pkg=com.google.android.gms }
2021-10-22 14:04:26.712 1404-1404/? D/BoundBrokerSvc: Loading bound service for intent: Intent { act=com.google.android.gms.common.BIND_SHARED_PREFS pkg=com.google.android.gms }
2021-10-22 14:04:26.715 1404-1404/? D/BoundBrokerSvc: onUnbind: Intent { act=com.google.android.gms.common.BIND_SHARED_PREFS pkg=com.google.android.gms }
2021-10-22 14:04:26.836 8777-8823/? V/NativeCrypto: Registering com/google/android/gms/org/conscrypt/NativeCrypto's 294 native methods...
2021-10-22 14:04:26.898 8777-8929/? D/HostConnection: createUnique: call
2021-10-22 14:04:26.898 8777-8929/? D/HostConnection: HostConnection::get() New Host Connection established 0x71789c457550, tid 8929
2021-10-22 14:04:26.929 8777-8823/? I/ProviderInstaller: Installed default security provider GmsCore_OpenSSL
2021-10-22 14:04:26.947 8777-8929/? D/HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_native_sync_v2 ANDROID_EMU_native_sync_v3 ANDROID_EMU_native_sync_v4 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_YUV_Cache ANDROID_EMU_async_unmap_buffer ANDROID_EMU_has_shared_slots_host_memory_allocator ANDROID_EMU_sync_buffer_data ANDROID_EMU_read_color_buffer_dma GL_OES_EGL_image_external_essl3 GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_host_side_tracing ANDROID_EMU_async_frame_commands ANDROID_EMU_gles_max_version_3_0
2021-10-22 14:04:26.948 8777-8929/? D/EGL_emulation: eglMakeCurrent: 0x71789c45f050: ver 3 0 (tinfo 0x717ab70c0300) (first time)
2021-10-22 14:04:26.951 8777-8929/? D/EGL_emulation: eglCreateContext: 0x71789c45d250: maj 3 min 0 rcv 3
2021-10-22 14:04:26.954 468-626/? W/ServiceManager: Permission failure: android.permission.SYSTEM_CAMERA from uid=10103 pid=1404
2021-10-22 14:04:26.967 8777-8927/? I/flutter: HomeWidgetBackgroundUpdate: Updating widget
2021-10-22 14:04:26.967 2741-2840/? D/PaySecureElementClient: Felica app not found; returning isSecureElementAvailable = false!
2021-10-22 14:04:26.967 8777-8927/? I/flutter: HomePetWidget: Start updating widget from timeline
2021-10-22 14:04:26.970 468-626/? W/ServiceManager: Permission failure: android.permission.SYSTEM_CAMERA from uid=10103 pid=1404
2021-10-22 14:04:26.971 468-5440/? W/ServiceManager: Permission failure: android.permission.SYSTEM_CAMERA from uid=10103 pid=1404
2021-10-22 14:04:26.972 468-5440/? W/ServiceManager: Permission failure: android.permission.SYSTEM_CAMERA from uid=10103 pid=1404
2021-10-22 14:04:26.974 551-2625/? D/BiometricService: canAuthenticate: User=0, Caller=0, Authenticators=15
2021-10-22 14:04:26.974 551-2625/? D/BiometricService/PreAuthInfo: Package: com.android.vending Sensor ID: 0 Modality: 2 Status: 7
2021-10-22 14:04:26.974 551-2625/? D/BiometricService/PreAuthInfo: getCanAuthenticateInternal Modality: 2 AuthenticatorStatus: 7
2021-10-22 14:04:26.974 551-2625/? D/AuthService: canAuthenticate, userId: 0, callingUserId: 0, authenticators: 15, result: 11
2021-10-22 14:04:26.975 551-2625/? D/BiometricService: canAuthenticate: User=0, Caller=0, Authenticators=255
2021-10-22 14:04:26.975 551-2625/? D/BiometricService/PreAuthInfo: Package: com.android.vending Sensor ID: 0 Modality: 2 Status: 7
2021-10-22 14:04:26.975 551-2625/? D/BiometricService/PreAuthInfo: getCanAuthenticateInternal Modality: 2 AuthenticatorStatus: 7
2021-10-22 14:04:26.975 551-2625/? D/AuthService: canAuthenticate, userId: 0, callingUserId: 0, authenticators: 255, result: 11
2021-10-22 14:04:26.976 551-2625/? D/BiometricService: canAuthenticate: User=0, Caller=0, Authenticators=15
2021-10-22 14:04:26.976 551-2625/? D/BiometricService/PreAuthInfo: Package: com.android.vending Sensor ID: 0 Modality: 2 Status: 7
2021-10-22 14:04:26.976 551-2625/? D/BiometricService/PreAuthInfo: getCanAuthenticateInternal Modality: 2 AuthenticatorStatus: 7
2021-10-22 14:04:26.976 551-2625/? D/AuthService: canAuthenticate, userId: 0, callingUserId: 0, authenticators: 15, result: 11
2021-10-22 14:04:26.979 8777-8927/? I/flutter: HomePetWidget: Cancel update from timeline
2021-10-22 14:04:26.981 1404-1404/? D/BoundBrokerSvc: onBind: Intent { act=com.google.android.gms.ocr.service.internal.START cmp=com.google.android.gms/.chimera.GmsInternalApiService }
2021-10-22 14:04:26.982 1404-1404/? D/BoundBrokerSvc: Loading bound service for intent: Intent { act=com.google.android.gms.ocr.service.internal.START cmp=com.google.android.gms/.chimera.GmsInternalApiService }
2021-10-22 14:04:26.985 2741-3151/? I/Finsky: [98] hbd.run(24): Skipping a request to /bulkAcquire since cache has all the records.
2021-10-22 14:04:26.987 8777-8847/? I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=f5eb31e7-b49b-45dc-9fc3-62a5a0ced36c, tags={ be.tramckrijte.workmanager.BackgroundWorker } ]
2021-10-22 14:04:27.064 551-2625/? D/ConnectivityService: requestNetwork for uid/pid:10149/8777 activeRequest: null callbackRequest: 172 [NetworkRequest [ REQUEST id=173, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10149 RequestorUid: 10149 RequestorPkg: com.finch.finch] ]] callback flags: 0 priority: 2147483647
2021-10-22 14:04:27.067 551-670/? D/ConnectivityService: NetReassign [173 : null → 102]
2021-10-22 14:04:27.082 551-663/? D/WifiNetworkFactory: got request NetworkRequest [ REQUEST id=173, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10149 RequestorUid: 10149 RequestorPkg: com.finch.finch] ]
2021-10-22 14:04:27.083 551-663/? D/UntrustedWifiNetworkFactory: got request NetworkRequest [ REQUEST id=173, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10149 RequestorUid: 10149 RequestorPkg: com.finch.finch] ]
2021-10-22 14:04:27.083 551-663/? D/OemPaidWifiNetworkFactory: got request NetworkRequest [ REQUEST id=173, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VCN_MANAGED Uid: 10149 RequestorUid: 10149 RequestorPkg: com.finch.finch] ]
2021-10-22 14:04:27.133 1120-6772/? W/NetworkScheduler: The extras of the task is not valid to be persisted so that the task is not persisted [CONTEXT service_id=218 ]
  java.lang.IllegalArgumentException: Only the following extra parameter types are supported: Integer, Long, Double, String, Boolean, and nested Bundles with the same restrictions.
  at aags.f(:com.google.android.gms@213916056@21.39.16 (190800-402663742):6)
  at alat.g(:com.google.android.gms@213916056@21.39.16 (190800-402663742):37)
  at alac.n(:com.google.android.gms@213916056@21.39.16 (190800-402663742):3)
  at alac.u(:com.google.android.gms@213916056@21.39.16 (190800-402663742):20)
  at alac.g(:com.google.android.gms@213916056@21.39.16 (190800-402663742):3)
  at akwx.run(:com.google.android.gms@213916056@21.39.16 (190800-402663742):9)
  at pvw.c(:com.google.android.gms@213916056@21.39.16 (190800-402663742):6)
  at pvw.run(:com.google.android.gms@213916056@21.39.16 (190800-402663742):7)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
  at qac.run(:com.google.android.gms@213916056@21.39.16 (190800-402663742):0)
  at java.lang.Thread.run(Thread.java:920)
2021-10-22 14:04:27.198 8777-8777/? E/libEGL: call to OpenGL ES API with no current context (logged once per thread)
2021-10-22 14:04:27.301 8777-8777/? D/[Purchases] - DEBUG:  Ending connection for com.android.billingclient.api.d@8cf3f47

​


Are you maybe using `workmanager` plugin and suffering from https://github.com/RevenueCat/purchases-flutter/issues/257. I think this is probably what’s going on. 

Steph
Userlevel 1
Badge +9

Ah interesting, yes we are using workmanager on Android and are now able to reproduce thanks to the above! The real device that didn’t seem to be replicating so this helps a lot. Thanks for sharing, we’ll look into the workaround.

Cesar
Rank
Userlevel 3
Badge +3

Great! We should release a version fixing it for everyone though. I will see if I can work on that soon.

Steph
Userlevel 1
Badge +9

Ah that’d be very appreciated! 🙏🏻🙏🏻🙏🏻

Cesar
Rank
Userlevel 3
Badge +3

I just opened a PR that should fix this https://github.com/RevenueCat/purchases-flutter/pull/268 

We will hopefully release it soon :wink:

Cesar
Rank
Userlevel 3
Badge +3

@Steph https://github.com/RevenueCat/purchases-flutter/releases/tag/3.5.0 has been released. Can you please let me know if it fixes your issues? Thanks!!

Steph
Userlevel 1
Badge +9

@Cesar Updating does seem to have fixed the billing service disconnect-- thanks so much for getting this out!

T
Userlevel 1
Badge +5

Hi @Cesar I’m having this problem too but I’m already using the latest version at the moment (4.1.2).

Both on real iPhone and iOS simulator, the function `Purchases.purchasePackage()` hangs and deesn’t return at all.

Cesar
Rank
Userlevel 3
Badge +3

@Thanh Do you also have a dependency on workmanager?

T
Userlevel 1
Badge +5

@Cesar I guess I don’t have workmanager. I checked my pubspec.lock for the name but cannot find it.

Cesar
Rank
Userlevel 3
Badge +3

Do you mind opening another post providing debug logs and your pubspec dependencies? I think that way we’ll be able to help you out better and the post will have better visibility.

Thanks!

T
Userlevel 1
Badge +5

Sure. Thank you. Here’s my new topic: 

 

Reply


Terms & ConditionsCookie settings