Discover readers is stuck when the user cancels Tap to Pay terms of service screen

marcin-mucha commented 1 year ago

Summary

When a user connects to the local reader for the first time they are presented Terms of Condition screen that user can cancel. However, for this scenario completion handler for discoverReaders is never called. Any subsequent attempt to call discoverReaders results in:

Error Domain=com.stripe-terminal Code=1000 "Could not execute discoverReaders because the SDK is busy with another command: discoverReaders." UserInfo={NSLocalizedDescription=Could not execute discoverReaders because the SDK is busy with another command: discoverReaders., com.stripe-terminal:Message=Could not execute discoverReaders because the SDK is busy with another command: discoverReaders.}

If I try to cancel discovery using the cancelable (after didUpdateDiscoveredReaders is called), I'm getting:

Error Domain=com.stripe-terminal Code=5000 "An unexpected SDK error occurred." UserInfo={com.stripe-terminal:InternalErrorCode=5100, NSLocalizedDescription=An unexpected SDK error occurred., com.stripe-terminal:Message=An unexpected SDK error occurred.}

How can I allow the user to rediscover the reader in that case? Or should I not try?
What if user changes his mind and wants to use card reader instead of tap to pay? I need to rediscover the readers in that case, which is not possible, because SDK is busy.

Code to reproduce

iOS version

16.5.1

Installation method

SPM

SDK version

2.21.0

Other information

bric-stripe commented 1 year ago

Hi, this sounds like an SDK bug. You should never see that unexpected SDK error. But I haven't been able to reproduce.

How can I allow the user to rediscover the reader in that case? Or should I not try?

after the connect fails, didUpdateDiscoveredReaders should be called again with the same reader re-discovered and should be able to be attempted to be connected to. This is because the discoverReaders resumes discovery after the connect fails.

What if user changes his mind and wants to use card reader instead of tap to pay? I need to rediscover the readers in that case, which is not possible, because SDK is busy.

that's when you'd need to cancel the discover reader's cancelable first.

But if you're hitting "An unexpected SDK error occurred" something else is off. So want to try to debug that.

Can you confirm you're waiting for the discover cancelable to call its completion block before attempting to start the next discovery? (even if you're not, you should be getting a better error message)
could you provide more detailed logs? If not already you may need to setup the Terminal.setLogListener. Or if you can provide the reader's reader.serialNumber. With that I should be able to pull up some more logs and can try to make sense of the issue from that.

marcin-mucha commented 1 year ago

Yes, I'm waiting for cancellable to finish:

    do {
      try await discoverCancelable?.cancel()
    } catch {
      Self.logger.debug("Cancellation failed.")
    }

The following unexpected SDK error happens if I try to cancel discovery after didUpdateDiscoveredReaders is called and before I call connectLocalMobileReader:

2023-07-05 22:10:11.629791+0200 Housecall Pro[28557:2168465] [TapToPayConnectionMediator] s scope=SCPTerminal event=connectReader_start logpoint_level=info app_id=com.codefied.HouseCallPro.stage command=connectReader device_type=Apple_Built-In last_request_id=req_HLXqN5MxEgpLhC multiple_readers_connected=false sdk_version=2.21.0 serial_number=5f69eab8e4b3d2d57fae68df942b6f4b896df67cfc3f242e37241b39573c080e time=1688587811621
2023-07-05 22:10:11.634520+0200 Housecall Pro[28557:2168465] [TapToPayConnectionMediator] l scope=SCPTerminal event=unexpected_state logpoint_level=warning app_id=com.codefied.HouseCallPro.stage last_request_id=req_HLXqN5MxEgpLhC sdk_version=2.21.0 time=1688587811630 unexpected_nil=reader.adapter
2023-07-05 22:10:11.636424+0200 Housecall Pro[28557:2167949] [TapToPayConnectionMediator] connectLocalMobileReader failed: Error Domain=com.stripe-terminal Code=5000 "An unexpected SDK error occurred." UserInfo={com.stripe-terminal:InternalErrorCode=5100, NSLocalizedDescription=An unexpected SDK error occurred., com.stripe-terminal:Message=An unexpected SDK error occurred.}

When I try different approach:

User cancels T&C screen, connection fails with error (as expected):

2023-07-05 22:16:13.306095+0200 Housecall Pro[28604:2171622] [TapToPayConnectionMediator] l scope=SCPAppleBuiltInReaderLinkOp event=unexpected_state logpoint_level=warning account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage error=Error_that_indicates_the_user_canceled_the_linking_operation error_code=24 error_domain=SCPAppleBuiltInReaderErrorDomain error_variant_name=AccountLinkingCancelled last_request_id=req_f69TSIHIpi2g4r reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1688588173291

User wants to try it again, taps the button to re-discover: I call:

do {
  try await discoverCancelable?.cancel()
} catch {
  Self.logger.debug("Cancellation failed.")
}

before I start the next discovery, but that next discovery fails anyway with error:

2023-07-05 22:16:27.670507+0200 Housecall Pro[28604:2171970] [TapToPayConnectionMediator] x scope=scpterminal event=discoverreaders domain=terminal_request outcome=success time=1688588187670
2023-07-05 22:16:27.752125+0200 Housecall Pro[28604:2171107] [TapToPayConnectionMediator] Local reader discovery failed with: Error Domain=com.stripe-terminal Code=1000 "Could not execute discoverReaders because the SDK is busy with another command: discoverReaders." UserInfo={NSLocalizedDescription=Could not execute discoverReaders because the SDK is busy with another command: discoverReaders., com.stripe-terminal:Message=Could not execute discoverReaders because the SDK is busy with another command: discoverReaders.}
2023-07-05 22:16:27.756598+0200 Housecall Pro[28604:2171809] [TapToPayConnectionMediator] e scope=SCPTerminal event=discoverReaders logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage error=Could_not_execute_discoverReaders_because_the_SDK_is_busy_with_another_command__discoverReaders error_code=1000 error_domain=com.stripe-terminal exception=INTEGRATION_ERROR.Busy last_request_id=req_f69TSIHIpi2g4r reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1688588187753 total_time_ms=116

bric-stripe commented 1 year ago

The following unexpected SDK error happens if I try to cancel discovery after didUpdateDiscoveredReaders is called and before I call connectLocalMobileReader

ack, thanks for the additional details. We'll fix up that error handling. If I understand correctly the error returned should be that discoverReaders must be running in order to attempt to connect to the reader.

before I start the next discovery, but that next discovery fails anyway with error:

ah, I missed this originally 😞 Unfortunately[^1] the source of truth for when the current running discoverReaders command is still running or not is the completion block for the original discoverReaders call. Until that is triggered the SDK will report BUSY, even if the cancelable's cancel has completed. Ideally if the cancelable's cancel succeeds the SDK should be ready for another command but that's not currently the case and instead the command's completion block is the current source of truth. This is something we plan to fix up but I don't have any dates to share or anything.

So for now before restarting discoverReaders you'll need to wait for the first discoverReaders completion to be run and then it should work without hitting the BUSY error.

[^1]: Unfortunate because we realize this requires more state management on the integration side and can be annoying.

marcin-mucha commented 1 year ago

I see, thanks for clarification. I have a followup question though.

you'll need to wait for the first discoverReaders completion to be run and then it should work without hitting the BUSY error.

How do I know when first discoverReaders completion happens in case the connection fails? Is there any internal timeout? What if user decides to use external card reader and I need to rediscover devices?

bric-stripe commented 1 year ago

How do I know when first discoverReaders completion happens in case the connection fails

when the connection fails the discoverReaders will still be running. You'll separately need to cancel the discoverReaders cancelable which will then trigger the discoverReaders completion to be called.

Is there any internal timeout?

no, not for local mobile. The discoverReaders will continue running until canceled or connecting to a reader succeeds.

What if user decides to use external card reader and I need to rediscover devices?

you should cancel the discoverReaders cancelable, wait for the discoverReaders completion to call and then restart discoverReaders with the updated configuration. This is the annoying part because you may need to communicate state that the discoverReaders completion has access to such that it knows it should restart a discover. The Example app can be referenced to see how this is managed there. But in that case it implicitly relies on the discoverReaders completion happening shortly after the cancel completion and because it dismisses/presents the discover view controller that takes the time needed for that.

We can't commit to anything at this point but want to give a heads up that we're re-evaluating some of this behavior for a future breaking change release. One of the items we're considering is having discoverReaders complete when connect*Reader is called to reduce some of this complexity and state tracking. This would also match how the Android SDK currently works.

marcin-mucha commented 1 year ago

@bric-stripe based on your suggestion I tried the following approach: 1) User discovers the local reader and Terms of Service screen is presented by the SDK. 2) Users dismisses (Cancel button) Terms of Service screen without configuring Apple ID. 3) I cancel the discovery cancellable and logs confirm it worked:

2023-07-10 17:45:01.482018+0200 Housecall Pro[2161:134443] [TapToPayConnectionMediator] t scope=SCPCancelable event=cancel logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage command=discoverReaders completed=0 last_request_id=req_W4Nm3qG5QeoM9J reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1689003901472

4) I wait a couple of seconds, not interacting with the phone. 5) I tap the button to discoverReaders (no BUSY error this time), but Terms of Service are never presented. Nothing happens, it's stuck. I just have the log:

2023-07-10 17:46:16.931663+0200 Housecall Pro[2161:133707] [TapToPayConnectionMediator] m Stripe trace identifier: discoverReaders!383381708700001689003976932
2023-07-10 17:46:16.943546+0200 Housecall Pro[2161:134449] [TapToPayConnectionMediator] s scope=SCPTerminal event=discoverReaders_start logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage command=discoverReaders discovery_method=Local_Mobile last_request_id=req_W4Nm3qG5QeoM9J multiple_readers_connected=false reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1689003976932
2023-07-10 17:46:16.951480+0200 Housecall Pro[2161:135029] [TapToPayConnectionMediator] t scope=SCPTerminal event=state_change logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage command_in_progress=discoverReaders last_request_id=req_W4Nm3qG5QeoM9J reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1689003976946
2023-07-10 17:46:16.955866+0200 Housecall Pro[2161:135029] [TapToPayConnectionMediator] t scope=SCPAppleBuiltInReaderAdapter event=discoverReaders_cancelable logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage last_request_id=req_W4Nm3qG5QeoM9J reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1689003976952
2023-07-10 17:46:16.959458+0200 Housecall Pro[2161:134860] [TapToPayConnectionMediator] t scope=SCPConnectionTokenManager event=requestToken logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage last_request_id=req_W4Nm3qG5QeoM9J reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1689003976956
2023-07-10 17:46:16.959739+0200 Housecall Pro[2161:135029] [ProximityReader] User cancelled
2023-07-10 17:46:16.968984+0200 Housecall Pro[2161:135029] [TapToPayConnectionMediator] t scope=SCPConnectionTokenManager event=requestToken logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage last_request_id=req_W4Nm3qG5QeoM9J reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1689003976967
2023-07-10 17:46:16.975405+0200 Housecall Pro[2161:135029] [TapToPayConnectionMediator] t scope=SCPAPIRequest event=api_request_post logpoint_level=info account=acct_15ur9bECzMAZB5JJ api_endpoint=terminal.readers.discover app_id=com.codefied.HouseCallPro.stage last_request_id=req_W4Nm3qG5QeoM9J reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1689003976971
2023-07-10 17:46:17.387192+0200 Housecall Pro[2161:134860] [TapToPayConnectionMediator] t scope=SCPAPIRequest event=api_response_success logpoint_level=info account=acct_15ur9bECzMAZB5JJ api_endpoint=terminal.readers.discover app_id=com.codefied.HouseCallPro.stage http_method=POST http_status_code=200 last_request_id=req_UY0NXj9hqFqPC7 reader=tmr_FKCfdwJ7Rnu1aH request_id=req_UY0NXj9hqFqPC7 sdk_version=2.21.0 time=1689003977374
2023-07-10 17:46:17.388800+0200 Housecall Pro[2161:134860] [TapToPayConnectionMediator] x scope=scpterminal event=post_terminal_readers_discover domain=api_request outcome=http_status_code_200 time=1689003977388
2023-07-10 17:46:17.404590+0200 Housecall Pro[2161:134860] [TapToPayConnectionMediator] t scope=SCPStripeAPIClientRouter event=shouldRetryWithOfflineClientForError_allowNilReader_reader logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage last_request_id=req_UY0NXj9hqFqPC7 reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1689003977388
2023-07-10 17:46:17.404726+0200 Housecall Pro[2161:134860] [TapToPayConnectionMediator] t scope=SCPReaderDiscoveryController event=requestLocationsForReaders logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage last_request_id=req_UY0NXj9hqFqPC7 reader=tmr_FKCfdwJ7Rnu1aH request_time_ms=427.1479845046997 sdk_version=2.21.0 time=1689003977394
2023-07-10 17:46:17.404810+0200 Housecall Pro[2161:134860] [TapToPayConnectionMediator] t scope=SCPTerminal event=updateDiscoveredReaders_forAdapter logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage last_request_id=req_UY0NXj9hqFqPC7 reader=tmr_FKCfdwJ7Rnu1aH sdk_version=2.21.0 time=1689003977399
2023-07-10 17:46:17.406314+0200 Housecall Pro[2161:134860] [TapToPayConnectionMediator] t scope=SCPTerminal event=updateDiscoveredReaders_forAdapter logpoint_level=info account=acct_15ur9bECzMAZB5JJ app_id=com.codefied.HouseCallPro.stage last_request_id=req_UY0NXj9hqFqPC7 reader=tmr_FKCfdwJ7Rnu1aH reader_count=1 reader_filter_count=1 readers=5f69eab8e4b3d2d57fae68df942b6f4b896df67cfc3f242e37241b39573c080e_unknown sdk_version=2.21.0 time=1689003977402

bric-stripe commented 1 year ago

thanks for the logs

I tap the button to discoverReaders (no BUSY error this time), but Terms of Service are never presented

from looking at the logs that all looks like a successfully running discoverReaders but then once the reader is re-announced in didUpdateDiscoveredReaders... you should just need to call connectLocalMobileReader... with the discovered reader and that should re-present the ToS UI.

marcin-mucha commented 1 year ago

Thanks, we managed to workaround it the way you proposed. As you said, such state management on the integration side can be annoying. This is less than ideal for us as this kind of logic is a bit fragile to potential changes, especially having in mind that we would like to rework our payment flow and start discovering/connecting to the card reader and TTP in a different part of the user flow.

We can't commit to anything at this point but want to give a heads up that we're re-evaluating some of this behavior for a future breaking change release. One of the items we're considering is having discoverReaders complete when connect*Reader is called to reduce some of this complexity and state tracking.

It would be highly appreciated as this sounds like an easy way of avoiding discoverReaders busy error. It would be a great step forward when it comes how convenient it is to integrate the SDK and make changes to such code later.

bric-stripe commented 1 year ago

It would be highly appreciated as this sounds like an easy way of avoiding discoverReaders busy error. It would be a great step forward when it comes how convenient it is to integrate the SDK and make changes to such code later.

I can confirm now this behavior change is scheduled to ship in early September as part of our 3.0 update. We also removed SCPErrorBusy and will queue incoming commands if another command is running (this matches how the Terminal Android SDK behaves), which should also help with some sometimes tricky coordinating of requests for other cases.

bric-stripe commented 1 year ago

@marcin-mucha SDK 3.0.0 is available now and has the queueing logic I mentioned which should help out here. I'm going to close this out but please re-open if you update to 3.0 and still have issues.

stripe / stripe-terminal-ios