Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 4 commits into from
Oct 11, 2022

Conversation

NachoSoto
Copy link
Contributor

@NachoSoto NachoSoto commented Oct 6, 2022

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'

Copy link
Contributor

@tonidero tonidero left a comment

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.

@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
Copy link
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.finishTransactionIfNeeded(transaction)
Copy link
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.


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
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