Skip to content

Purchasing: fixed consumable purchases by fixing transaction-finishing#1965

Merged
NachoSoto merged 4 commits into
mainfrom
integration-test-consumable-purchase
Oct 11, 2022
Merged

Purchasing: fixed consumable purchases by fixing transaction-finishing#1965
NachoSoto merged 4 commits into
mainfrom
integration-test-consumable-purchase

Conversation

@NachoSoto

@NachoSoto NachoSoto commented Oct 6, 2022

Copy link
Copy Markdown
Contributor

Fixes #1964, TRIAGE-134, TRIAGE-131, and possibly TRIAGE-82.

Depends on #1967, #1968.

Fixes:

  • For SK2 purchases we were never finishing transactions. We are now.
  • For SK1 purchases, transactions were finished after the completion block was invoked (and tests were very lenient checking that eventually this happened). This could have lead to race conditions.
  • For SK2 only (at least in SKTestSessions), this fixes the ability to purchase multiple consumable purchases.

This is the log from the failing test using SK2:

Open
2022-10-06 15:18:52.286813-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:6f630d50b8294288a2d0862629d766fb/offerings
2022-10-06 15:18:52.383594-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - DEBUG: ℹ️ API request completed: GET /v1/subscribers/$RCAnonymousID:6f630d50b8294288a2d0862629d766fb/offerings 200
2022-10-06 15:18:52.388247-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - DEBUG: ℹ️ No existing products cached, starting store products request for: ["com.revenuecat.weekly_1.99.3_day_intro", "consumable.10_coins", "com.revenuecat.annual_39.99.2_week_intro", "com.revenuecat.monthly_4.99.1_week_intro"]
2022-10-06 15:18:52.388382-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - DEBUG: ℹ️ Found an existing request for products: ["com.revenuecat.monthly_4.99.1_week_intro", "com.revenuecat.annual_39.99.2_week_intro", "com.revenuecat.weekly_1.99.3_day_intro", "consumable.10_coins"], appending to completion
2022-10-06 15:18:52.388451-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - DEBUG: ℹ️ GetOfferingsOperation: Finished
2022-10-06 15:18:52.388560-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - DEBUG: ℹ️ Serial request done: GET subscribers/$RCAnonymousID%3A6f630d50b8294288a2d0862629d766fb/offerings, 0 requests left in the queue
2022-10-06 15:18:52.420210-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - DEBUG: 😻 Store products request request received response
2022-10-06 15:18:52.420358-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - DEBUG: ℹ️ Store products request finished
2022-10-06 15:18:52.421126-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - DEBUG: ℹ️ Vending Offerings from cache
2022-10-06 15:18:52.421353-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - INFO: 💰 Purchasing Product 'consumable.10_coins' from package in Offering 'coins'
2022-10-06 15:18:52.496438-0700 BackendIntegrationTestsHostApp[45464:7076968] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2022-10-06 15:18:52.510974-0700 BackendIntegrationTestsHostApp[45464:7076903] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///Users/nachosoto/Library/Developer/CoreSimulator/Devices/A3576DC2-355E-45BA-B32C-D2C0A3811BB4/data/Containers/Data/Application/BFD385C4-52BC-414B-9C1C-44522ED1222F/StoreKit/receipt
2022-10-06 15:18:52.511072-0700 BackendIntegrationTestsHostApp[45464:7076903] [Purchases] - DEBUG: ℹ️ Skipping products request because products were already cached. products: ["consumable.10_coins"]
2022-10-06 15:18:52.511181-0700 BackendIntegrationTestsHostApp[45464:7076903] [Purchases] - DEBUG: ℹ️ Skipping products request because products were already cached. products: ["consumable.10_coins"]
2022-10-06 15:18:52.511564-0700 BackendIntegrationTestsHostApp[45464:7076903] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:6f630d50b8294288a2d0862629d766fb
2022-10-06 15:18:52.515448-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2022-10-06 15:18:52.516403-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2022-10-06 15:18:52.516763-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Posting receipt: {
  "opaque_value" : "oX91ewAAAAA=",
  "sha1_hash" : "GsyNpUKQ89SonYyj\/jpw8\/N5nr8=",
  "bundle_id" : "com.revenuecat.StoreKitTestApp",
  "in_app_purchases" : [
    {
      "quantity" : 1,
      "product_id" : "consumable.10_coins",
      "purchase_date" : "2022-10-06T22:18:52Z",
      "transaction_id" : "0"
    }
  ],
  "application_version" : "1",
  "creation_date" : "2022-10-06T22:18:52Z",
  "expiration_date" : "4001-01-01T00:00:00Z"
}
2022-10-06 15:18:52.516825-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2022-10-06 15:18:52.518059-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2022-10-06 15:18:52.960048-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts 200
2022-10-06 15:18:52.964274-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2022-10-06 15:18:52.964666-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2022-10-06 15:18:52.966476-0700 BackendIntegrationTestsHostApp[45464:7076903] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2022-10-06 15:18:52.966697-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - INFO: 😻💰 Purchased product - 'consumable.10_coins'
2022-10-06 15:18:52.966973-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - DEBUG: ℹ️ Vending Offerings from cache
2022-10-06 15:18:52.967284-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - INFO: 💰 Purchasing Product 'consumable.10_coins' from package in Offering 'coins'
2022-10-06 15:18:52.991334-0700 BackendIntegrationTestsHostApp[45464:7076973] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2022-10-06 15:18:53.015046-0700 BackendIntegrationTestsHostApp[45464:7076903] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///Users/nachosoto/Library/Developer/CoreSimulator/Devices/A3576DC2-355E-45BA-B32C-D2C0A3811BB4/data/Containers/Data/Application/BFD385C4-52BC-414B-9C1C-44522ED1222F/StoreKit/receipt
2022-10-06 15:18:53.015174-0700 BackendIntegrationTestsHostApp[45464:7076903] [Purchases] - DEBUG: ℹ️ Skipping products request because products were already cached. products: ["consumable.10_coins"]
2022-10-06 15:18:53.015262-0700 BackendIntegrationTestsHostApp[45464:7076903] [Purchases] - DEBUG: ℹ️ Skipping products request because products were already cached. products: ["consumable.10_coins"]
2022-10-06 15:18:53.015419-0700 BackendIntegrationTestsHostApp[45464:7076903] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:6f630d50b8294288a2d0862629d766fb
2022-10-06 15:18:53.015927-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2022-10-06 15:18:53.016558-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2022-10-06 15:18:53.016727-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Posting receipt: {
  "opaque_value" : "LP9LZQwAAAA=",
  "sha1_hash" : "WdANBTWr7wYWh8RYEgmGebO8DR8=",
  "bundle_id" : "com.revenuecat.StoreKitTestApp",
  "in_app_purchases" : [
    {
      "quantity" : 1,
      "product_id" : "consumable.10_coins",
      "purchase_date" : "2022-10-06T22:18:52Z",
      "transaction_id" : "0"
    }
  ],
  "application_version" : "1",
  "creation_date" : "2022-10-06T22:18:53Z",
  "expiration_date" : "4001-01-01T00:00:00Z"
}
2022-10-06 15:18:53.016783-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2022-10-06 15:18:53.017602-0700 BackendIntegrationTestsHostApp[45464:7076966] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2022-10-06 15:18:53.411689-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts 200
2022-10-06 15:18:53.413980-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2022-10-06 15:18:53.414147-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2022-10-06 15:18:53.414927-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - INFO: 😻💰 Purchased product - 'consumable.10_coins'
2022-10-06 15:18:53.415505-0700 BackendIntegrationTestsHostApp[45464:7076978] [Purchases] - DEBUG: ℹ️ Vending CustomerInfo from cache.

With the fix, you can see transactions are now finished at the right time:

Open
2022-10-07 11:08:01.967843-0700 BackendIntegrationTestsHostApp[45714:674592] [Purchases] - INFO: 💰 Purchasing Product 'consumable.10_coins' from package in Offering 'coins'
2022-10-07 11:08:02.123611-0700 BackendIntegrationTestsHostApp[45714:674592] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2022-10-07 11:08:02.138918-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///Users/nachosoto/Library/Developer/CoreSimulator/Devices/F02A9A20-949B-4C9D-A01E-AB0CC7544F96/data/Containers/Data/Application/C52A5EFD-733F-46EC-84B7-734B6AF9D28C/StoreKit/receipt
2022-10-07 11:08:02.139013-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Skipping products request because products were already cached. products: ["consumable.10_coins"]
2022-10-07 11:08:02.139095-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Skipping products request because products were already cached. products: ["consumable.10_coins"]
2022-10-07 11:08:02.139481-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:bd74b9d10f2c48eea1d741a32f5acb16
2022-10-07 11:08:02.147220-0700 BackendIntegrationTestsHostApp[45714:674592] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2022-10-07 11:08:02.148192-0700 BackendIntegrationTestsHostApp[45714:674592] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2022-10-07 11:08:02.148552-0700 BackendIntegrationTestsHostApp[45714:674592] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Posting receipt: {
  "opaque_value" : "\/3nevQ0AAAA=",
  "sha1_hash" : "\/bAkxLQ6BPgUg3rR9jDR28dEfig=",
  "bundle_id" : "com.revenuecat.StoreKitTestApp",
  "in_app_purchases" : [
    {
      "quantity" : 1,
      "product_id" : "consumable.10_coins",
      "purchase_date" : "2022-10-07T18:08:02Z",
      "transaction_id" : "0"
    }
  ],
  "application_version" : "1",
  "creation_date" : "2022-10-07T18:08:02Z",
  "expiration_date" : "4001-01-01T00:00:00Z"
}
2022-10-07 11:08:02.148604-0700 BackendIntegrationTestsHostApp[45714:674592] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2022-10-07 11:08:02.149748-0700 BackendIntegrationTestsHostApp[45714:674592] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2022-10-07 11:08:02.733225-0700 BackendIntegrationTestsHostApp[45714:674602] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts 200
2022-10-07 11:08:02.734687-0700 BackendIntegrationTestsHostApp[45714:674602] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2022-10-07 11:08:02.734802-0700 BackendIntegrationTestsHostApp[45714:674602] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2022-10-07 11:08:02.735631-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2022-10-07 11:08:02.735700-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - INFO: 💰 Finishing transaction '0' for product 'consumable.10_coins'
2022-10-07 11:08:02.760613-0700 BackendIntegrationTestsHostApp[45714:674592] [Purchases] - INFO: 😻💰 Purchased product - 'consumable.10_coins'
2022-10-07 11:08:02.760828-0700 BackendIntegrationTestsHostApp[45714:674590] [Purchases] - DEBUG: ℹ️ Vending Offerings from cache
2022-10-07 11:08:02.761032-0700 BackendIntegrationTestsHostApp[45714:674590] [Purchases] - INFO: 💰 Purchasing Product 'consumable.10_coins' from package in Offering 'coins'
2022-10-07 11:08:02.820835-0700 BackendIntegrationTestsHostApp[45714:674589] [Purchases] - DEBUG: ℹ️ Force refreshing the receipt to get latest transactions from Apple.
2022-10-07 11:08:02.839184-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Loaded receipt from url file:///Users/nachosoto/Library/Developer/CoreSimulator/Devices/F02A9A20-949B-4C9D-A01E-AB0CC7544F96/data/Containers/Data/Application/C52A5EFD-733F-46EC-84B7-734B6AF9D28C/StoreKit/receipt
2022-10-07 11:08:02.839275-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Skipping products request because products were already cached. products: ["consumable.10_coins"]
2022-10-07 11:08:02.839348-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Skipping products request because products were already cached. products: ["consumable.10_coins"]
2022-10-07 11:08:02.839476-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Found 0 unsynced attributes for App User ID: $RCAnonymousID:bd74b9d10f2c48eea1d741a32f5acb16
2022-10-07 11:08:02.839911-0700 BackendIntegrationTestsHostApp[45714:674589] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Started
2022-10-07 11:08:02.840457-0700 BackendIntegrationTestsHostApp[45714:674589] [Purchases] - INFO: ℹ️ Receipt parsed successfully
2022-10-07 11:08:02.840603-0700 BackendIntegrationTestsHostApp[45714:674589] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Posting receipt: {
  "opaque_value" : "fXr9\/QYAAAA=",
  "sha1_hash" : "zreYwGKGSaOEww1bsTRu8MylAas=",
  "bundle_id" : "com.revenuecat.StoreKitTestApp",
  "in_app_purchases" : [
    {
      "quantity" : 1,
      "product_id" : "consumable.10_coins",
      "purchase_date" : "2022-10-07T18:08:02Z",
      "transaction_id" : "1"
    }
  ],
  "application_version" : "1",
  "creation_date" : "2022-10-07T18:08:02Z",
  "expiration_date" : "4001-01-01T00:00:00Z"
}
2022-10-07 11:08:02.840662-0700 BackendIntegrationTestsHostApp[45714:674589] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request POST receipts
2022-10-07 11:08:02.841268-0700 BackendIntegrationTestsHostApp[45714:674589] [Purchases] - DEBUG: ℹ️ API request started: POST /v1/receipts
2022-10-07 11:08:03.313116-0700 BackendIntegrationTestsHostApp[45714:674589] [Purchases] - DEBUG: ℹ️ API request completed: POST /v1/receipts 200
2022-10-07 11:08:03.316115-0700 BackendIntegrationTestsHostApp[45714:674589] [Purchases] - DEBUG: ℹ️ PostReceiptDataOperation: Finished
2022-10-07 11:08:03.316342-0700 BackendIntegrationTestsHostApp[45714:674589] [Purchases] - DEBUG: ℹ️ Serial request done: POST receipts, 0 requests left in the queue
2022-10-07 11:08:03.317444-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - DEBUG: ℹ️ Sending updated CustomerInfo to delegate.
2022-10-07 11:08:03.317527-0700 BackendIntegrationTestsHostApp[45714:674399] [Purchases] - INFO: 💰 Finishing transaction '1' for product 'consumable.10_coins'
2022-10-07 11:08:03.342767-0700 BackendIntegrationTestsHostApp[45714:674602] [Purchases] - INFO: 😻💰 Purchased product - 'consumable.10_coins'

@tonidero tonidero left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Couple of small things but looks good.

Comment thread Tests/BackendIntegrationTests/StoreKitIntegrationTests.swift Outdated
Comment thread Tests/BackendIntegrationTests/StoreKitIntegrationTests.swift Outdated
@NachoSoto NachoSoto force-pushed the integration-test-consumable-purchase branch from 2e80400 to 0699e18 Compare October 7, 2022 15:21
@NachoSoto NachoSoto requested a review from a team October 7, 2022 18:11
@NachoSoto NachoSoto force-pushed the integration-test-consumable-purchase branch from 0699e18 to d4b5d98 Compare October 7, 2022 18:22
@NachoSoto NachoSoto changed the title Integration Tests: added tests for purchasing consumable products Purchasing: fixed consumable purchases by fixing transaction finishing Oct 7, 2022
@NachoSoto NachoSoto changed the base branch from main to either-queue-wrapper October 7, 2022 18:30
@NachoSoto NachoSoto force-pushed the integration-test-consumable-purchase branch from de32618 to 61f6317 Compare October 7, 2022 18:32
@NachoSoto NachoSoto requested a review from tonidero October 7, 2022 18:32
@NachoSoto

Copy link
Copy Markdown
Contributor Author

This is ready for review now.

@NachoSoto NachoSoto requested a review from a team October 7, 2022 18:36
@NachoSoto NachoSoto force-pushed the integration-test-consumable-purchase branch from 61f6317 to fc37cd8 Compare October 7, 2022 18:38
@NachoSoto NachoSoto changed the title Purchasing: fixed consumable purchases by fixing transaction finishing Purchasing: fixed consumable purchases by fixing transaction-finishing Oct 7, 2022
@NachoSoto NachoSoto requested a review from aboedo October 7, 2022 18:54
self.customerInfoManager.cache(customerInfo: customerInfo, appUserID: appUserID)
completion?(transaction, customerInfo, nil, false)

self.finishTransactionIfNeeded(transaction)

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was out of order.

@NachoSoto NachoSoto force-pushed the either-queue-wrapper branch from 66d3982 to 0a7b5a6 Compare October 10, 2022 15:39

func testCanPurchaseConsumableMultipleTimes() async throws {
// See https://revenuecats.atlassian.net/browse/TRIAGE-134
try XCTSkipIf(Self.storeKit2Setting == .disabled, "This test is not currently passing on SK1")

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I filed [TRIAGE-136] for this.

@NachoSoto NachoSoto force-pushed the integration-test-consumable-purchase branch from fc37cd8 to 436be58 Compare October 10, 2022 15:49
Base automatically changed from either-queue-wrapper to main October 11, 2022 19:55
@NachoSoto NachoSoto force-pushed the integration-test-consumable-purchase branch from 436be58 to 1002300 Compare October 11, 2022 20:08
@NachoSoto NachoSoto merged commit 70365df into main Oct 11, 2022
@NachoSoto NachoSoto deleted the integration-test-consumable-purchase branch October 11, 2022 20:38
NachoSoto added a commit that referenced this pull request Nov 14, 2022
### Changes:
- Greatly increased test coverage for `StoreKit2TransactionListener`
- Extracted `AsyncSequence.extractValues`
- Created `MockStoreTransaction` to be able to mock and verify `finish()` calls
- Simplified `StoreKit2TransactionListener`, moved `finish` call to `PurchasesOrchestrator`
- Follow up to #1965, also finish SK2 transactions from `StoreKit.Transaction.updates`
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

pr:fix A bug fix

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Unable to buy the same Product twice in the same app session

2 participants