Instrument Swift checkout failures #675
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -1,4 +1,5 @@ | ||
| #if !COCOAPODS | ||
| import CheckoutKitTelemetry | ||
| import EmbeddedCheckoutProtocol | ||
| #endif | ||
| import SafariServices | ||
|
|
@@ -202,6 +203,15 @@ final class PreloadCache { | |
| } | ||
|
|
||
| func keepAliveDidFail() { | ||
| entry?.view.telemetryRecorder.recordError( | ||
| .init( | ||
| category: .navigation, | ||
| stage: .load, | ||
| code: .connectionLost, | ||
| retryable: false, | ||
| isRetry: false | ||
| ) | ||
| ) | ||
| evict(with: .failed( | ||
| reason: .webContentUnavailable, | ||
| message: "Preload keep-alive failed." | ||
|
|
@@ -291,10 +301,14 @@ class CheckoutWebView: WKWebView { | |
| private static let purposeHeader = "Shopify-Purpose" | ||
| private static let prefetchPurpose = "prefetch" | ||
|
|
||
| private let navigationClock: () -> TimeInterval = { ProcessInfo.processInfo.systemUptime } | ||
| private var navigationStartedAt: TimeInterval? | ||
| private var didRecordInitialNavigationDuration = false | ||
|
|
||
| private(set) var checkoutNavigation: WKNavigation? | ||
| private var didRetryCheckoutNavigation = false | ||
| private var navigationRetryReason: TelemetryNavigationRetryReason? | ||
| private var didCancelNavigationForHTTPError = false | ||
| private var checkoutRequest: URLRequest? | ||
|
|
||
| var checkoutBridge: CheckoutBridgeProtocol.Type = CheckoutBridge.self | ||
|
|
@@ -331,9 +345,15 @@ class CheckoutWebView: WKWebView { | |
| /// in-app browser surface, and routes non-web URLs through `externalURLHandler` | ||
| /// (consumers may still override via their own client). | ||
| lazy var defaultsClient: CheckoutProtocol.Client = .init() | ||
| .onDecodeError { [entryPoint] method, error, params in | ||
| OSLogger.shared.error("Failed to decode \(method) payload: \(error)") | ||
| OSLogger.shared.debug("Raw \(method) params: \(String(bytes: params, encoding: .utf8) ?? "")") | ||
| // Resolve the recorder per event; snapshotting it in the capture | ||
| // list would pin whichever client existed when this closure was | ||
| // first built, outliving telemetry disable/re-enable. | ||
| CheckoutTelemetry.recorder(for: entryPoint).recordProtocolDecodeError( | ||
| .init(method: .init(method: method), failureType: .params) | ||
| ) | ||
|
Comment on lines
+354
to
+356
Contributor
There was a problem hiding this comment. I'm not totally following why we have a telemetry instance for each "entrypoint" - @tiagocandido can you help me understand this? |
||
| } | ||
| .on(CheckoutProtocol.ready) { _ in | ||
| ReadyResult(checkout: nil, credential: nil, ucp: .success(), upgrade: nil, continueURL: nil, messages: nil) | ||
|
|
@@ -460,6 +480,9 @@ class CheckoutWebView: WKWebView { | |
| /// cart-url origin for incoming message validation. | ||
| var loadedCheckoutURL: URL? | ||
| private var entryPoint: MetaData.EntryPoint? | ||
| var telemetryRecorder: any CheckoutTelemetryRecording { | ||
| CheckoutTelemetry.recorder(for: entryPoint) | ||
| } | ||
|
|
||
| // MARK: Initializers | ||
|
|
||
|
|
@@ -560,6 +583,8 @@ class CheckoutWebView: WKWebView { | |
| checkoutRequest = request | ||
| didRetryCheckoutNavigation = false | ||
| hasHandledTerminalFailure = false | ||
| navigationRetryReason = nil | ||
| didCancelNavigationForHTTPError = false | ||
| checkoutNavigation = load(request) | ||
| } | ||
|
|
||
|
|
@@ -702,6 +727,11 @@ extension CheckoutWebView: WKScriptMessageHandler { | |
| /// unrecoverable error message selects the stable lifecycle code; no qualifying message maps to | ||
| /// `.unknown`. Malformed terminal payloads map to `.sdkError`. | ||
| private func handleTerminalProtocolError(_ body: String, malformedEnvelope: Bool = false) { | ||
| if malformedEnvelope { | ||
| telemetryRecorder.recordProtocolDecodeError( | ||
| .init(method: .init(method: "ec.error"), failureType: .envelope) | ||
| ) | ||
| } | ||
| Task { @MainActor in | ||
| let composedClient = ComposedCheckoutCommunicationClient( | ||
| merchant: client, | ||
|
|
@@ -715,15 +745,23 @@ extension CheckoutWebView: WKScriptMessageHandler { | |
|
|
||
| // `ec.error` denotes a terminal session error. Message severity selects the public | ||
| // lifecycle code, but does not keep the embedded session alive. | ||
| let failure: CheckoutError | ||
| if !malformedEnvelope, | ||
| let notification = try? JSONDecoder().decode( | ||
| TerminalErrorNotification.self, | ||
| from: Data(body.utf8) | ||
| ) | ||
| { | ||
| failure = CheckoutError.terminalProtocol(error: notification.params.error) | ||
| } else { | ||
| if !malformedEnvelope { | ||
| // Valid envelope with undecodable params; the envelope case | ||
| // was already recorded before this method was called. | ||
| telemetryRecorder.recordProtocolDecodeError( | ||
| .init(method: .init(method: "ec.error"), failureType: .params) | ||
| ) | ||
| } | ||
| failure = CheckoutError.sdk(message: "Embedded checkout sent an invalid terminal error.") | ||
| } | ||
|
|
||
| let wasBackgroundedPreload = isPreloadBackgrounded | ||
|
|
@@ -734,6 +772,16 @@ extension CheckoutWebView: WKScriptMessageHandler { | |
| hasHandledTerminalFailure = true | ||
| guard !wasBackgroundedPreload else { return } | ||
|
|
||
| telemetryRecorder.recordError( | ||
| .init( | ||
| category: .protocol, | ||
| stage: .message, | ||
| code: .unknown, | ||
| retryable: false, | ||
| isRetry: navigationRetryReason != nil | ||
| ) | ||
| ) | ||
| recordNavigationDuration(result: .failure) | ||
| viewDelegate?.checkoutViewDidFailWithError(error: failure) | ||
| } | ||
| } | ||
|
|
@@ -845,6 +893,18 @@ extension CheckoutWebView: WKNavigationDelegate { | |
| .httpError(statusCode: statusCode), | ||
| message: "HTTP response returned status code \(statusCode)." | ||
| ) | ||
| let isServerError = statusCode >= 500 | ||
| telemetryRecorder.recordError( | ||
| .init( | ||
| category: .http, | ||
| stage: .load, | ||
| code: isServerError ? .server : .client, | ||
| retryable: isServerError, | ||
| isRetry: navigationRetryReason != nil | ||
| ) | ||
| ) | ||
| recordNavigationDuration(result: .failure) | ||
| didCancelNavigationForHTTPError = true | ||
|
|
||
| OSLogger.shared.debug("Handling response for URL: \(LogSafeURL.string(response.url)), status code: \(statusCode)") | ||
|
|
||
|
|
@@ -861,17 +921,25 @@ extension CheckoutWebView: WKNavigationDelegate { | |
| func webView(_ webView: WKWebView, didStartProvisionalNavigation _: WKNavigation!) { | ||
| let url = LogSafeURL.string(webView.url) | ||
| OSLogger.shared.info("Started provisional navigation - url:\(url)") | ||
| if navigationStartedAt == nil, !didRecordInitialNavigationDuration { | ||
| navigationStartedAt = navigationClock() | ||
| } | ||
| didCancelNavigationForHTTPError = false | ||
| viewDelegate?.checkoutViewDidStartNavigation() | ||
| } | ||
|
|
||
| func webView(_ webView: WKWebView, didFailProvisionalNavigation navigation: WKNavigation!, withError error: Error) { | ||
| let nsError = error as NSError | ||
| let url = LogSafeURL.string(webView.url) | ||
|
|
||
| if didCancelNavigationForHTTPError { | ||
| didCancelNavigationForHTTPError = false | ||
| OSLogger.shared.debug("Ignoring provisional navigation cancelled by HTTP response policy - url:\(url)") | ||
| return | ||
| } | ||
|
|
||
| if isCancelledNavigationError(nsError) { | ||
| navigationStartedAt = nil | ||
| OSLogger.shared.debug("Ignoring cancelled provisional navigation - url:\(url)") | ||
| return | ||
| } | ||
|
|
@@ -887,14 +955,22 @@ extension CheckoutWebView: WKNavigationDelegate { | |
| } | ||
|
|
||
| didRetryCheckoutNavigation = true | ||
| let retryReason = CheckoutTelemetry.retryReason(for: nsError) | ||
|
Contributor
There was a problem hiding this comment. Is there a way we could bake this into the |
||
| OSLogger.shared.warn("Retrying checkout navigation - domain:\(nsError.domain) code:\(nsError.code) url:\(url)") | ||
|
|
||
| guard let retryNavigation = load(checkoutRequest) else { | ||
| telemetryRecorder.recordNavigationRetry( | ||
| .init(reason: retryReason, result: .notAttempted) | ||
| ) | ||
| OSLogger.shared.error("Checkout navigation retry failed to start - domain:\(nsError.domain) code:\(nsError.code) url:\(url)") | ||
| failNavigation(with: error) | ||
| return | ||
| } | ||
|
|
||
| telemetryRecorder.recordNavigationRetry( | ||
| .init(reason: retryReason, result: .started) | ||
| ) | ||
| navigationRetryReason = retryReason | ||
| checkoutNavigation = retryNavigation | ||
| } | ||
|
|
||
|
|
@@ -903,14 +979,13 @@ extension CheckoutWebView: WKNavigationDelegate { | |
|
|
||
| viewDelegate?.checkoutViewDidFinishNavigation() | ||
|
|
||
| if let startTime = navigationStartedAt { | ||
| let diff = milliseconds(from: startTime) / 1000 | ||
| let message = "Loaded checkout in \(String(format: "%.2f", diff))s" | ||
|
|
||
| ShopifyCheckoutKit.configuration.logger.log(message) | ||
| } | ||
| recordNavigationDuration(result: .success) | ||
|
|
||
| if navigation === checkoutNavigation { | ||
| resetProvisionalNavigationRetryState() | ||
|
|
@@ -920,16 +995,31 @@ extension CheckoutWebView: WKNavigationDelegate { | |
| func webViewWebContentProcessDidTerminate(_ webView: WKWebView) { | ||
| guard !hasHandledTerminalFailure else { return } | ||
| hasHandledTerminalFailure = true | ||
| // Capture before the reset below so a crash during a retried | ||
| // navigation still reports is_retry. | ||
| let wasRetry = navigationRetryReason != nil | ||
| resetProvisionalNavigationRetryState() | ||
|
Contributor
There was a problem hiding this comment. This will clear the Maybe we can add some tests around all the paths of isRetry - I think I see a few assertions that its false, but none on when its true
Contributor
Author
There was a problem hiding this comment. Yeah, good catch — the reset ran before the |
||
| let wasBackgroundedPreload = isPreloadBackgrounded | ||
| handleCachedViewFailure( | ||
| .webContentUnavailable, | ||
| message: "Web content process terminated." | ||
| ) | ||
|
|
||
| guard !wasBackgroundedPreload else { | ||
| navigationStartedAt = nil | ||
| return | ||
| } | ||
|
|
||
| telemetryRecorder.recordError( | ||
| .init( | ||
| category: .renderProcess, | ||
| stage: .presentation, | ||
| code: .unknown, | ||
| retryable: false, | ||
| isRetry: wasRetry | ||
| ) | ||
| ) | ||
| recordNavigationDuration(result: .failure) | ||
| OSLogger.shared.error("Web content process terminated - url:\(LogSafeURL.string(webView.url))") | ||
| viewDelegate?.checkoutViewDidFailWithError( | ||
| error: CheckoutError.webContentProcessTerminated( | ||
|
|
@@ -939,11 +1029,16 @@ extension CheckoutWebView: WKNavigationDelegate { | |
| } | ||
|
|
||
| func webView(_ webView: WKWebView, didFail _: WKNavigation!, withError error: Error) { | ||
| let nsError = error as NSError | ||
|
|
||
| if didCancelNavigationForHTTPError { | ||
| didCancelNavigationForHTTPError = false | ||
| OSLogger.shared.debug("Ignoring committed navigation cancelled by HTTP response policy") | ||
| return | ||
| } | ||
|
|
||
| if isCancelledNavigationError(nsError) { | ||
| navigationStartedAt = nil | ||
| OSLogger.shared.debug("Ignoring cancelled committed navigation - code:NSURLErrorCancelled") | ||
| return | ||
| } | ||
|
|
@@ -976,11 +1071,27 @@ extension CheckoutWebView: WKNavigationDelegate { | |
| checkoutRequest = nil | ||
| checkoutNavigation = nil | ||
| didRetryCheckoutNavigation = false | ||
| navigationRetryReason = nil | ||
| } | ||
|
|
||
| private func failNavigation(with error: Error) { | ||
| let nsError = error as NSError | ||
| if let navigationRetryReason { | ||
| telemetryRecorder.recordNavigationRetry( | ||
| .init(reason: navigationRetryReason, result: .failed) | ||
| ) | ||
| } | ||
| telemetryRecorder.recordError( | ||
| .init( | ||
| category: .navigation, | ||
| stage: .load, | ||
| code: CheckoutTelemetry.errorCode(for: nsError), | ||
| retryable: isRetryableProvisionalNavigationError(nsError), | ||
| isRetry: navigationRetryReason != nil | ||
| ) | ||
| ) | ||
| recordNavigationDuration(result: .failure) | ||
| resetProvisionalNavigationRetryState() | ||
| handleCachedViewFailure( | ||
| .navigationFailed, | ||
| message: "Navigation failed (error code: \(nsError.code))." | ||
|
|
@@ -991,6 +1102,23 @@ extension CheckoutWebView: WKNavigationDelegate { | |
| viewDelegate?.checkoutViewDidFailWithError(error: failure) | ||
| } | ||
|
|
||
| private func recordNavigationDuration(result: TelemetryNavigationDurationResult) { | ||
| guard let startTime = navigationStartedAt else { return } | ||
| navigationStartedAt = nil | ||
| didRecordInitialNavigationDuration = true | ||
| telemetryRecorder.recordNavigationDuration( | ||
| .init( | ||
| milliseconds: milliseconds(from: startTime), | ||
| result: result, | ||
| preloaded: isPreloadRequest | ||
| ) | ||
| ) | ||
| } | ||
|
|
||
| private func milliseconds(from startTime: TimeInterval) -> Double { | ||
| return (navigationClock() - startTime) * 1000 | ||
| } | ||
|
|
||
| private func isCheckout(url: URL?) -> Bool { | ||
| return self.url == url | ||
| } | ||
|
|
||
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.
Oops, something went wrong.
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Feels strange to me that the telemetry class is bound to the checkout view. What's the reason for that? Can't it be a global instance?
Also a small nit: I find the name
telemetryRecordera bit awkward. Can we make ittelemetryinstead?