Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Purchasing: fixed consumable purchases by fixing transaction-finishing (
#1965) 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 `SKTestSession`s), this fixes the ability to purchase multiple consumable purchases. This is the log from the failing test using SK2: <details> <summary>Open</summary> ``` 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. ``` </details> With the fix, you can see transactions are now finished at the right time: <details> <summary>Open</summary> ``` 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' ``` </details> [TRIAGE-134]: https://revenuecats.atlassian.net/browse/TRIAGE-134?atlOrigin=eyJpIjoiNWRkNTljNzYxNjVmNDY3MDlhMDU5Y2ZhYzA5YTRkZjUiLCJwIjoiZ2l0aHViLWNvbS1KU1cifQ [TRIAGE-131]: https://revenuecats.atlassian.net/browse/TRIAGE-131?atlOrigin=eyJpIjoiNWRkNTljNzYxNjVmNDY3MDlhMDU5Y2ZhYzA5YTRkZjUiLCJwIjoiZ2l0aHViLWNvbS1KU1cifQ [TRIAGE-82]: https://revenuecats.atlassian.net/browse/TRIAGE-82?atlOrigin=eyJpIjoiNWRkNTljNzYxNjVmNDY3MDlhMDU5Y2ZhYzA5YTRkZjUiLCJwIjoiZ2l0aHViLWNvbS1KU1cifQ
- Loading branch information