iPadOS 15 running app from Xcode fails to return any products. Restore Purchases also fails to return.
Rebooting iPad allows it to work first time only.
This issue is specifically relating to auto-renewing subscriptions.
Built using Xcode Version 13.0 (13A233)
No issue with same code on iOS 14.
Success and failure logs follow.
Success:
2021-09-24 16:17:50.773181+0800 ZeroTime[345:4478] [Purchases] - DEBUG: ℹ️ Debug logging enabled
2021-09-24 16:17:50.773293+0800 ZeroTime[345:4478] [Purchases] - DEBUG: ℹ️ SDK Version - 3.12.4
2021-09-24 16:17:50.773336+0800 ZeroTime[345:4478] [Purchases] - DEBUG: 👤 Initial App User ID - (null)
2021-09-24 16:17:50.777445+0800 ZeroTime[345:4478] [Purchases] - DEBUG: ℹ️ Sending latest PurchaserInfo to delegate.
2021-09-24 16:17:50.778858+0800 ZeroTime[345:4478] didReceiveUpdatedPurchaserInfo: <PurchaserInfo
originalApplicationVersion: (null),
latestExpirationDate: (null)
activeEntitlements: {
},
activeSubscriptions: {
},
nonConsumablePurchases: {(
)},
requestDate: 2021-09-24 08:12:16 +0000
firstSeen: 2021-09-24 08:12:16 +0000,
originalAppUserId: $RCAnonymousID:cada631d501147efa13dd3dd44741b9c,
entitlements: {
},
> {
originalAppUserId = "$RCAnonymousID:cada631d501147efa13dd3dd44741b9c";
willRenew = No;
}
2021-09-24 16:17:50.778946+0800 ZeroTime[345:4478] [Purchases] - DEBUG: ℹ️ Delegate set
2021-09-24 16:17:51.070276+0800 ZeroTime[345:4478] [Purchases] - DEBUG: ℹ️ Vending PurchaserInfo from cache.
2021-09-24 16:17:51.070546+0800 ZeroTime[345:4478] purchaserInfo: <PurchaserInfo
originalApplicationVersion: (null),
latestExpirationDate: (null)
activeEntitlements: {
},
activeSubscriptions: {
},
nonConsumablePurchases: {(
)},
requestDate: 2021-09-24 08:12:16 +0000
firstSeen: 2021-09-24 08:12:16 +0000,
originalAppUserId: $RCAnonymousID:cada631d501147efa13dd3dd44741b9c,
entitlements: {
},
>
2021-09-24 16:17:51.070670+0800 ZeroTime[345:4478] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2021-09-24 16:17:51.079287+0800 ZeroTime[345:4655] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c
2021-09-24 16:17:51.079500+0800 ZeroTime[345:4655] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c
2021-09-24 16:17:51.081741+0800 ZeroTime[345:4655] [Purchases] - DEBUG: ℹ️ There's a request currently running and 0 requests left in the queue, queueing GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings
2021-09-24 16:17:52.576457+0800 ZeroTime[345:4653] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c 304
2021-09-24 16:17:52.580989+0800 ZeroTime[345:4653] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c, 1 requests left in the queue
2021-09-24 16:17:52.581240+0800 ZeroTime[345:4653] [Purchases] - DEBUG: ℹ️ Starting the next request in the queue, <RCHTTPRequest: httpMethod=GET
path=/subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings
requestBody=(null)
headers={
Authorization = "Bearer vXpx...";
}
retried=0
>
2021-09-24 16:17:52.582667+0800 ZeroTime[345:4653] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings
2021-09-24 16:17:52.582820+0800 ZeroTime[345:4653] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c/offerings
2021-09-24 16:17:52.993356+0800 ZeroTime[345:4652] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c/offerings 304
2021-09-24 16:17:52.994226+0800 ZeroTime[345:4652] [Purchases] - DEBUG: ℹ️ Requesting products from the store with identifiers: {(
"io.smudge.ZeroTime.SUB.Yearly",
"io.smudge.ZeroTime.SUB.Monthly"
)}
2021-09-24 16:17:52.998017+0800 ZeroTime[345:4652] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings, 0 requests left in the queue
2021-09-24 16:17:53.062085+0800 ZeroTime[345:4652] [Purchases] - DEBUG: ℹ️ Products request finished.
2021-09-24 16:17:53.062174+0800 ZeroTime[345:4652] [Purchases] - DEBUG: 💰 Retrieved SKProducts:
2021-09-24 16:17:53.062242+0800 ZeroTime[345:4652] [Purchases] - DEBUG: 💰 io.smudge.ZeroTime.SUB.Monthly - <SKProduct: 0x283cbdc10>
2021-09-24 16:17:53.062297+0800 ZeroTime[345:4652] [Purchases] - DEBUG: 💰 io.smudge.ZeroTime.SUB.Yearly - <SKProduct: 0x283cbd820>
2021-09-24 16:17:53.062345+0800 ZeroTime[345:4652] [Purchases] - DEBUG: ℹ️ 1 completion handlers waiting on products
2021-09-24 16:17:58.074549+0800 ZeroTime[345:4478] [Purchases] - DEBUG: ℹ️ Vending Offerings from cache
Failure:
2021-09-24 16:13:05.996820+0800 ZeroTime[503:10344] [Purchases] - DEBUG: ℹ️ Debug logging enabled
2021-09-24 16:13:05.996935+0800 ZeroTime[503:10344] [Purchases] - DEBUG: ℹ️ SDK Version - 3.12.4
2021-09-24 16:13:05.996978+0800 ZeroTime[503:10344] [Purchases] - DEBUG: 👤 Initial App User ID - (null)
2021-09-24 16:13:06.000895+0800 ZeroTime[503:10344] [Purchases] - DEBUG: ℹ️ Sending latest PurchaserInfo to delegate.
2021-09-24 16:13:06.001788+0800 ZeroTime[503:10344] didReceiveUpdatedPurchaserInfo: <PurchaserInfo
originalApplicationVersion: (null),
latestExpirationDate: (null)
activeEntitlements: {
},
activeSubscriptions: {
},
nonConsumablePurchases: {(
)},
requestDate: 2021-09-24 08:12:16 +0000
firstSeen: 2021-09-24 08:12:16 +0000,
originalAppUserId: $RCAnonymousID:cada631d501147efa13dd3dd44741b9c,
entitlements: {
},
> {
originalAppUserId = "$RCAnonymousID:cada631d501147efa13dd3dd44741b9c";
willRenew = No;
}
2021-09-24 16:13:06.001865+0800 ZeroTime[503:10344] [Purchases] - DEBUG: ℹ️ Delegate set
2021-09-24 16:13:06.280716+0800 ZeroTime[503:10344] [Purchases] - DEBUG: ℹ️ Vending PurchaserInfo from cache.
2021-09-24 16:13:06.280911+0800 ZeroTime[503:10344] purchaserInfo: <PurchaserInfo
originalApplicationVersion: (null),
latestExpirationDate: (null)
activeEntitlements: {
},
activeSubscriptions: {
},
nonConsumablePurchases: {(
)},
requestDate: 2021-09-24 08:12:16 +0000
firstSeen: 2021-09-24 08:12:16 +0000,
originalAppUserId: $RCAnonymousID:cada631d501147efa13dd3dd44741b9c,
entitlements: {
},
>
2021-09-24 16:13:06.281064+0800 ZeroTime[503:10344] [Purchases] - DEBUG: ℹ️ applicationDidBecomeActive
2021-09-24 16:13:06.287826+0800 ZeroTime[503:10402] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c
2021-09-24 16:13:06.287919+0800 ZeroTime[503:10402] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c
2021-09-24 16:13:06.290863+0800 ZeroTime[503:10402] [Purchases] - DEBUG: ℹ️ There's a request currently running and 0 requests left in the queue, queueing GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings
2021-09-24 16:13:07.702613+0800 ZeroTime[503:10399] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c 304
2021-09-24 16:13:07.705077+0800 ZeroTime[503:10399] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c, 1 requests left in the queue
2021-09-24 16:13:07.705201+0800 ZeroTime[503:10399] [Purchases] - DEBUG: ℹ️ Starting the next request in the queue, <RCHTTPRequest: httpMethod=GET
path=/subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings
requestBody=(null)
headers={
Authorization = "Bearer vXpx...";
}
retried=0
>
2021-09-24 16:13:07.706122+0800 ZeroTime[503:10399] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings
2021-09-24 16:13:07.706187+0800 ZeroTime[503:10399] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c/offerings
2021-09-24 16:13:08.111173+0800 ZeroTime[503:10422] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c/offerings 304
2021-09-24 16:13:08.111475+0800 ZeroTime[503:10422] [Purchases] - DEBUG: ℹ️ Requesting products from the store with identifiers: {(
"io.smudge.ZeroTime.SUB.Yearly",
"io.smudge.ZeroTime.SUB.Monthly"
)}
2021-09-24 16:13:08.111900+0800 ZeroTime[503:10422] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings, 0 requests left in the queue
2021-09-24 16:13:12.926935+0800 ZeroTime[503:10344] [Purchases] - DEBUG: ℹ️ No cached Offerings, fetching from network
2021-09-24 16:13:12.963155+0800 ZeroTime[503:10422] [Purchases] - DEBUG: ℹ️ There are no requests currently running, starting request GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings
2021-09-24 16:13:12.963257+0800 ZeroTime[503:10422] [Purchases] - DEBUG: ℹ️ API request started: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c/offerings
2021-09-24 16:13:13.334771+0800 ZeroTime[503:10422] [Purchases] - DEBUG: ℹ️ API request completed with status: GET /v1/subscribers/$RCAnonymousID:cada631d501147efa13dd3dd44741b9c/offerings 304
2021-09-24 16:13:13.335316+0800 ZeroTime[503:10422] [Purchases] - DEBUG: ℹ️ Serial request done: GET /subscribers/$RCAnonymousID0X0P+0cada631d501147efa13dd3dd44741b9c/offerings, 0 requests left in the queue