Skip to content

PostReceiptDataOperation: log Apple error when purchase equals expiration date#2038

Merged
NachoSoto merged 2 commits into
mainfrom
log-purchase-equal-expiration
Nov 9, 2022
Merged

PostReceiptDataOperation: log Apple error when purchase equals expiration date#2038
NachoSoto merged 2 commits into
mainfrom
log-purchase-equal-expiration

Conversation

@NachoSoto

@NachoSoto NachoSoto commented Nov 8, 2022

Copy link
Copy Markdown
Contributor

A large amount of flaky integration tests are due to this bug, so detecting it early in the logs will help debug this.
Radar: FB11767559.

productType is missing in StoreKitTest purchases, so I changed isSubscription to default to checking if there is an expiration when the type is .unknown.
To simplify the code, I changed ProductType? to be non-optional, since we already have .unknown as a case.

Example:

[00:27:56]: ▸ 2022-11-09 00:27:56.000533+0000 BackendIntegrationTestsHostApp[3942:17000] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Posting receipt: {
[00:27:56]: ▸   "opaque_value" : "1n+XXw8AAAA=",
[00:27:56]: ▸   "sha1_hash" : "unR7vAzPaUlB0TtZ09z5jMyqqAs=",
[00:27:56]: ▸   "bundle_id" : "com.revenuecat.StoreKitTestApp",
[00:27:56]: ▸   "in_app_purchases" : [
[00:27:56]: ▸     {
[00:27:56]: ▸       "quantity" : 1,
[00:27:56]: ▸       "product_id" : "com.revenuecat.weekly_1.99.3_day_intro",
[00:27:56]: ▸       "purchase_date" : "2022-11-09T00:27:50Z",
[00:27:56]: ▸       "transaction_id" : "0",
[00:27:56]: ▸       "is_in_intro_offer_period" : true,
[00:27:56]: ▸       "expires_date" : "2022-11-09T00:27:50Z"
[00:27:56]: ▸     },
[00:27:56]: ▸     {
[00:27:56]: ▸       "product_id" : "com.revenuecat.weekly_1.99.3_day_intro",
[00:27:56]: ▸       "quantity" : 1,
[00:27:56]: ▸       "transaction_id" : "1",
[00:27:56]: ▸       "is_in_intro_offer_period" : false,
[00:27:56]: ▸       "expires_date" : "2022-11-09T00:28:00Z",
[00:27:56]: ▸       "original_purchase_date" : "2022-11-09T00:27:50Z",
[00:27:56]: ▸       "original_transaction_id" : "0",
[00:27:56]: ▸       "purchase_date" : "2022-11-09T00:27:50Z"
[00:27:56]: ▸     }
[00:27:56]: ▸   ],
[00:27:56]: ▸   "application_version" : "1",
[00:27:56]: ▸   "creation_date" : "2022-11-09T00:27:55Z",
[00:27:56]: ▸   "expiration_date" : "4001-01-01T00:00:00Z"
[00:27:56]: ▸ }
[00:27:56]: ▸ 2022-11-09 00:27:56.000710+0000 BackendIntegrationTestsHostApp[3942:17000] [Purchases] - ERROR: 🍎‼️ Receipt for product 'com.revenuecat.weekly_1.99.3_day_intro' has the same purchase (2022-11-09 00:27:50 +0000) and expiration (2022-11-09 00:27:50 +0000) dates. This is likely a StoreKit bug.

@NachoSoto NachoSoto added the test label Nov 8, 2022
@NachoSoto NachoSoto requested a review from a team November 8, 2022 17:10
@NachoSoto NachoSoto force-pushed the log-purchase-equal-expiration branch from ca77557 to 378f9d0 Compare November 8, 2022 17:25
@NachoSoto

Copy link
Copy Markdown
Contributor Author

Hmm wait this didn't work?

[17:29:09]: ▸ 2022-11-08 17:29:09.472623+0000 BackendIntegrationTestsHostApp[4237:18935] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Posting receipt: {
[17:29:09]: ▸   "opaque_value" : "+5ff\/QkAAAA=",
[17:29:09]: ▸   "sha1_hash" : "zMLvh7dMVqV8xa1FC5qVnBFs1+0=",
[17:29:09]: ▸   "bundle_id" : "com.revenuecat.StoreKitTestApp",
[17:29:09]: ▸   "in_app_purchases" : [
[17:29:09]: ▸     {
[17:29:09]: ▸       "quantity" : 1,
[17:29:09]: ▸       "product_id" : "com.revenuecat.weekly_1.99.3_day_intro",
[17:29:09]: ▸       "purchase_date" : "2022-11-08T17:29:09Z",
[17:29:09]: ▸       "transaction_id" : "0",
[17:29:09]: ▸       "is_in_intro_offer_period" : true,
[17:29:09]: ▸       "expires_date" : "2022-11-08T17:29:09Z"
[17:29:09]: ▸     }
[17:29:09]: ▸   ],
[17:29:09]: ▸   "application_version" : "1",
[17:29:09]: ▸   "creation_date" : "2022-11-08T17:29:09Z",
[17:29:09]: ▸   "expiration_date" : "4001-01-01T00:00:00Z"
[17:29:09]: ▸ }
[17:29:09]: ▸ 2022-11-08 17:29:09.472802+0000 BackendIntegrationTestsHostApp[4237:18935] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
[17:29:09]: ▸ 2022-11-08 17:29:09.474132+0000 BackendIntegrationTestsHostApp[4237:18935] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
[17:29:09]: ▸ 2022-11-08 17:29:09.673765+0000 BackendIntegrationTestsHostApp[4237:18936] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts 422
[17:29:09]: ▸ 2022-11-08 17:29:09.676052+0000 BackendIntegrationTestsHostApp[4237:18936] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
[17:29:09]: ▸ 2022-11-08 17:29:09.676081+0000 BackendIntegrationTestsHostApp[4237:18913] [Purchases] - ERROR: 😿‼️ The receipt is not valid. The purchased product was missing in the receipt. This is typically due to a bug in StoreKit.
[17:29:09]: ▸ 2022-11-08 17:29:09.676345+0000 BackendIntegrationTestsHostApp[4237:18913] [Purchases] - INFO: 💰 Finishing transaction '0' for product 'com.revenuecat.weekly_1.99.3_day_intro'
[17:29:09]: ▸ 2022-11-08 17:29:09.676351+0000 BackendIntegrationTestsHostApp[4237:18936] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
[17:29:09]: ▸ 2022-11-08 17:29:09.750567+0000 BackendIntegrationTestsHostApp[4237:18938] [Purchases] - ERROR: 💰 Product purchase for 'com.revenuecat.weekly_1.99.3_day_intro' failed with error: Error Domain=RevenueCat.ErrorCode Code=8 "The receipt is not valid. The purchased product was missing in the receipt. This is typically due to a bug in StoreKit." UserInfo={readable_error_code=INVALID_RECEIPT, source_file=RevenueCat/HTTPClient.swift:378, NSUnderlyingError=0x60000010def0 {Error Domain=RevenueCat.BackendErrorCode Code=7712 "The purchased product was missing in the receipt. This is typically due to a bug in StoreKit." UserInfo={NSLocalizedDescription=The purchased product was missing in the receipt. This is typically due to a bug in StoreKit.}}, source_function=convertUnsuccessfulResponseToError(), NSLocalizedDescription=The receipt is not valid. The purchased product was missing in the receipt. This is typically due to a bug in StoreKit., rc_response_status_code=422}
[17:29:09]: ▸ 2022-11-08 17:29:09.750966+0000 BackendIntegrationTestsHostApp[4237:18913] [Purchases] - ERROR: 😿‼️ Unknown error.
[17:29:09]: ▸ 2022-11-08 17:29:09.753538+0000 BackendIntegrationTestsHostApp[4237:18913] Exception attempting to serialize sanitized error of issue. All userInfo with be discarded except localized description: NSInvalidUnarchiveOperationException: The data couldn’t be read because it isn’t in the correct format.
[17:29:09]: ▸ <unknown>:0: error: -[BackendIntegrationTests.StoreKit2IntegrationTests testIneligibleForIntroAfterPurchaseExpires] : failed: caught error: "Unknown error."

@NachoSoto

Copy link
Copy Markdown
Contributor Author

Oh it's because there's no productType.

Comment thread Sources/LocalReceiptParsing/BasicTypes/InAppPurchase.swift Outdated
@NachoSoto NachoSoto requested review from a team and aboedo November 9, 2022 00:21
@NachoSoto

Copy link
Copy Markdown
Contributor Author

Removed AppleReceipt.InAppPurchase.ProductType.

@NachoSoto NachoSoto force-pushed the log-purchase-equal-expiration branch from 378f9d0 to 40554f4 Compare November 9, 2022 00:22
NachoSoto added a commit that referenced this pull request Nov 9, 2022
…around 0-second subscriptions

As exposed by #2038, weekly subscriptions were leading to false negatives because they were always expired by the time the purchase was made using `TimeRate.monthlyRenewalEveryThirtySeconds`, instead of lasting 10 seconds as documented.
(`FB11767559`)

The advantage of using weekly subscriptions was to also work around `FB11767679`, which means that we have to manually _wait_ for the subscription to expire, as `SKTestSession.expireSubscription(productIdentifier:)` doesn't actually change the receipt.
Because we had to wait, using weekly subscriptions was faster, since we only needed to wait 10 seconds.

This does mean that expirations in these tests now have to wait 30 seconds instead of 10, but now they're no longer flaky 🎉
NachoSoto added a commit that referenced this pull request Nov 9, 2022
…around 0-second subscriptions

As exposed by #2038, weekly subscriptions were leading to false negatives because they were always expired by the time the purchase was made using `TimeRate.monthlyRenewalEveryThirtySeconds`, instead of lasting 10 seconds as documented.
(`FB11767559`)

The advantage of using weekly subscriptions was to also work around `FB11767679`, which means that we have to manually _wait_ for the subscription to expire, as `SKTestSession.expireSubscription(productIdentifier:)` doesn't actually change the receipt.
Because we had to wait, using weekly subscriptions was faster, since we only needed to wait 10 seconds.

This does mean that expirations in these tests now have to wait 30 seconds instead of 10, but now they're no longer flaky 🎉
NachoSoto added a commit that referenced this pull request Nov 9, 2022
…around 0-second subscriptions (#2042)

As exposed by #2038, weekly subscriptions were leading to false
negatives because they were always expired by the time the purchase was
made (using `TimeRate.monthlyRenewalEveryThirtySeconds`), instead of
lasting 10 seconds as documented. This is reported as `FB11767559`.

The advantage of using weekly subscriptions was to also work around
`FB11767679`, which means that we have to manually _wait_ for the
subscription to expire, as
`SKTestSession.expireSubscription(productIdentifier:)` doesn't actually
change the receipt.
Because we had to wait, using weekly subscriptions was faster, since we
only needed to wait 10 seconds.

This does mean that expirations in these tests now have to wait 30
seconds instead of 10, but now they're no longer flaky 🎉
Looks like tests right now pass in CI in less than 7 minutes, which I
believe is totally acceptable, especially for the benefit of no longer
having these flaky tests.
…ration date

A large amount of flaky integration tests are due to this bug, so detecting it early in the logs will help debug this.
Radar: `FB11767559`.
@NachoSoto NachoSoto force-pushed the log-purchase-equal-expiration branch from 40554f4 to d84768c Compare November 9, 2022 14:40
@NachoSoto NachoSoto force-pushed the log-purchase-equal-expiration branch from d84768c to 8cdf8fb Compare November 9, 2022 19:10
@NachoSoto NachoSoto merged commit 8b4a9ec into main Nov 9, 2022
@NachoSoto NachoSoto deleted the log-purchase-equal-expiration branch November 9, 2022 19:18
NachoSoto pushed a commit that referenced this pull request Nov 18, 2022
**This is an automatic release.**

### Bugfixes
* `StoreKit 2`: don't finish transactions in observer mode (#2053) via
NachoSoto (@NachoSoto)
### Other Changes
* `CircleCI`: added ability to create a release manually (#2067) via
NachoSoto (@NachoSoto)
* Changelog: Fix links to V4 API Migration guide (#2051) via Kevin
Quisquater (@KevinQuisquater)
* `HTTPClient`: added log for failed requests (#2048) via NachoSoto
(@NachoSoto)
* `ErrorResponse.asBackendError`: serialize attribute errors as
`NSDictionary` (#2034) via NachoSoto (@NachoSoto)
* `ErrorCode.unknownBackendError`: include original error code (#2032)
via NachoSoto (@NachoSoto)
* `CI`: fixed `push-pods` job (#2045) via NachoSoto (@NachoSoto)
* `PostReceiptDataOperation`: log Apple error when purchase equals
expiration date (#2038) via NachoSoto (@NachoSoto)
* Update Fastlane plugin (#2041) via Cesar de la Vega (@vegaro)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants