概要

StoreKitTest を使った課金のユニットテストを回していると、たまに fail することがありました。
一見コードに誤りはなさそうなのになぜテストが失敗するのか、その原因を探ってみました。

たまに失敗するテストの例

というわけで、StoreKitTest を使った購入のテストを書いてみました。

以下、見やすいように少し編集しつつ、何をしているか説明します。

setUpWithError() で SKTestSession のインスタンスを作成します。
その後 .clearTransactions() を呼び出して前回のテストの transaction を消去し、.resetToDefaultState() を呼び出してプロパティの変更をクリアしています。

この 2つのメソッドは .tearDown() .tearDownWithError() で呼び出してもいいのですが、テストが fatalError() で終了した場合などに tearDown() 系のメソッドは呼ばれないことがあるため、万全を期して setUpWithError() に置いています。

    private var session: SKTestSession!

    override func setUpWithError() throws {
        session = try SKTestSession(configurationFileNamed: "Default")
        session.clearTransactions()
        session.resetToDefaultState()
        session.disableDialogs = true
    }

購入のテストケースは testPurchase() にまとめています。

PaymentTransactionObserver は SKPaymentTransactionObserver に準拠しつつ初期化時に渡されたクロージャを呼び出すように実装したクラスです。
MockSKProduct は SKProduct を継承したうえで、.storekit ファイルに定義されたプロダクトに合わせて各プロパティがいい感じの値を返すように実装したクラスです。

    func testPurchase() {
        let expectation = self.expectation(description: "SKPaymentTransaction with purchased state should be received")
        var transactionStates: [SKPaymentTransactionState] = []
        let paymentTransactionObserver = PaymentTransactionObserver { queue, transactions in
            for transaction in transactions {
                transactionStates.append(transaction.transactionState)
                switch transaction.transactionState {
                case .purchasing:
                    // 何度もテストしているとたまにここに到達しないことがある
                    break
                case .purchased:
                    // ここには必ず到達する
                    queue.finishTransaction(transaction)
                    expectation.fulfill()
                case .failed:
                    // ここに到達することはない
                    queue.finishTransaction(transaction)
                case .restored:
                    // ここに到達することはない
                    XCTFail("SKPaymentTransaction with restored state should not be received")
                case .deferred:
                    // ここに到達することはない
                    XCTFail("SKPaymentTransaction with deferred state should not be received")
                @unknown default:
                    // ここに到達することはない
                }
            }
        } removedTransactions: { queue, transactions in
            // 何度もテストしているとたまにここに到達することがある
        } restoreCompletedTransactionsFinished: { queue in
            // ここに到達することはない
            XCTFail(".restoreCompletedTransactionsFinished should not be called")
        }
        let product = MockSKProduct()
        let payment = SKPayment(product: product)
        let paymentQueue = SKPaymentQueue.default()
        paymentQueue.add(paymentTransactionObserver)
        paymentQueue.add(payment)
        waitForExpectations(timeout: 5) // ここで失敗することはない
        XCTAssertEqual(transactionStates, [.purchasing, .purchased]) // ここでたまに失敗する
    }

このテストケースのみを一度だけ実行した場合、私の環境では確実に成功します。
しかし、Xcode 13 の test repetition 機能を使って連続実行したり、複数のテストケースをまとめて実行したりすると、2回目以降は高確率で失敗してしまいます。

失敗した時のログは以下のようになっていました。

XCTAssertEqual failed: ("[purchased]") is not equal to ("[purchasing, purchased]")

通常購入時には purchasing purchased の順で SKPaymentTransaction.State が変化するはずですが、失敗時には purchasing にならず、最初から purchased になっており、テストが失敗するようです。

失敗の原因調査

StoreKitTest は StoreKit と同様、iOS で動作している appstored デーモンと NSXPCConnection で通信しています。
iOS シミュレータの appstored デーモンのログは Console.app や log コマンドで見ることができるので、ログを取りながらテスト失敗時の様子を観察してみます。

$ log stream --predicate 'subsystem == "com.apple.appstored" AND category CONTAINS "StoreKit"'
Filtering the log data using "subsystem == "com.apple.appstored" AND category CONTAINS "StoreKit""
Timestamp                       Thread     Type        Activity             PID    TTL
2021-12-19 16:30:04.804015+0900 0xe71a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] StoreKitServiceListener: Accepting new connection (StoreKitTestingExample) <NSXPCConnection: 0x60000321c000> connection from pid 2410 on mach service named com.apple.storekitservice
2021-12-19 16:30:04.804936+0900 0xe71a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] <StoreKitClient: 0x600002d2bf80>: Initializing client from bundle URL: file:///Users/rito/Library/Developer/CoreSimulator/Devices/B9583549-E37D-4567-A1AF-616D006196B6/data/Containers/Bundle/Application/4C59AD85-C89F-49CB-957F-285FAEB19697/StoreKitTestingExample.app/
2021-12-19 16:30:04.805941+0900 0xe71a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] <StoreKitClient: 0x600002d2bf80>: Client initialized with bundle ID com.github.manicmaniac.StoreKitTestingExample and request bundle ID com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.806184+0900 0xe71a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] com.github.manicmaniac.StoreKitTestingExample: Application has StoreKit testing enabled.
2021-12-19 16:30:04.812260+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [27DC8889] Entering -[StoreKitTestingService saveConfigurationData:forBundleID:completion:] for com.github.manicmaniac.StoreKitTestingExample by com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.815490+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [27DC8889] Exiting  -[StoreKitTestingService saveConfigurationData:forBundleID:completion:]
2021-12-19 16:30:04.816181+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [F5A27CD0] Entering -[StoreKitTestingService deleteAllTransactionsForBundleID:completion:] for com.github.manicmaniac.StoreKitTestingExample by com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.817547+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [F5A27CD0] Exiting  -[StoreKitTestingService deleteAllTransactionsForBundleID:completion:]
2021-12-19 16:30:04.818013+0900 0xe71a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [4DA96E40] Entering -[StoreKitTestingService removeTransactionIdentifiersFromCache:forBundleIdentifier:] for com.github.manicmaniac.StoreKitTestingExample by com.apple.ASOctaneSupportXPCService
2021-12-19 16:30:04.818424+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [E9C3C800] Entering -[StoreKitTestingService clearOverridesForBundleID:completion:] for com.github.manicmaniac.StoreKitTestingExample by com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.819024+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [E9C3C800] Exiting  -[StoreKitTestingService clearOverridesForBundleID:completion:]
2021-12-19 16:30:04.819688+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [A88B9052] Entering -[StoreKitTestingService setIntegerValue:forIdentifier:forBundleID:completion:] for com.github.manicmaniac.StoreKitTestingExample by com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.819906+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [A88B9052] Requested to set value 1 for identifier 2
2021-12-19 16:30:04.820411+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [A88B9052] Exiting  -[StoreKitTestingService setIntegerValue:forIdentifier:forBundleID:completion:]
2021-12-19 16:30:04.824209+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKUT:X:L/com.github.manicmaniac.StoreKitTestingExample/2C345125] Starting
 server purchase queue check
2021-12-19 16:30:04.824471+0900 0xe51a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] StoreKitServiceConnection(2410): Clearing all purchase intents for bundle identifier com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.825253+0900 0xe51a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] No revocations in database for DSID: 17322632127, bundleID: com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.826557+0900 0xe51a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] StoreKitServiceConnection(2410): [SKIAP:X:L/com.github.manicmaniac.StoreKitTestingExample/70FFCD18] Adding payment for com.example.auto-renewable and quantity 1
2021-12-19 16:30:04.871081+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKUT:X:L/com.github.manicmaniac.StoreKitTestingExample/2C345125] Found 0 transactions in pending queue
2021-12-19 16:30:04.881785+0900 0xe51a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKIAP:X:L/com.github.manicmaniac.StoreKitTestingExample/70FFCD18] Running payment for com.example.auto-renewable
2021-12-19 16:30:04.939042+0900 0xe51a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKIAP:X:L/com.github.manicmaniac.StoreKitTestingExample/70FFCD18] Payment complete
2021-12-19 16:30:04.943925+0900 0xe51a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKIAP:X:L/com.github.manicmaniac.StoreKitTestingExample/70FFCD18] 1 transactions in response
2021-12-19 16:30:04.950314+0900 0xe51a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKIAP:X:L/com.github.manicmaniac.StoreKitTestingExample/70FFCD18]: Found 1 products in receipt with ID com.example.auto-renewable
2021-12-19 16:30:04.958844+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [864A202D] Entering -[StoreKitTestingService saveConfigurationData:forBundleID:completion:] for com.github.manicmaniac.StoreKitTestingExample by com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.961231+0900 0xe51a     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKFT:X:L/com.github.manicmaniac.StoreKitTestingExample/CDFFFCB6] Finishing transaction 915 for com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.963495+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [864A202D] Exiting  -[StoreKitTestingService saveConfigurationData:forBundleID:completion:]
2021-12-19 16:30:04.965177+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [AA0F6CE0] Entering -[StoreKitTestingService deleteAllTransactionsForBundleID:completion:] for com.github.manicmaniac.StoreKitTestingExample by com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.967992+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [AA0F6CE0] Exiting  -[StoreKitTestingService deleteAllTransactionsForBundleID:completion:]
2021-12-19 16:30:04.968917+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [3CF5381B] Entering -[StoreKitTestingService removeTransactionIdentifiersFromCache:forBundleIdentifier:] for com.github.manicmaniac.StoreKitTestingExample by com.apple.ASOctaneSupportXPCService
2021-12-19 16:30:04.969236+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [E7D49B82] Entering -[StoreKitTestingService clearOverridesForBundleID:completion:] for com.github.manicmaniac.StoreKitTestingExample by com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.970081+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [E7D49B82] Exiting  -[StoreKitTestingService clearOverridesForBundleID:completion:]
2021-12-19 16:30:04.971056+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [4EAB29F3] Entering -[StoreKitTestingService setIntegerValue:forIdentifier:forBundleID:completion:] for com.github.manicmaniac.StoreKitTestingExample by com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:04.971580+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [4EAB29F3] Requested to set value 1 for identifier 2
2021-12-19 16:30:04.972235+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [4EAB29F3] Exiting  -[StoreKitTestingService setIntegerValue:forIdentifier:forBundleID:completion:]
2021-12-19 16:30:04.975538+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKitInXcode] [126C2554] Entering -[StoreKitTestingService revokeEntitlementsForProductIdentifiers:forBundleId:completion:] for com.github.manicmaniac.StoreKitTestingExample by com.apple.ASOctaneSupportXPCService
2021-12-19 16:30:04.976775+0900 0xe861     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] StoreKitServiceConnection(2410): renewing receipt for com.github.manicmaniac.StoreKitTestingExample with options: (null)
2021-12-19 16:30:04.978321+0900 0xe93c     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKFT:X:L/com.github.manicmaniac.StoreKitTestingExample/713BAC39] Finishing transaction 915 for com.github.manicmaniac.StoreKitTestingExample
2021-12-19 16:30:05.055576+0900 0xe51a     Error       0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKFT:X:L/com.github.manicmaniac.StoreKitTestingExample/CDFFFCB6] Error finishing payment 915 for com.github.manicmaniac.StoreKitTestingExample - Error Domain=AMSErrorDomain Code=301 "Invalid Status Code" UserInfo={NSLocalizedFailureReason=The response has an invalid status code, AMSURL=http://localhost:49402/WebObjects/MZFinance.woa/wa/inAppTransactionDone?REDACTED, AMSStatusCode=404, AMSServerPayload={
    error = "Transaction not found";
}, NSLocalizedDescription=Invalid Status Code}
2021-12-19 16:30:05.071178+0900 0xe93c     Error       0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKFT:X:L/com.github.manicmaniac.StoreKitTestingExample/713BAC39] Error finishing payment 915 for com.github.manicmaniac.StoreKitTestingExample - Error Domain=AMSErrorDomain Code=301 "Invalid Status Code" UserInfo={NSLocalizedFailureReason=The response has an invalid status code, AMSURL=http://localhost:49402/WebObjects/MZFinance.woa/wa/inAppTransactionDone?REDACTED, AMSStatusCode=404, AMSServerPayload={
    error = "Transaction not found";
}, NSLocalizedDescription=Invalid Status Code}
2021-12-19 16:30:05.470320+0900 0xe822     Default     0x0                  1253   0    appstored: [com.apple.appstored:StoreKit] [SKSS:X:C/com.github.manicmaniac.StoreKitTestingExample/05DDF19D] Ignoring subscription status sync from push notification for com.github.manicmaniac.StoreKitTestingExample since the app has not queried status

最後の数行で Error finishing payment やら Transaction not found などのエラーログが出ていることがわかります。

なんとなく、SKPaymentQueue.finishTransaction(_:) の処理に関係がありそうです。

`SKPaymentQueue.finishTransaction(_:)` の処理を調べる

というわけで、StoreKit の実体 (/Applications/Xcode.app/Contents/Developer/Platforms/iPhoneOS.platform/Library/Developer/CoreSimulator/Profiles/Runtimes/iOS.simruntime/Contents/Resources/RuntimeRoot/System/Library/Frameworks/StoreKit.framework/StoreKit) をディスアセンブルして挙動を調べてみます。
いろいろ方法がありますが、今回は Hopper Disassembler を使って解析します。

さすがに商用ソフトウェアをディスアセンブルした結果をそのまま載せるのは法的に問題がありそうなので、一部の主要な処理だけを読みやすく加工して載せると、以下のような Objective-C コードになっています。

- (id)finishTransaction:(id)transaction {
    ...
    id service = [[SKServiceBroker defaultBroker] asdStoreKitServiceWithErrorHandler:^{
        ...
    }];
    ...
    [service finishPaymentWithIdentifier:[transaction transactionIdentifier] reply:^{
        ...
    }];
}

ここに出てくる [SKServiceBroker asdStoreKitServiceWithErrorHandler:] についてさらに解析すると、だいたい以下のような実装になっています。
返り値の型は Xcode 付属の LLDB でこのメソッドにシンボリックブレークポイントを打つとわかります。

- (__NSXPCInterfaceProxy_ASDStoreKitServiceProtocol *)asdStoreKitServiceWithErrorHandler:(id)errorHandler {
    ...
    return [[self _serviceConnection] remoteObjectProxyWithErrorHandler:errorHandler];
}

[NSXPCConnection remoteObjectProxyWithErrorHandler:] が呼び出されているのがわかります。
これは非同期に実行されるメソッドで、別プロセスのメソッドを mach IPC 経由で呼び出して結果をコールバックで受け取るようになっています。
ここでは [service finishPaymentWithIdentifier:reply:] が別プロセスのメソッドで、実際にこのメソッドは StoreKit には存在せず、appstored 内に定義されています。

同期で実行される [NSXPCConnection synchronousRemoteObjectProxyWithErrorHandler:] もありますが、[SKPaymentQueue finishTransaction:] では非同期の方を呼び出しています。
ということは、この [SKPaymentQueue finishTransaction:] はスレッドをブロックせずにすぐに呼び出し元に制御を返す実装になっていることがわかります。
実際に実機で購入するときは appstored を通してインターネット上の AppStore と通信するでしょうから、これが同期呼び出しでないことは納得できます。

仮説

というわけで、テストを連続実行するとき、以下のようなことがプログラム内部で起こっていると考えられます。

テストケース A で購入トランザクションαを開始する
テストケース A で購入トランザクションαを終了する ([SKPaymentQueue finishTransaction:] を呼ぶ)
無事購入できたので、テストケース A が成功裡に終了する
テストケース B が全てのトランザクションを削除する ([SKTestSession clearTransactions] を呼ぶ)
テストケース B が購入トランザクションβを開始する
appstored がまだ購入トランザクションαを終了できていないので purchased トランザクションが [SKPaymentTransactionObserver updatedTransactions:] に入ってしまう
テストケース B が予期しない purchased トランザクションを受け取り失敗する
appstored がようやく購入トランザクションαを終了するが、すでに [SKTestSession clearTransactions] が呼ばれているためエラーになる

4 の時点で [SKTestSession clearTransactions] が呼ばれているのに購入トランザクションαが残っている理由は調べましたがよくわかりませんでした。
なお、[SKTestSession clearTransactions] は内部的には [NSXPCConnection synchronousRemoteObjectProxyWithErrorHandler:] を呼んでいるので、[SKPaymentQueue finishTransaction:] と異なり同期的に完了しています。

なんとなく [SKPaymentQueue finishTransaction:] を呼ぶと当該のトランザクションのロックを取得し、処理が完了するまでの間 [SKTestSession clearTransactions] で消せなくなる、みたいな実装なのではないかと想像していますが、もし詳しい方がいたら教えていただきたいです。

対策

[SKPaymentQueue finishTransaction:] の完了まで待ってから次のテストケースを実行するようにすれば問題なさそうです。
残念ながら [SKPaymentQueue finishTransaction:] の完了を受け取る公開 API は用意されていないので、適当にウェイトを入れればよさそうです。

ログを見ている感じだと大体 0.2秒ほどあればリモートオブジェクト側での処理も完了していそうなので、適当に 0.25 秒としてみました。心配なら倍の 0.5秒くらい待てばよさそうです。

queue.finishTransaction(transaction)
RunLoop.main.run(until: Date(timeIntervalSinceNow: 0.25))

単に Thread.sleep() でもいいかもしれませんが、RunLoop を回しておかないとイベントの取りこぼしが発生してしまうのでそのようにしています。

実際には [SKPaymentQueue finishTransaction:] はプロダクト側のコードに書かれていてウェイトすることが許容できない場合も多いと思うので、その場合は setUp() などで RunLoop を空転させると良いと思います。

以上の対策を施したところ、テストにかかる時間は延びてしまいましたが、無事テストが100回中100回パスするようになりました。

この挙動についてはちょっと罠っぽいのと、そもそも使い方が間違っている可能性もあるかもしれないですが、一応調査した結果を Apple のバグトラッカーである Feedback Assistant に投げています (FB9814502)。

2022-08-17 追記: その後しばらく間が開きましたが、FB9814502 について Apple から返信があり、iOS 16 beta 5 で動作確認してほしい旨の依頼が届きました。残念ながら今すぐ iOS beta を入れられる端末が手元に用意できないのですぐに確認はできませんが、ひとまずこの挙動については Apple 側でも対応する姿勢がありそうです。

概要

たまに失敗するテストの例

失敗の原因調査

SKPaymentQueue.finishTransaction(_:) の処理を調べる

仮説

対策

`SKPaymentQueue.finishTransaction(_:)` の処理を調べる